[ 0.000000] Linux version 4.18.0rh8.10-debug (green@maintenance) (gcc version 8.5.0 20210514 (Red Hat 8.5.0-26) (GCC)) #2 SMP Mon Jul 14 01:24:22 EDT 2025 [ 0.000000] Command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers' [ 0.000000] x86/fpu: xstate_offset[2]: 576, xstate_sizes[2]: 256 [ 0.000000] x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'standard' format. [ 0.000000] signal: max sigframe size: 1776 [ 0.000000] BIOS-provided physical RAM map: [ 0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable [ 0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000000100000-0x00000000bffd9fff] usable [ 0.000000] BIOS-e820: [mem 0x00000000bffda000-0x00000000bfffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000100000000-0x0000000146dfffff] usable [ 0.000000] NX (Execute Disable) protection: active [ 0.000000] SMBIOS 2.8 present. [ 0.000000] DMI: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.17.0-10.fc44 06/10/2025 [ 0.000000] Hypervisor detected: KVM [ 0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00 [ 0.000000] kvm-clock: using sched offset of 464765136 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2399.998 MHz processor [ 0.000000] last_pfn = 0x146e00 max_arch_pfn = 0x400000000 [ 0.000000] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT [ 0.000000] last_pfn = 0xbffda max_arch_pfn = 0x400000000 [ 0.000000] found SMP MP-table at [mem 0x000f54d0-0x000f54df] [ 0.000000] RAMDISK: [mem 0xbcc64000-0xbffcffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F52F0 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE2464 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE2300 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 0022C0 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE2374 000090 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE2404 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE243C 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe2300-0xbffe2373] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe22ff] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe2374-0xbffe2403] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe2404-0xbffe243b] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe243c-0xbffe2463] [ 0.000000] No NUMA configuration found [ 0.000000] Faking a node at [mem 0x0000000000000000-0x0000000146dfffff] [ 0.000000] NODE_DATA(0) allocated [mem 0x1465a3000-0x1465cdfff] [ 0.000000] Reserving 256MB of memory at 2752MB for crashkernel (System RAM: 4205MB) [ 0.000000] Zone ranges: [ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.000000] DMA32 [mem 0x0000000001000000-0x00000000ffffffff] [ 0.000000] Normal [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Device empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff] [ 0.000000] node 0: [mem 0x0000000000100000-0x00000000bffd9fff] [ 0.000000] node 0: [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Zeroed struct page in unavailable ranges: 4744 pages [ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x0000000146dfffff] [ 0.000000] ACPI: PM-Timer IO Port: 0x608 [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) [ 0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) [ 0.000000] Using ACPI (MADT) for SMP configuration information [ 0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000] TSC deadline timer available [ 0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs [ 0.000000] kvm-guest: KVM setup pv remote TLB flush [ 0.000000] kvm-guest: setup PV sched yield [ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff] [ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff] [ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff] [ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff] [ 0.000000] PM: Registered nosave memory: [mem 0xbffda000-0xbfffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xc0000000-0xfeffbfff] [ 0.000000] PM: Registered nosave memory: [mem 0xfeffc000-0xfeffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xff000000-0xfffbffff] [ 0.000000] PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff] [ 0.000000] [mem 0xc0000000-0xfeffbfff] available for PCI devices [ 0.000000] Booting paravirtualized kernel on KVM [ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns [ 0.000000] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1 [ 0.000000] percpu: Embedded 63 pages/cpu s221184 r8192 d28672 u524288 [ 0.000000] kvm-guest: PV spinlocks enabled [ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1059618 [ 0.000000] Policy zone: Normal [ 0.000000] Kernel command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] Specific versions of hardware are certified with Red Hat Enterprise Linux 8. Please see the list of hardware certified with Red Hat Enterprise Linux 8 at https://catalog.redhat.com. [ 0.000000] audit: disabled (until reboot) [ 0.000000] software IO TLB: area num 4. [ 0.000000] Memory: 2829700K/4306400K available (18435K kernel code, 11221K rwdata, 7248K rodata, 2908K init, 18040K bss, 524580K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] ftrace: allocating 41240 entries in 162 pages [ 0.000000] ftrace: allocated 162 pages with 3 groups [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] rcu: RCU event tracing is enabled. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ 0.000000] rcu: RCU callback double-/use-after-free debug enabled. [ 0.000000] Rude variant of Tasks RCU enabled. [ 0.000000] Tracing variant of Tasks RCU enabled. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 0.000000] NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16 [ 0.000000] random: get_random_bytes called from start_kernel+0x622/0x9a8 with crng_init=0 [ 0.001000] Console: colour *CGA 80x25 [ 0.001000] printk: console [ttyS1] enabled [ 0.001000] ACPI: Core revision 20220331 [ 0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.001013] APIC: Switch to symmetric I/O mode setup [ 0.003202] x2apic enabled [ 0.004007] Switched APIC routing to physical x2apic. [ 0.005013] kvm-guest: setup PV IPIs [ 0.008000] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.008000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.008021] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.009012] pid_max: default: 32768 minimum: 301 [ 0.010137] LSM: Security Framework initializing [ 0.011053] Yama: becoming mindful. [ 0.012034] SELinux: Initializing. [ 0.013074] *** VALIDATE selinux *** [ 0.021406] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.026569] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.027139] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.028105] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.029112] *** VALIDATE tmpfs *** [ 0.030456] *** VALIDATE proc *** [ 0.031292] *** VALIDATE cgroup *** [ 0.032012] *** VALIDATE cgroup2 *** [ 0.033319] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.035117] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.037005] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.038030] Spectre V2 : User space: Vulnerable [ 0.039009] Speculative Store Bypass: Vulnerable [ 0.041893] debug: unmapping init [mem 0xffffffffb6259000-0xffffffffb6260fff] [ 0.043157] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.044678] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.045019] ... version: 2 [ 0.046010] ... bit width: 48 [ 0.047012] ... generic registers: 4 [ 0.048013] ... value mask: 0000ffffffffffff [ 0.049014] ... max period: 00007fffffffffff [ 0.050013] ... fixed-purpose events: 3 [ 0.051013] ... event mask: 000000070000000f [ 0.052314] rcu: Hierarchical SRCU implementation. [ 0.054462] smp: Bringing up secondary CPUs ... [ 0.055604] x86: Booting SMP configuration: [ 0.056028] .... node #0, CPUs: #1 #2 #3 [ 0.059445] smp: Brought up 1 node, 4 CPUs [ 0.061011] smpboot: Max logical packages: 1 [ 0.062017] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.155090] node 0 deferred pages initialised in 91ms [ 0.158139] devtmpfs: initialized [ 0.159164] x86/mm: Memory block size: 128MB [ 0.161430] gcov: version magic: 0x41383552 [ 0.162598] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.163099] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.164239] pinctrl core: initialized pinctrl subsystem [ 0.165190] [ 0.165712] ************************************************************* [ 0.166014] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.167013] ** ** [ 0.168014] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.169018] ** ** [ 0.170011] ** This means that this kernel is built to expose internal ** [ 0.171011] ** IOMMU data structures, which may compromise security on ** [ 0.172016] ** your system. ** [ 0.173014] ** ** [ 0.174012] ** If you see this message and you are not debugging the ** [ 0.175014] ** kernel, report this immediately to your vendor! ** [ 0.176014] ** ** [ 0.177013] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.178015] ************************************************************* [ 0.179683] NET: Registered protocol family 16 [ 0.180457] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.181056] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.182057] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.183466] cpuidle: using governor menu [ 0.184000] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.187433] PCI: Using configuration type 1 for base access [ 0.189127] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.200059] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.201026] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.203087] cryptd: max_cpu_qlen set to 1000 [ 0.205335] ACPI: Added _OSI(Module Device) [ 0.206014] ACPI: Added _OSI(Processor Device) [ 0.207014] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.208014] ACPI: Added _OSI(Processor Aggregator Device) [ 0.212176] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.214418] ACPI: Interpreter enabled [ 0.215057] ACPI: PM: (supports S0 S3 S4 S5) [ 0.216011] ACPI: Using IOAPIC for interrupt routing [ 0.217111] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.218376] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.239980] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.244078] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.247052] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.253099] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.258885] acpiphp: Slot [2] registered [ 0.261250] acpiphp: Slot [5] registered [ 0.263239] acpiphp: Slot [6] registered [ 0.265293] acpiphp: Slot [3] registered [ 0.267206] acpiphp: Slot [4] registered [ 0.268136] acpiphp: Slot [7] registered [ 0.270114] acpiphp: Slot [8] registered [ 0.272153] acpiphp: Slot [9] registered [ 0.273143] acpiphp: Slot [10] registered [ 0.275146] acpiphp: Slot [11] registered [ 0.277253] acpiphp: Slot [12] registered [ 0.279113] acpiphp: Slot [13] registered [ 0.280114] acpiphp: Slot [14] registered [ 0.282091] acpiphp: Slot [15] registered [ 0.283000] acpiphp: Slot [16] registered [ 0.283000] acpiphp: Slot [17] registered [ 0.285121] acpiphp: Slot [18] registered [ 0.286084] acpiphp: Slot [19] registered [ 0.288108] acpiphp: Slot [20] registered [ 0.289091] acpiphp: Slot [21] registered [ 0.289958] acpiphp: Slot [22] registered [ 0.291334] acpiphp: Slot [23] registered [ 0.293072] acpiphp: Slot [24] registered [ 0.293916] acpiphp: Slot [25] registered [ 0.294053] acpiphp: Slot [26] registered [ 0.295032] acpiphp: Slot [27] registered [ 0.296069] acpiphp: Slot [28] registered [ 0.297106] acpiphp: Slot [29] registered [ 0.297925] acpiphp: Slot [30] registered [ 0.299102] acpiphp: Slot [31] registered [ 0.301078] PCI host bridge to bus 0000:00 [ 0.302022] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.304024] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.306017] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.307013] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.308014] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.310016] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.311124] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.312740] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.314838] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.319416] pci 0000:00:01.1: reg 0x20: [io 0xc120-0xc12f] [ 0.322507] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.324016] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.326014] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.328016] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.329402] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.330516] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.332027] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.334582] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.337013] pci 0000:00:02.0: reg 0x10: [io 0xc100-0xc11f] [ 0.343016] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.347013] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.352032] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.358018] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.367017] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.387025] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.398287] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.405018] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.411017] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.428015] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.441124] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.444441] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.447501] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.451384] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.455258] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.460101] iommu: Default domain type: Passthrough [ 0.462650] SCSI subsystem initialized [ 0.464151] ACPI: bus type USB registered [ 0.465170] usbcore: registered new interface driver usbfs [ 0.466056] usbcore: registered new interface driver hub [ 0.467064] usbcore: registered new device driver usb [ 0.469306] pps_core: LinuxPPS API ver. 1 registered [ 0.471012] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.474079] PTP clock support registered [ 0.476090] EDAC MC: Ver: 3.0.0 [ 0.478146] PCI: Using ACPI for IRQ routing [ 0.480735] NetLabel: Initializing [ 0.482014] NetLabel: domain hash size = 128 [ 0.485014] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.487091] NetLabel: unlabeled traffic allowed by default [ 0.490156] vgaarb: loaded [ 0.492315] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.494018] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.502168] clocksource: Switched to clocksource kvm-clock [ 0.614233] VFS: Disk quotas dquot_6.6.0 [ 0.615458] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.617472] *** VALIDATE ramfs *** [ 0.618503] *** VALIDATE hugetlbfs *** [ 0.620041] pnp: PnP ACPI init [ 0.622435] pnp: PnP ACPI: found 6 devices [ 0.642636] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.645471] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.647014] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.648967] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.650900] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.652341] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.654115] NET: Registered protocol family 2 [ 0.657275] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.663894] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.666759] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.671423] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.674620] TCP: Hash tables configured (established 65536 bind 65536) [ 0.677288] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.680425] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.683178] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.685817] NET: Registered protocol family 1 [ 0.688223] RPC: Registered named UNIX socket transport module. [ 0.690037] RPC: Registered udp transport module. [ 0.691632] RPC: Registered tcp transport module. [ 0.693688] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.696375] NET: Registered protocol family 44 [ 0.698200] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.700681] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.701954] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.703524] PCI: CLS 0 bytes, default 64 [ 0.704820] Unpacking initramfs... [ 2.156637] debug: unmapping init [mem 0xffff9efafcc64000-0xffff9efafffcffff] [ 2.163328] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.165596] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.169566] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 2.666801] Initialise system trusted keyrings [ 2.668729] Key type blacklist registered [ 2.670754] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.680069] zbud: loaded [ 2.682844] *** VALIDATE nfs *** [ 2.684228] *** VALIDATE nfs4 *** [ 2.685884] pstore: using deflate compression [ 2.689356] Platform Keyring initialized [ 2.781853] NET: Registered protocol family 38 [ 2.784490] Key type asymmetric registered [ 2.786262] Asymmetric key parser 'x509' registered [ 2.788505] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 2.791949] io scheduler mq-deadline registered [ 2.793774] io scheduler kyber registered [ 2.795902] io scheduler bfq registered [ 2.797980] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 2.801382] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 2.804226] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 2.806385] ACPI: Power Button [PWRF] [ 2.811080] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 2.815772] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 2.826224] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 2.851497] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 2.877186] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 2.881802] Non-volatile memory driver v1.3 [ 2.883104] Linux agpgart interface v0.103 [ 2.915034] virtio_blk virtio1: [vda] 146640 512-byte logical blocks (75.1 MB/71.6 MiB) [ 2.918146] vda: detected capacity change from 0 to 75079680 [ 2.932613] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 2.935708] vdb: detected capacity change from 0 to 1073741824 [ 2.942249] libphy: Fixed MDIO Bus: probed [ 2.964170] usbcore: registered new interface driver usbserial_generic [ 2.966946] usbserial: USB Serial support registered for generic [ 2.970771] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 2.975141] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 2.976800] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 2.978928] mousedev: PS/2 mouse device common for all mice [ 2.981928] rtc_cmos 00:05: RTC can wake from S4 [ 2.984376] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 2.989098] rtc_cmos 00:05: registered as rtc0 [ 2.990397] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 2.992869] intel_pstate: CPU model not supported [ 2.995980] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 2.998412] hid: raw HID events driver (C) Jiri Kosina [ 3.001933] usbcore: registered new interface driver usbhid [ 3.003361] usbhid: USB HID core driver [ 3.004585] drop_monitor: Initializing network drop monitor service [ 3.006972] Initializing XFRM netlink socket [ 3.007047] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.009238] NET: Registered protocol family 10 [ 3.015136] Segment Routing with IPv6 [ 3.016584] NET: Registered protocol family 17 [ 3.018751] mpls_gso: MPLS GSO support [ 3.025072] RAS: Correctable Errors collector initialized. [ 3.027181] AVX version of gcm_enc/dec engaged. [ 3.028720] AES CTR mode by8 optimization enabled [ 3.108399] sched_clock: Marking stable (3108352621, 0)->(4061906157, -953553536) [ 3.111926] registered taskstats version 1 [ 3.114179] Loading compiled-in X.509 certificates [ 3.116532] zswap: loaded using pool lzo/zbud [ 3.142909] Key type big_key registered [ 3.156866] Key type encrypted registered [ 3.158580] ima: No TPM chip found, activating TPM-bypass! [ 3.160676] ima: Allocated hash algorithm: sha1 [ 3.162265] ima: No architecture policies found [ 3.164019] evm: Initialising EVM extended attributes: [ 3.165796] evm: security.selinux [ 3.167121] evm: security.ima [ 3.168196] evm: security.capability [ 3.169608] evm: HMAC attrs: 0x1 [ 3.171965] rtc_cmos 00:05: setting system clock to 2026-09-02 06:15:22 UTC (1788329722) [ 3.178411] debug: unmapping init [mem 0xffffffffb7203000-0xffffffffb73fffff] [ 3.181492] debug: unmapping init [mem 0xffffffffb5f82000-0xffffffffb6258fff] [ 3.190103] Write protecting the kernel read-only data: 28672k [ 3.194144] debug: unmapping init [mem 0xffffffffb4603000-0xffffffffb47fffff] [ 3.197475] debug: unmapping init [mem 0xffffffffb4f14000-0xffffffffb4ffffff] [ 3.232260] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 3.241140] systemd[1]: Detected virtualization kvm. [ 3.242568] systemd[1]: Detected architecture x86-64. [ 3.244078] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.267395] systemd[1]: No hostname configured. [ 3.269034] systemd[1]: Set hostname to . [ 3.270994] random: systemd: uninitialized urandom read (16 bytes read) [ 3.273451] systemd[1]: Initializing machine ID from random generator. [ 3.328324] random: ln: uninitialized urandom read (6 bytes read) [ 3.416613] random: systemd: uninitialized urandom read (16 bytes read) [ 3.418554] systemd[1]: Started Dispatch Password Requests to Console Directory Watch. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ 3.425520] systemd[1]: Listening on udev Kernel Socket. [ OK ] Listening on udev Kernel Socket. [ 3.431086] systemd[1]: Listening on Journal Socket (/dev/log). [ OK ] Listening on Journal Socket (/dev/log). [ OK ] Listening on udev Control Socket. [ OK ] Listening on Journal Socket. Starting Journal Service... Starting Create list of required st…ce nodes for the current kernel... [ OK ] Reached target Timers. [ OK ] Reached target Slices. Starting Setup Virtual Console... [ OK ] Reached target Local File Systems. Starting Create Volatile Files and Directories... [ OK ] Reached target Swap. [ OK ] Reached target Paths. [ OK ] Reached target Initrd Root Device. Starting Apply Kernel Variables... [ OK ] Started Memstrack Anylazing Service. [ OK ] Reached target Sockets. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Setup Virtual Console. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Apply Kernel Variables. Starting dracut cmdline hook... Starting Create Static Device Nodes in /dev... [ OK ] Started Journal Service. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 4.084317] device-mapper: uevent: version 1.0.3 [ 4.086526] device-mapper: ioctl: 4.46.0-ioctl (2022-02-22) initialised: dm-devel@redhat.com [ OK ] Started dracut pre-udev hook. Starting udev Kernel Device Manager... [ OK ] Started udev Kernel Device Manager. Starting dracut pre-trigger hook... [ OK ] Started dracut pre-trigger hook. Starting udev Coldplug all Devices... Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. Starting dracut initqueue hook... [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ 4.793571] virtio_net virtio0 ens2: renamed from eth0 [ 4.811655] random: fast init done [ 4.842924] scsi host0: ata_piix [ 4.904178] scsi host1: ata_piix [ 4.908902] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc120 irq 14 [ 4.911365] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc128 irq 15 [ 8.660475] dracut-initqueue[582]: RTNETLINK answers: File exists [ 9.675458] random: crng init done [ 9.676386] random: 7 urandom warning(s) missed due to ratelimiting Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Mounting /sysroot... [ 10.137816] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped target Timers. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target System Initialization. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped target Swap. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. Stopping udev Kernel Device Manager... [ OK ] Stopped target Paths. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped target Slices. [ OK ] Stopped target Sockets. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Closed udev Control Socket. [ OK ] Closed udev Kernel Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 11.318973] printk: systemd: 24 output lines suppressed due to ratelimiting [ 11.782769] SELinux: Disabled at runtime. [ 11.906081] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 11.925457] systemd[1]: Detected virtualization kvm. [ 11.931744] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 13.857916] systemd[1]: initrd-switch-root.service: Succeeded. [ 13.871358] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 13.897783] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 13.912963] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 13.932379] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 14.001399] systemd[1]: Starting Journal Service... Starting Journal Service... [ 14.030908] systemd[1]: Starting Create list of required static device nodes for the current kernel... Starting Create list of required st…ce nodes for the current kernel... [ OK ] Created slice system-serial\x2dgetty.slice. Mounting Kernel Debug File System... [ OK ] Listening on Process Core Dump Socket. [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Listening on RPCbind Server Activation Socket. [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Created slice User and Session Slice. [ OK ] Created slice system-getty.slice. [ OK ] Listening on udev Kernel Socket. [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd Root File System. [ OK ] Stopped target Initrd File Systems. Activating swap /dev/disk/by-label/SWAP... [ OK ] Reached target Slices. Starting Remount Root and Kernel File Systems... Mounting Huge Pages File System... [ 14.416995] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS Starting Apply Kernel Variables... Mounting POSIX Message Queue File System... [ OK ] Listening on udev Control Socket. Starting udev Coldplug all Devices... [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Reached target RPC Port Mapper. [ OK ] Reached target rpc_pipefs.target. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Journal Service. [ OK ] Mounted Kernel Debug File System. [ OK ] Activated swap /dev/disk/by-label/SWAP. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Mounted Huge Pages File System. [ OK ] Started Apply Kernel Variables. [ OK ] Mounted POSIX Message Queue File System. Starting Configure read-only root support... [ OK ] Reached target Swap. Starting Flush Journal to Persistent Storage... Starting Create Static Device Nodes in /dev... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Reached target Local File Systems (Pre). Mounting /mnt... Mounting /home/green/git/lustre-release... Starting udev Kernel Device Manager... [ OK ] Started udev Coldplug all Devices. [ OK ] Mounted /mnt. [ 15.765715] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 17.057844] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 17.190800] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 17.565108] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 17.722372] EDAC sbridge: Ver: 1.1.2 [ 21.195514] Key type dns_resolver registered [* ] A start job is running for Configur…-only root support (8s / no limit)[ 22.030382] NFS: Registering the id_resolver key type [ 22.033443] Key type id_resolver registered [ 22.035411] Key type id_legacy registered [** ] A start job is running for Configur…-only root support (8s / no limit) [ OK ] Started Configure read-only root support. [ OK ] Reached target Local File Systems. Starting Rebuild Dynamic Linker Cache... Starting Mark the need to relabel after reboot... Starting Load/Save Random Seed... Starting Create Volatile Files and Directories... [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Load/Save Random Seed. [ OK ] Started Create Volatile Files and Directories. Starting Update UTMP about System Boot/Shutdown... Starting RPC Bind... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Started D-Bus System Message Bus. Starting Network Manager... Starting Login Service... Starting Restore /run/initramfs on shutdown... [ OK ] Started irqbalance daemon. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Started dnf makecache --timer. [ OK ] Reached target Timers. [ OK ] Reached target sshd-keygen.target. [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Network Manager. Starting Network Manager Wait Online... [ OK ] Reached target Network. Starting GSSAPI Proxy Daemon... Starting Dynamic System Tuning Daemon... Starting OpenSSH server daemon... Starting Hostname Service... [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Started Login Service. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... [ OK ] Started OpenSSH server daemon. [ OK ] Started Permit User Sessions. [ OK ] Started Getty on tty1. [ OK ] Started Serial Getty on ttyS1. [ OK ] Started Serial Getty on ttyS0. [ OK ] Reached target Login Prompts. [ OK ] Started Command Scheduler. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting System Logging Service... Starting Crash recovery kernel arming... Starting Notify NFS peers of a restart... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg151-client login: [ 87.814370] libcfs: loading out-of-tree module taints kernel. [ 87.969374] Key type ._llcrypt registered [ 87.971036] Key type .llcrypt registered [ 88.519293] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [ 88.533358] alg: No test for adler32 (adler32-zlib) [ 90.131385] Lustre: Lustre: Build Version: 2.17.57_104_g6cc0f2c [ 91.209756] LNet: Added LNI 192.168.201.51@tcp [8/256/0/180] [ 92.959188] Key type lgssc registered [ 94.779541] Lustre: Echo OBD driver; http://www.lustre.org/ [ 262.452692] Lustre: Mounted lustre-client - version 2.17.57_104_g6cc0f2c [ 267.462256] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 280.079277] Lustre: DEBUG MARKER: oleg151-client.virtnet: executing check_logdir /tmp/testlogs/ [ 285.373594] Lustre: DEBUG MARKER: oleg151-client.virtnet: executing yml_node [ 288.223971] Lustre: lustre-OST0000-osc-ffff9efb51572000: disconnect after 23s idle [ 290.733166] Lustre: DEBUG MARKER: Client: 2.17.57.104 [ 293.486514] Lustre: DEBUG MARKER: MDS: 2.17.57.104 [ 295.950216] Lustre: DEBUG MARKER: OSS: 2.17.57.104 [ 297.565046] Lustre: DEBUG MARKER: -----============= acceptance-small: sanityn ============----- Wed Sep 2 02:20:15 EDT 2026 [ 314.643360] Lustre: DEBUG MARKER: excepting tests: 27 40a [ 316.170880] Lustre: DEBUG MARKER: skipping tests SLOW=no: 33a [ 317.801135] Lustre: DEBUG MARKER: === sanityn: start setup 02:20:35 (1788330035) === [ 318.747308] Lustre: Mounted lustre-client - version 2.17.57_104_g6cc0f2c [ 324.129154] Lustre: DEBUG MARKER: oleg151-client.virtnet: executing check_config_client /mnt/lustre [ 338.198267] hrtimer: interrupt took 5248485 ns [ 343.866934] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 357.448338] Lustre: DEBUG MARKER: === sanityn: finish setup 02:21:15 (1788330075) === [ 359.793035] Lustre: DEBUG MARKER: == sanityn test 0: do_node_vp() and do_facet_vp() do the right thing ========================================================== 02:21:17 (1788330077) [ 367.785465] Lustre: DEBUG MARKER: == sanityn test 1: Check attribute updates on 2 mount points ========================================================== 02:21:25 (1788330085) [ 375.477702] Lustre: DEBUG MARKER: == sanityn test 2a: check cached attribute updates on 2 mtpt's ================================================================== 02:21:32 (1788330092) [ 382.836482] Lustre: DEBUG MARKER: == sanityn test 2b: check cached attribute updates on 2 mtpt's ================================================================== 02:21:40 (1788330100) [ 389.486714] Lustre: DEBUG MARKER: == sanityn test 2c: check cached attribute updates on 2 mtpt's root ============================================================= 02:21:47 (1788330107) [ 395.959925] Lustre: DEBUG MARKER: == sanityn test 2d: check cached attribute updates on 2 mtpt's root ============================================================= 02:21:54 (1788330114) [ 402.103724] Lustre: DEBUG MARKER: == sanityn test 2e: check chmod on root is propagated to others ========================================================== 02:22:00 (1788330120) [ 408.241706] Lustre: DEBUG MARKER: == sanityn test 2f: check attr/owner updates on DNE with 2 mtpt's ========================================================== 02:22:06 (1788330126) [ 415.659357] Lustre: DEBUG MARKER: == sanityn test 2g: check blocks update on sync write ==== 02:22:13 (1788330133) [ 423.082763] Lustre: DEBUG MARKER: == sanityn test 3: symlink on one mtpt, readlink on another ===================================================================== 02:22:20 (1788330140) [ 429.185663] Lustre: DEBUG MARKER: == sanityn test 4: fstat validation on multiple mount points ==================================================================== 02:22:27 (1788330147) [ 436.704572] Lustre: lustre-OST0000-osc-ffff9efb51572000: disconnect after 21s idle [ 436.709922] Lustre: Skipped 1 previous similar message [ 438.069464] Lustre: DEBUG MARKER: == sanityn test 5: create a file on one mount, truncate it on the other ========================================================== 02:22:35 (1788330155) [ 444.384722] Lustre: DEBUG MARKER: == sanityn test 6: remove of open file on other node ============================================================================ 02:22:42 (1788330162) [ 451.656464] Lustre: DEBUG MARKER: == sanityn test 7: remove of open directory on other node ======================================================================= 02:22:49 (1788330169) [ 452.064728] Lustre: lustre-OST0001-osc-ffff9efb45ee9800: disconnect after 22s idle [ 458.752605] Lustre: DEBUG MARKER: == sanityn test 8: remove of open special file on other node ==================================================================== 02:22:56 (1788330176) [ 466.727230] Lustre: DEBUG MARKER: == sanityn test 9a: append of file with sub-page size on multiple mounts ========================================================== 02:23:04 (1788330184) [ 472.543213] Lustre: lustre-OST0000-osc-ffff9efb51572000: disconnect after 21s idle [ 473.593681] Lustre: DEBUG MARKER: == sanityn test 9b: append to striped sparse file ======== 02:23:11 (1788330191) [ 480.832277] Lustre: DEBUG MARKER: == sanityn test 10a: write of file with sub-page size on multiple mounts ========================================================== 02:23:18 (1788330198) [ 488.998097] Lustre: DEBUG MARKER: == sanityn test 10b: write of file with sub-page size on multiple mounts ========================================================== 02:23:26 (1788330206) [ 495.051717] Lustre: DEBUG MARKER: == sanityn test 11: execution of file opened for write should return error ============================================================== 02:23:33 (1788330213) [ 502.346070] Lustre: DEBUG MARKER: == sanityn test 12: test lock ordering (link, stat, unlink) ========================================================== 02:23:40 (1788330220) [ 503.113396] Lustre: DEBUG MARKER: start dir: /mnt/lustre/lockdir=144115205289279517 file: /mnt/lustre/lockdir/lockfile=144115205289279516 [ 637.169862] Lustre: DEBUG MARKER: == sanityn test 13: test directory page revocation ======= 02:25:55 (1788330355) [ 643.455355] Lustre: DEBUG MARKER: == sanityn test 14aa: execution of file open for write returns -ETXTBSY ========================================================== 02:26:01 (1788330361) [ 649.978604] Lustre: DEBUG MARKER: == sanityn test 14ab: open(RDWR) of executing file returns -ETXTBSY ========================================================== 02:26:07 (1788330367) [ 657.293588] Lustre: DEBUG MARKER: == sanityn test 14b: truncate of executing file returns -ETXTBSY ================================================================ 02:26:15 (1788330375) [ 664.723313] Lustre: DEBUG MARKER: == sanityn test 14c: open(O_TRUNC) of executing file return -ETXTBSY ============================================================ 02:26:22 (1788330382) [ 672.603859] Lustre: DEBUG MARKER: == sanityn test 14d: chmod of executing file is still possible ================================================================== 02:26:30 (1788330390) [ 674.925631] Lustre: DEBUG MARKER: chmod [ 681.949452] Lustre: DEBUG MARKER: == sanityn test 15: test out-of-space with multiple writers ===================================================================== 02:26:39 (1788330399) [ 1601.714889] Lustre: DEBUG MARKER: == sanityn test 16a: 2500 iterations of dual-mount fsx === 02:41:59 (1788331319) [ 1737.183646] Lustre: lustre-OST0001-osc-ffff9efb45ee9800: disconnect after 24s idle [ 1821.614696] Lustre: DEBUG MARKER: == sanityn test 16b: 2500 iterations of dual-mount fsx at small size ========================================================== 02:45:39 (1788331539) [ 1932.351939] Lustre: DEBUG MARKER: == sanityn test 16c: verify data consistency on ldiskfs with cache disabled (b=17397) ========================================================== 02:47:30 (1788331650) [ 2076.976702] Lustre: DEBUG MARKER: == sanityn test 16d: Verify DIO and buffer IO with two clients ========================================================== 02:49:54 (1788331794) [ 2120.202774] Lustre: DEBUG MARKER: == sanityn test 16e: Verify size consistency for O_DIRECT write ========================================================== 02:50:38 (1788331838) [ 2121.183415] Lustre: lustre-OST0000-osc-ffff9efb45ee9800: disconnect after 22s idle [ 2127.245544] Lustre: DEBUG MARKER: == sanityn test 16f: rw sequential consistency vs drop_caches ========================================================== 02:50:45 (1788331845) [ 2128.373464] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2128.440524] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2128.520547] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2128.636352] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2128.722613] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2128.820268] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2128.931497] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2129.002075] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2129.087162] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2129.155095] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2129.192869] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2129.232522] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2129.294928] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2129.354599] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2129.399625] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2129.438454] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2129.472334] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2129.515852] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2129.566406] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2129.641867] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2129.724699] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2129.765604] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2129.813773] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2129.853502] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2129.900152] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2129.942044] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2129.978795] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2130.023289] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2130.076227] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2130.155635] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2130.196678] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2130.228414] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2130.268921] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2130.309029] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2130.372073] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2130.435912] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2130.523918] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2130.586435] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2130.648226] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2130.733405] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2130.791205] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2130.862256] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2130.939393] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2131.013708] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2131.086071] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2131.163613] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2131.260645] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2131.329682] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2131.407957] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2131.475030] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2131.538454] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2131.598576] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2131.660569] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2131.758185] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2131.836653] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2131.876166] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2131.910142] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2131.960706] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2131.996459] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2132.028933] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2132.061927] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2132.101653] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2132.134270] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2132.180482] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2132.233570] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2132.299820] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2132.393220] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2132.450669] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2132.489899] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2132.537368] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2132.602740] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2132.700180] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2132.775375] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2132.831284] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2132.890771] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2132.953885] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2133.033214] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2133.105289] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2133.187049] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2133.319631] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2133.512756] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2133.651661] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2133.776415] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2133.854166] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2133.951307] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2134.044432] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2134.123593] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2134.190769] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2134.271829] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2134.335434] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2134.407193] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2134.536597] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2134.653784] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2134.760108] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2134.839039] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2134.939222] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2135.040580] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2135.113400] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2135.191865] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2135.290676] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2135.394047] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2135.498719] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2135.580240] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2135.658914] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2135.715371] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2135.798840] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2135.952387] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2136.055201] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2136.102329] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2136.142252] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2136.234021] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2136.336425] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2136.449921] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2136.553814] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2136.646258] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2136.688074] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2136.747804] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2136.798101] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2136.866455] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2136.917961] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2136.966267] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2137.042900] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2137.095065] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2137.125397] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2137.157898] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2137.256476] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2137.387479] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2137.442590] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2137.478821] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2137.529588] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2137.575898] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2137.712484] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2137.787094] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2137.835481] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2137.909581] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2138.005435] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2138.095354] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2138.170525] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2138.309488] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2138.367641] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2138.440927] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2138.513376] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2138.587699] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2138.662680] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2138.738669] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2138.813811] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2138.887565] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2138.973844] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2139.040599] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2139.133763] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2139.232717] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2139.305343] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2139.369680] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2139.428330] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2139.485827] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2139.542645] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2139.612399] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2139.674839] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2139.732357] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2139.796274] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2139.853362] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2139.966540] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2140.062457] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2140.161784] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2140.293586] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2140.361560] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2140.440259] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2140.580846] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2140.660143] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2140.737578] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2140.875352] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2140.966701] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2141.058895] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2141.135697] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2141.235205] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2141.342661] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2141.419599] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2141.514833] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2141.596232] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2141.667667] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2141.671128] Lustre: lustre-OST0001-osc-ffff9efb45ee9800: disconnect after 20s idle [ 2141.744224] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2141.803744] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2141.862490] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2141.919782] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2141.999236] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2142.063915] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2142.124466] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2142.198516] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2142.261520] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2142.327374] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2142.397518] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2142.474812] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2142.536856] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2142.604238] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2142.671593] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2142.747133] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2142.893058] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2143.047567] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2143.192078] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2143.308457] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2143.371861] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2143.440140] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2143.506737] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2143.576718] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2143.620677] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2143.671446] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2143.735800] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2143.818766] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2143.885162] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2143.944657] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2144.023686] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2144.115848] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2144.193665] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2144.351663] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2144.477786] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2144.579763] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2144.663163] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2144.751331] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2144.819204] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2144.899069] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2144.967807] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2145.043588] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2145.141661] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2145.251698] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2145.414673] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2145.538349] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2145.736088] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2145.865590] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2146.053522] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2146.252336] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2146.385853] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2146.520580] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2146.616761] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2146.717315] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2146.783829] Lustre: lustre-OST0001-osc-ffff9efb51572000: disconnect after 23s idle [ 2146.794835] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2146.931068] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2147.077540] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2147.161505] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2147.290110] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2147.384467] rw_seq_cst_vs_d (32411): drop_caches: 3 [ 2156.207467] Lustre: DEBUG MARKER: == sanityn test 16g: mmap rw sequential consistency vs drop_caches ========================================================== 02:51:14 (1788331874) [ 2156.707863] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2156.765475] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2157.018566] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2157.191064] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2157.335943] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2157.455486] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2157.502325] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2157.598408] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2157.633759] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2157.716567] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2157.766890] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2157.866448] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2157.991842] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2158.037318] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2158.151737] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2158.412113] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2158.497055] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2158.608459] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2158.783379] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2159.009820] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2159.188783] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2159.287921] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2159.388832] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2159.510610] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2159.625539] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2159.717826] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2159.792598] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2159.849336] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2159.920380] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2160.049307] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2160.171630] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2160.213316] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2160.369805] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2160.480513] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2160.580507] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2160.668634] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2160.719090] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2160.999696] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2161.113333] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2161.162052] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2161.287181] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2161.396686] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2161.574144] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2161.641895] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2161.723739] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2161.900392] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2162.055481] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2162.220813] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2162.351408] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2162.449310] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2162.492868] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2162.572321] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2162.665273] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2162.690820] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2162.726272] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2162.836210] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2162.857930] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2162.996441] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2163.184676] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2163.260521] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2163.296204] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2163.519455] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2163.762191] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2164.044759] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2164.153854] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2164.324598] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2164.518989] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2164.693331] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2164.823181] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2164.977304] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2165.129863] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2165.193495] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2165.397082] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2165.563780] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2165.702877] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2165.831417] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2165.971865] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2166.036851] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2166.126878] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2166.211799] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2166.273788] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2166.345792] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2166.467442] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2166.587334] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2166.766475] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2166.869804] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2167.003980] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2167.112321] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2167.263419] Lustre: lustre-OST0000-osc-ffff9efb45ee9800: disconnect after 20s idle [ 2167.295880] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2167.370695] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2167.484491] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2167.578065] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2167.646881] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2167.813495] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2167.927299] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2168.094782] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2168.268920] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2168.402381] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2168.437088] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2168.552140] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2168.769844] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2168.926722] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2169.018699] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2169.088733] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2169.193571] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2169.291819] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2169.340391] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2169.520114] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2169.654366] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2169.699707] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2169.866491] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2169.969087] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2170.025440] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2170.215353] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2170.281261] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2170.317933] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2170.437430] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2170.526492] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2170.593614] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2170.770172] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2170.986971] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2171.122216] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2171.289555] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2171.359380] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2171.598577] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2171.689324] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2171.850346] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2172.141887] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2172.285953] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2172.346371] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2172.499129] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2172.603922] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2172.940131] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2173.036907] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2173.123980] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2173.215599] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2173.397448] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2173.536344] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2173.652290] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2173.737709] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2173.770165] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2173.835144] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2173.886537] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2173.931802] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2174.130367] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2174.237125] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2174.385650] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2174.450548] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2174.698190] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2175.096992] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2175.200981] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2175.401120] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2175.578548] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2175.678065] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2175.809924] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2175.984525] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2176.142664] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2176.333740] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2176.394263] rw_seq_cst_vs_d (32996): drop_caches: 3 [ 2177.511952] Lustre: lustre-OST0000-osc-ffff9efb51572000: disconnect after 24s idle [ 2186.887067] Lustre: DEBUG MARKER: == sanityn test 16h: mmap read after truncate file ======= 02:51:43 (1788331903) [ 2194.318847] Lustre: DEBUG MARKER: == sanityn test 16i: read after truncate file ============ 02:51:51 (1788331911) [ 2202.207791] Lustre: DEBUG MARKER: == sanityn test 16j: race dio with buffered i/o ========== 02:51:59 (1788331919) [ 2239.703995] Lustre: DEBUG MARKER: == sanityn test 16k: Parallel FSX and drop caches should not panic ========================================================== 02:52:37 (1788331957) [ 2240.510783] bash (35477): drop_caches: 3 [ 2244.151953] bash (35477): drop_caches: 3 [ 2247.465191] bash (35477): drop_caches: 3 [ 2250.672499] bash (35477): drop_caches: 3 [ 2253.808069] bash (35477): drop_caches: 3 [ 2256.992332] bash (35477): drop_caches: 3 [ 2260.197163] bash (35477): drop_caches: 3 [ 2263.350966] bash (35477): drop_caches: 3 [ 2266.682277] bash (35477): drop_caches: 3 [ 2269.821149] bash (35477): drop_caches: 3 [ 2273.101877] bash (35477): drop_caches: 3 [ 2276.275466] bash (35477): drop_caches: 3 [ 2279.647044] bash (35477): drop_caches: 3 [ 2282.928624] bash (35477): drop_caches: 3 [ 2286.037388] bash (35477): drop_caches: 3 [ 2289.148834] bash (35477): drop_caches: 3 [ 2292.299788] bash (35477): drop_caches: 3 [ 2297.197945] Lustre: DEBUG MARKER: == sanityn test 17: resource creation/LVB creation race ========================================================================= 02:53:34 (1788332014) [ 2307.340595] Lustre: DEBUG MARKER: == sanityn test 18: mmap sanity check =========================================================================================== 02:53:45 (1788332025) [ 2320.863217] Lustre: lustre-OST0001-osc-ffff9efb45ee9800: disconnect after 23s idle [ 2336.149680] Lustre: DEBUG MARKER: == sanityn test 19: test concurrent uncached read races ========================================================================= 02:54:14 (1788332054) [ 2344.797071] Lustre: DEBUG MARKER: loop 5 [ 2349.324549] Lustre: DEBUG MARKER: loop 10 [ 2354.917190] Lustre: DEBUG MARKER: loop 15 [ 2359.390951] Lustre: DEBUG MARKER: loop 20 [ 2368.133695] Lustre: DEBUG MARKER: == sanityn test 20: test extra readahead page left in cache ============================================================== 02:54:46 (1788332086) [ 2375.591155] Lustre: DEBUG MARKER: == sanityn test 21: Try to remove mountpoint on another dir ============================================================== 02:54:53 (1788332093) [ 2381.582720] Lustre: DEBUG MARKER: == sanityn test 23: others should see updated atime while another read============================================================== 02:54:59 (1788332099) [ 2387.424500] Lustre: lustre-OST0001-osc-ffff9efb45ee9800: disconnect after 20s idle [ 2387.428823] Lustre: Skipped 2 previous similar messages [ 2452.709641] Lustre: DEBUG MARKER: == sanityn test 24a: lfs df [-ih] [path] test =================================================================================== 02:56:11 (1788332171) [ 2461.692310] Lustre: DEBUG MARKER: == sanityn test 24b: lfs df should show both filesystems ========================================================================= 02:56:19 (1788332179) [ 2468.510776] Lustre: DEBUG MARKER: == sanityn test 25a: change ACL on one mountpoint be seen on another ============================================================= 02:56:26 (1788332186) [ 2477.770901] Lustre: DEBUG MARKER: == sanityn test 25b: change ACL under remote dir on one mountpoint be seen on another ========================================================== 02:56:35 (1788332195) [ 2485.485754] Lustre: DEBUG MARKER: == sanityn test 26a: allow mtime to get older ============ 02:56:43 (1788332203) [ 2494.527093] Lustre: DEBUG MARKER: == sanityn test 26b: sync mtime between ost and mds ====== 02:56:52 (1788332212) [ 2503.874386] Lustre: DEBUG MARKER: == sanityn test 26c: set-in-past on open file is not lost on close ========================================================== 02:57:01 (1788332221) [ 2505.185871] Lustre: lustre-OST0001-osc-ffff9efb51572000: disconnect after 21s idle [ 2505.201499] Lustre: Skipped 3 previous similar messages [ 2514.080310] Lustre: DEBUG MARKER: SKIP: sanityn test_27 skipping excluded test 27 [ 2516.457249] Lustre: DEBUG MARKER: == sanityn test 30: recreate file race =================== 02:57:13 (1788332233) [ 2529.790341] Lustre: DEBUG MARKER: == sanityn test 31a: voluntary cancel / blocking ast race======================================================================== 02:57:26 (1788332246) [ 2530.630846] Lustre: *** cfs_fail_loc=314, val=0*** [ 2531.679309] Lustre: *** cfs_fail_loc=314, val=0*** [ 2531.689719] Lustre: Skipped 2 previous similar messages [ 2541.588369] Lustre: DEBUG MARKER: == sanityn test 31b: voluntary OST cancel / blocking ast race======================================================================== 02:57:39 (1788332259) [ 2553.717703] Lustre: *** cfs_fail_loc=314, val=0*** [ 2553.785369] LustreError: lustre-OST0000-osc-ffff9efb45ee9800: operation ldlm_enqueue to node 192.168.201.151@tcp failed: rc = -107 [ 2553.789779] Lustre: lustre-OST0000-osc-ffff9efb45ee9800: Connection to lustre-OST0000 (at 192.168.201.151@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 2553.802775] LustreError: lustre-OST0000-osc-ffff9efb45ee9800: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 2553.811472] LustreError: 46429:0:(ldlm_resource.c:1207:ldlm_resource_complain()) lustre-OST0000-osc-ffff9efb45ee9800: namespace resource [0x280000400:0x8:0x0].0x0 (ffff9efb532f5300) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 2553.824262] Lustre: lustre-OST0000-osc-ffff9efb45ee9800: Connection restored to 192.168.201.151@tcp (at 192.168.201.151@tcp) [ 2562.916557] Lustre: DEBUG MARKER: == sanityn test 31r: open-rename(replace) race =========== 02:58:00 (1788332280) [ 2563.206671] LustreError: 47019:0:(file.c:850:ll_intent_file_open()) cfs_fail_timeout id 1419 sleeping for 3000ms [ 2566.231237] LustreError: 47019:0:(file.c:850:ll_intent_file_open()) cfs_fail_timeout id 1419 awake [ 2573.155457] Lustre: DEBUG MARKER: == sanityn test 31s: open should not revalidate invalid dentry ========================================================== 02:58:11 (1788332291) [ 2582.719367] Lustre: DEBUG MARKER: == sanityn test 31t: getattr should not revalidate invalid dentry ========================================================== 02:58:20 (1788332300) [ 2592.034620] Lustre: DEBUG MARKER: == sanityn test 32b: lockless i/o ======================== 02:58:29 (1788332309) [ 2594.822079] Lustre: DEBUG MARKER: SKIP: sanityn test_32b max_nolock_bytes is removed >= 2.17.53 [ 2597.040674] Lustre: DEBUG MARKER: == sanityn test 32c: contention detection ================ 02:58:34 (1788332314) [ 2631.849084] Lustre: DEBUG MARKER: SKIP: sanityn test_33a skipping SLOW test 33a [ 2633.829655] Lustre: DEBUG MARKER: == sanityn test 33b: COS: cross create/delete, 2 clients, benchmark under remote dir ========================================================== 02:59:11 (1788332351) [ 2636.003657] Lustre: DEBUG MARKER: SKIP: sanityn test_33b Need two or more clients, have 1 [ 2637.982663] Lustre: DEBUG MARKER: == sanityn test 33c: Cancel cross-MDT lock should trigger Sync-on-Lock-Cancel ========================================================== 02:59:15 (1788332355) [ 2638.303357] Lustre: lustre-OST0001-osc-ffff9efb51572000: disconnect after 23s idle [ 2638.307920] Lustre: Skipped 1 previous similar message [ 2643.438649] Lustre: lustre-MDT0000-mdc-ffff9efb45ee9800: Connection to lustre-MDT0000 (at 192.168.201.151@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 2653.677761] LustreError: MGC192.168.201.151@tcp: Connection to MGS (at 192.168.201.151@tcp) was lost; in progress operations using this service will fail [ 2653.725566] Lustre: Evicted from MGS (at 192.168.201.151@tcp) after server handle changed from 0xb537d7c8a6ee09e7 to 0xb537d7c8a6f92052 [ 2653.754657] Lustre: MGC192.168.201.151@tcp: Connection restored to 192.168.201.151@tcp (at 192.168.201.151@tcp) [ 2655.842696] Lustre: lustre-MDT0000-mdc-ffff9efb51572000: Connection restored to 192.168.201.151@tcp (at 192.168.201.151@tcp) [ 2697.717876] Lustre: DEBUG MARKER: == sanityn test 33d: dependent transactions should trigger COS ========================================================== 03:00:14 (1788332414) [ 2765.798975] Lustre: DEBUG MARKER: == sanityn test 33e: independent transactions shouldn't trigger COS ========================================================== 03:01:23 (1788332483) [ 2787.191391] Lustre: DEBUG MARKER: == sanityn test 34: no lock timeout under IO ============= 03:01:45 (1788332505) [ 2842.073436] Lustre: lustre-OST0001-osc-ffff9efb51572000: Connection to lustre-OST0001 (at 192.168.201.151@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 2842.089246] Lustre: Skipped 2 previous similar messages [ 2842.091465] LustreError: lustre-OST0001-osc-ffff9efb45ee9800: This client was evicted by lustre-OST0001; in progress operations using this service will fail. [ 2842.121466] LustreError: lustre-OST0001-osc-ffff9efb51572000: This client was evicted by lustre-OST0001; in progress operations using this service will fail. [ 2842.124184] Lustre: lustre-OST0001-osc-ffff9efb45ee9800: Connection restored to 192.168.201.151@tcp (at 192.168.201.151@tcp) [ 2842.155963] Lustre: Skipped 2 previous similar messages [ 2857.410511] Lustre: lustre-OST0000-osc-ffff9efb51572000: Connection to lustre-OST0000 (at 192.168.201.151@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 2857.444459] LustreError: lustre-OST0000-osc-ffff9efb51572000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 2857.464094] Lustre: lustre-OST0000-osc-ffff9efb51572000: Connection restored to 192.168.201.151@tcp (at 192.168.201.151@tcp) [ 2879.278477] Lustre: DEBUG MARKER: oleg151-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0000-osc-ffff9efb45ee9800.ost_server_uuid 50 [ 2881.061601] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9efb45ee9800.ost_server_uuid in FULL state after 0 sec [ 2887.338060] Lustre: DEBUG MARKER: oleg151-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0001-osc-ffff9efb45ee9800.ost_server_uuid 50 [ 2889.020911] Lustre: DEBUG MARKER: osc.lustre-OST0001-osc-ffff9efb45ee9800.ost_server_uuid in IDLE state after 0 sec [ 2896.520103] Lustre: DEBUG MARKER: oleg151-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0000-osc-ffff9efb45ee9800.ost_server_uuid 50 [ 2897.850616] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9efb45ee9800.ost_server_uuid in FULL state after 0 sec [ 2904.790462] Lustre: DEBUG MARKER: oleg151-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0001-osc-ffff9efb45ee9800.ost_server_uuid 50 [ 2907.430688] Lustre: DEBUG MARKER: osc.lustre-OST0001-osc-ffff9efb45ee9800.ost_server_uuid in IDLE state after 0 sec [ 2922.528127] Lustre: DEBUG MARKER: oleg151-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0000-osc-ffff9efb45ee9800.ost_server_uuid 50 [ 2924.148837] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9efb45ee9800.ost_server_uuid in FULL state after 0 sec [ 2931.909353] Lustre: DEBUG MARKER: oleg151-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0001-osc-ffff9efb45ee9800.ost_server_uuid 50 [ 2933.821849] Lustre: DEBUG MARKER: osc.lustre-OST0001-osc-ffff9efb45ee9800.ost_server_uuid in IDLE state after 0 sec [ 2935.632960] Lustre: DEBUG MARKER: == sanityn test 35: -EINTR cp_ast vs. bl_ast race does not evict client ========================================================== 03:04:13 (1788332653) [ 2938.441863] Lustre: DEBUG MARKER: Race attempt 0 [ 2941.765079] Lustre: DEBUG MARKER: Wait for 59650 59662 for 60 sec... [ 3010.357619] Lustre: DEBUG MARKER: == sanityn test 36: handle ESTALE/open-unlink correctly == 03:05:28 (1788332728) [ 3019.042921] Lustre: DEBUG MARKER: start test - cycle (0) [ 3046.126383] Lustre: DEBUG MARKER: start test - cycle (1) [ 3053.025355] Lustre: lustre-OST0001-osc-ffff9efb45ee9800: disconnect after 24s idle [ 3053.033383] Lustre: Skipped 13 previous similar messages [ 3068.394672] Lustre: DEBUG MARKER: start test - cycle (2) [ 3095.043801] Lustre: DEBUG MARKER: start test - cycle (3) [ 3119.655824] Lustre: DEBUG MARKER: start test - cycle (4) [ 3146.648234] Lustre: DEBUG MARKER: start test - cycle (5) [ 3170.561065] Lustre: DEBUG MARKER: start test - cycle (6) [ 3198.091883] Lustre: DEBUG MARKER: start test - cycle (7) [ 3223.548214] Lustre: DEBUG MARKER: start test - cycle (8) [ 3250.008496] Lustre: DEBUG MARKER: start test - cycle (9) [ 3276.488777] Lustre: DEBUG MARKER: start test - cycle (10) [ 3306.437986] Lustre: DEBUG MARKER: == sanityn test 37: check i_size is not updated for directory on close (bug 18695) ======================================================================== 03:10:24 (1788333024) [ 3380.225188] Lustre: DEBUG MARKER: == sanityn test 39a: file mtime does not change after rename ========================================================== 03:11:37 (1788333097) [ 3389.393506] Lustre: DEBUG MARKER: == sanityn test 39b: file mtime the same on clients with/out lock ========================================================== 03:11:47 (1788333107) [ 3400.189318] Lustre: DEBUG MARKER: == sanityn test 39c: check truncate mtime update ================================================================================ 03:11:57 (1788333117) [ 3407.952821] Lustre: DEBUG MARKER: == sanityn test 39d: sync write should update mtime ====== 03:12:06 (1788333126) [ 3408.711981] Lustre: *** cfs_fail_loc=411, val=0*** [ 3415.333411] Lustre: DEBUG MARKER: SKIP: sanityn test_40a skipping ALWAYS excluded test 40a [ 3417.439590] Lustre: DEBUG MARKER: == sanityn test 40b: pdirops: open|create and others ======================================================================== 03:12:15 (1788333135) [ 3435.387101] Lustre: DEBUG MARKER: == sanityn test 40c: pdirops: link and others ======================================================================== 03:12:33 (1788333153) [ 3453.552766] Lustre: DEBUG MARKER: == sanityn test 40d: pdirops: unlink and others ======================================================================== 03:12:51 (1788333171) [ 3471.257820] Lustre: DEBUG MARKER: == sanityn test 40e: pdirops: rename and others ======================================================================== 03:13:08 (1788333188) [ 3489.961068] Lustre: DEBUG MARKER: == sanityn test 41a: pdirops: create vs mkdir ======================================================================== 03:13:27 (1788333207) [ 3503.857066] Lustre: DEBUG MARKER: == sanityn test 41b: pdirops: create vs create ======================================================================== 03:13:41 (1788333221) [ 3516.261233] Lustre: DEBUG MARKER: == sanityn test 41c: pdirops: create vs link ======================================================================== 03:13:53 (1788333233) [ 3530.292057] Lustre: DEBUG MARKER: == sanityn test 41d: pdirops: create vs unlink ======================================================================== 03:14:08 (1788333248) [ 3543.309321] Lustre: DEBUG MARKER: == sanityn test 41e: pdirops: create and rename (tgt) ======================================================================== 03:14:21 (1788333261) [ 3556.652199] Lustre: DEBUG MARKER: == sanityn test 41f: pdirops: create and rename (src) ======================================================================== 03:14:34 (1788333274) [ 3569.028152] Lustre: DEBUG MARKER: == sanityn test 41g: pdirops: create vs getattr ======================================================================== 03:14:47 (1788333287) [ 3575.264493] Lustre: lustre-OST0000-osc-ffff9efb45ee9800: disconnect after 20s idle [ 3575.277498] Lustre: Skipped 13 previous similar messages [ 3581.684516] Lustre: DEBUG MARKER: == sanityn test 41h: pdirops: create vs readdir ======================================================================== 03:14:59 (1788333299) [ 3598.193547] Lustre: DEBUG MARKER: == sanityn test 41i: reint_open: create vs create ======== 03:15:16 (1788333316) [ 4215.263335] Lustre: lustre-OST0000-osc-ffff9efb45ee9800: disconnect after 22s idle [ 4215.265912] Lustre: Skipped 2 previous similar messages [ 4685.968910] Lustre: DEBUG MARKER: == sanityn test 42a: pdirops: mkdir vs mkdir ======================================================================== 03:33:23 (1788334403) [ 4701.544707] Lustre: DEBUG MARKER: == sanityn test 42b: pdirops: mkdir vs create ======================================================================== 03:33:39 (1788334419) [ 4717.336664] Lustre: DEBUG MARKER: == sanityn test 42c: pdirops: mkdir vs link ======================================================================== 03:33:55 (1788334435) [ 4730.531408] Lustre: DEBUG MARKER: == sanityn test 42d: pdirops: mkdir vs unlink ======================================================================== 03:34:08 (1788334448) [ 4742.358964] Lustre: DEBUG MARKER: == sanityn test 42e: pdirops: mkdir and rename (tgt) ======================================================================== 03:34:20 (1788334460) [ 4756.322501] Lustre: DEBUG MARKER: == sanityn test 42f: pdirops: mkdir and rename (src) ======================================================================== 03:34:33 (1788334473) [ 4770.244084] Lustre: DEBUG MARKER: == sanityn test 42g: pdirops: mkdir vs getattr ======================================================================== 03:34:48 (1788334488) [ 4783.281054] Lustre: DEBUG MARKER: == sanityn test 42h: pdirops: mkdir vs readdir ======================================================================== 03:35:01 (1788334501) [ 4796.986273] Lustre: DEBUG MARKER: == sanityn test 43a: rmdir,mkdir doesn't return -EEXIST ======================================================================== 03:35:14 (1788334514) [ 4881.403352] Lustre: DEBUG MARKER: == sanityn test 43b: pdirops: unlink vs create ======================================================================== 03:36:38 (1788334598) [ 4895.749382] Lustre: DEBUG MARKER: == sanityn test 43c: pdirops: unlink vs link ======================================================================== 03:36:53 (1788334613) [ 4912.089347] Lustre: DEBUG MARKER: == sanityn test 43d: pdirops: unlink vs unlink ======================================================================== 03:37:09 (1788334629) [ 4925.495590] Lustre: DEBUG MARKER: == sanityn test 43e: pdirops: unlink and rename (tgt) ======================================================================== 03:37:23 (1788334643) [ 4939.173456] Lustre: DEBUG MARKER: == sanityn test 43f: pdirops: unlink and rename (src) ======================================================================== 03:37:36 (1788334656) [ 4952.718654] Lustre: DEBUG MARKER: == sanityn test 43g: pdirops: unlink vs getattr ======================================================================== 03:37:50 (1788334670) [ 4967.019659] Lustre: DEBUG MARKER: == sanityn test 43h: pdirops: unlink vs readdir ======================================================================== 03:38:04 (1788334684) [ 4967.903755] Lustre: lustre-OST0000-osc-ffff9efb51572000: disconnect after 21s idle [ 4967.911990] Lustre: Skipped 4 previous similar messages [ 4981.379615] Lustre: DEBUG MARKER: == sanityn test 43i: pdirops: unlink vs remote mkdir ===== 03:38:19 (1788334699) [ 4996.326353] Lustre: DEBUG MARKER: == sanityn test 43j: racy mkdir return EEXIST ======================================================================== 03:38:34 (1788334714) [ 5127.365556] Lustre: DEBUG MARKER: == sanityn test 43k: unlink vs create ==================== 03:40:44 (1788334844) [ 5607.904333] Lustre: lustre-OST0000-osc-ffff9efb51572000: disconnect after 20s idle [ 5607.908882] Lustre: Skipped 6 previous similar messages [ 6140.179387] Lustre: DEBUG MARKER: == sanityn test 44a: pdirops: rename tgt vs mkdir ======================================================================== 03:57:38 (1788335858) [ 6150.056023] Lustre: DEBUG MARKER: == sanityn test 44b: pdirops: rename tgt vs create ======================================================================== 03:57:48 (1788335868) [ 6160.985749] Lustre: DEBUG MARKER: == sanityn test 44c: pdirops: rename tgt vs link ======================================================================== 03:57:59 (1788335879) [ 6171.041276] Lustre: DEBUG MARKER: == sanityn test 44d: pdirops: rename tgt vs unlink ======================================================================== 03:58:09 (1788335889) [ 6180.724403] Lustre: DEBUG MARKER: == sanityn test 44e: pdirops: rename tgt and rename (tgt) ======================================================================== 03:58:18 (1788335898) [ 6189.976398] Lustre: DEBUG MARKER: == sanityn test 44f: pdirops: rename tgt and rename (src) ======================================================================== 03:58:28 (1788335908) [ 6198.603754] Lustre: DEBUG MARKER: == sanityn test 44g: pdirops: rename tgt vs getattr ======================================================================== 03:58:36 (1788335916) [ 6207.395619] Lustre: DEBUG MARKER: == sanityn test 44h: pdirops: rename tgt vs readdir ======================================================================== 03:58:45 (1788335925) [ 6217.034799] Lustre: DEBUG MARKER: == sanityn test 44i: pdirops: rename tgt vs remote mkdir ========================================================== 03:58:55 (1788335935) [ 6226.726439] Lustre: DEBUG MARKER: == sanityn test 45a: rename,mkdir doesn't return -EEXIST ======================================================================== 03:59:05 (1788335945) [ 6242.786885] Lustre: lustre-OST0001-osc-ffff9efb51572000: disconnect after 25s idle [ 6242.794440] Lustre: Skipped 5 previous similar messages [ 6335.244895] Lustre: DEBUG MARKER: == sanityn test 45b: pdirops: rename src vs create ======================================================================== 04:00:53 (1788336053) [ 6344.205151] Lustre: DEBUG MARKER: == sanityn test 45c: pdirops: rename src vs link ======================================================================== 04:01:02 (1788336062) [ 6352.450831] Lustre: DEBUG MARKER: == sanityn test 45d: pdirops: rename src vs unlink ======================================================================== 04:01:10 (1788336070) [ 6362.019922] Lustre: DEBUG MARKER: == sanityn test 45e: pdirops: rename src and rename (tgt) ======================================================================== 04:01:20 (1788336080) [ 6370.696098] Lustre: DEBUG MARKER: == sanityn test 45f: pdirops: rename src and rename (src) ======================================================================== 04:01:29 (1788336089) [ 6379.532306] Lustre: DEBUG MARKER: == sanityn test 45g: pdirops: rename src vs getattr ======================================================================== 04:01:37 (1788336097) [ 6388.228378] Lustre: DEBUG MARKER: == sanityn test 45h: pdirops: unlink vs readdir ======================================================================== 04:01:46 (1788336106) [ 6396.561756] Lustre: DEBUG MARKER: == sanityn test 45i: pdirops: rename src vs remote mkdir ========================================================== 04:01:54 (1788336114) [ 6405.400547] Lustre: DEBUG MARKER: == sanityn test 45j: read vs rename ====================== 04:02:03 (1788336123) [ 7045.491272] Lustre: DEBUG MARKER: == sanityn test 46a: pdirops: link vs mkdir ======================================================================== 04:12:44 (1788336764) [ 7051.498657] Lustre: DEBUG MARKER: == sanityn test 46b: pdirops: link vs create ======================================================================== 04:12:50 (1788336770) [ 7057.239991] Lustre: DEBUG MARKER: == sanityn test 46c: pdirops: link vs link ======================================================================== 04:12:56 (1788336776) [ 7061.985197] Lustre: lustre-OST0001-osc-ffff9efb45ee9800: disconnect after 20s idle [ 7061.988175] Lustre: Skipped 1 previous similar message [ 7063.038109] Lustre: DEBUG MARKER: == sanityn test 46d: pdirops: link vs unlink ======================================================================== 04:13:01 (1788336781) [ 7068.870028] Lustre: DEBUG MARKER: == sanityn test 46e: pdirops: link and rename (tgt) ======================================================================== 04:13:07 (1788336787) [ 7074.389676] Lustre: DEBUG MARKER: == sanityn test 46f: pdirops: link and rename (src) ======================================================================== 04:13:13 (1788336793) [ 7079.919592] Lustre: DEBUG MARKER: == sanityn test 46g: pdirops: link vs getattr ======================================================================== 04:13:18 (1788336798) [ 7085.876069] Lustre: DEBUG MARKER: == sanityn test 46h: pdirops: link vs readdir ======================================================================== 04:13:24 (1788336804) [ 7091.991505] Lustre: DEBUG MARKER: == sanityn test 46i: pdirops: link vs remote mkdir ======= 04:13:30 (1788336810) [ 7097.745067] Lustre: DEBUG MARKER: == sanityn test 47a: pdirops: remote mkdir vs mkdir ====== 04:13:36 (1788336816) [ 7103.341600] Lustre: DEBUG MARKER: == sanityn test 47b: pdirops: remote mkdir vs create ===== 04:13:42 (1788336822) [ 7109.829966] Lustre: DEBUG MARKER: == sanityn test 47c: pdirops: remote mkdir vs link ======= 04:13:48 (1788336828) [ 7115.446321] Lustre: DEBUG MARKER: == sanityn test 47d: pdirops: remote mkdir vs unlink ===== 04:13:54 (1788336834) [ 7120.985412] Lustre: DEBUG MARKER: == sanityn test 47e: pdirops: remote mkdir and rename (tgt) ========================================================== 04:13:59 (1788336839) [ 7126.730243] Lustre: DEBUG MARKER: == sanityn test 47f: pdirops: remote mkdir and rename (src) ========================================================== 04:14:05 (1788336845) [ 7132.833048] Lustre: DEBUG MARKER: == sanityn test 47g: pdirops: remote mkdir vs getattr ==== 04:14:11 (1788336851) [ 7140.758859] Lustre: DEBUG MARKER: == sanityn test 50: osc lvb attrs: enqueue vs. CP AST ======================================================================== 04:14:19 (1788336859) [ 7140.873884] LustreError: 22698:0:(ldlm_lockd.c:2079:ldlm_handle_cp_callback()) cfs_fail_timeout id 410 sleeping for 2000ms [ 7142.959130] LustreError: 22698:0:(ldlm_lockd.c:2079:ldlm_handle_cp_callback()) cfs_fail_timeout id 410 awake [ 7148.704990] Lustre: DEBUG MARKER: == sanityn test 51a: layout lock: refresh layout should work ========================================================== 04:14:27 (1788336867) [ 7153.216245] Lustre: DEBUG MARKER: == sanityn test 51b: layout lock: glimpse should be able to restart if layout changed ========================================================== 04:14:31 (1788336871) [ 7153.345616] LustreError: 240878:0:(glimpse.c:206:__cl_glimpse_size()) cfs_fail_timeout id 1404 sleeping for 4000ms [ 7157.407105] LustreError: 240878:0:(glimpse.c:206:__cl_glimpse_size()) cfs_fail_timeout id 1404 awake [ 7157.416156] LustreError: 240878:0:(glimpse.c:206:__cl_glimpse_size()) cfs_fail_timeout id 1404 sleeping for 4000ms [ 7161.471131] LustreError: 240878:0:(glimpse.c:206:__cl_glimpse_size()) cfs_fail_timeout id 1404 awake [ 7161.486183] LustreError: 240885:0:(glimpse.c:206:__cl_glimpse_size()) cfs_fail_timeout id 1404 sleeping for 4000ms [ 7165.543145] LustreError: 240885:0:(glimpse.c:206:__cl_glimpse_size()) cfs_fail_timeout id 1404 awake [ 7168.274513] Lustre: DEBUG MARKER: == sanityn test 51c: layout lock: IT_LAYOUT blocked and correct layout can be returned ========================================================== 04:14:47 (1788336887) [ 7175.928584] Lustre: DEBUG MARKER: == sanityn test 51d: layout lock: losing layout lock should clean up memory map region ========================================================== 04:14:54 (1788336894) [ 7180.074851] Lustre: DEBUG MARKER: == sanityn test 51e: lfs getstripe does not break leases, part 2 ========================================================== 04:14:58 (1788336898) [ 7185.239735] Lustre: DEBUG MARKER: == sanityn test 54: rename locking ======================= 04:15:03 (1788336903) [ 7211.228143] Lustre: DEBUG MARKER: == sanityn test 55a: rename vs unlink target dir ========= 04:15:30 (1788336930) [ 7219.655847] Lustre: DEBUG MARKER: == sanityn test 55b: rename vs unlink source dir ========= 04:15:38 (1788336938) [ 7227.739795] Lustre: DEBUG MARKER: == sanityn test 55c: rename vs unlink orphan target dir == 04:15:46 (1788336946) [ 7241.166944] Lustre: DEBUG MARKER: == sanityn test 55d: rename file vs link ================= 04:15:59 (1788336959) [ 7251.340925] Lustre: DEBUG MARKER: == sanityn test 55e: rename race AB/BA under the same parent dir ========================================================== 04:16:10 (1788336970) [ 7264.975321] Lustre: DEBUG MARKER: == sanityn test 55f: rename: (P1/A -> P2/B) race with (P2/B -> P1/A) ========================================================== 04:16:23 (1788336983) [ 7279.764114] Lustre: DEBUG MARKER: == sanityn test 55g: rename: race with trylock =========== 04:16:38 (1788336998) [ 7294.829922] Lustre: DEBUG MARKER: == sanityn test 56a: test llverdev with single large stripe ========================================================== 04:16:53 (1788337013) [ 7303.248525] Lustre: DEBUG MARKER: == sanityn test 56b: test llverdev and partial verify of wide stripe file ========================================================== 04:17:01 (1788337021) [ 7338.700385] Lustre: DEBUG MARKER: == sanityn test 60: Verify data_version behaviour ======== 04:17:37 (1788337057) [ 7342.341477] Lustre: DEBUG MARKER: == sanityn test 70a: cd directory [ 7346.291525] Lustre: DEBUG MARKER: == sanityn test 70b: remove files after calling rm_entry ========================================================== 04:17:44 (1788337064) [ 7350.021261] Lustre: DEBUG MARKER: == sanityn test 71a: correct file map just after write operation is finished ========================================================== 04:17:48 (1788337068) [ 7353.214631] Lustre: DEBUG MARKER: == sanityn test 71b: check fiemap support for stripecount > 1 ========================================================== 04:17:51 (1788337071) [ 7356.407889] Lustre: DEBUG MARKER: == sanityn test 71c: check FIEMAP_EXTENT_LAST flag with different extents number ========================================================== 04:17:55 (1788337075) [ 7375.913720] Lustre: DEBUG MARKER: == sanityn test 71d: fiemap corruption test with fm_extent_count=0 ========================================================== 04:18:14 (1788337094) [ 7398.350443] Lustre: DEBUG MARKER: == sanityn test 72: getxattr/setxattr cache should be consistent between nodes ========================================================== 04:18:37 (1788337117) [ 7400.956423] Lustre: DEBUG MARKER: == sanityn test 73: getxattr should not cause xattr lock cancellation ========================================================== 04:18:39 (1788337119) [ 7403.656527] Lustre: DEBUG MARKER: == sanityn test 74: flock deadlock: different mounts ======================================================================== 04:18:42 (1788337122) [ 7406.805548] LustreError: lustre-MDT0000-mdc-ffff9efb45ee9800: operation ldlm_enqueue to node 192.168.201.151@tcp failed: rc = -35 [ 7410.392372] Lustre: DEBUG MARKER: == sanityn test 75: osc: upcall after unuse lock============================================================================= 04:18:49 (1788337129) [ 7410.605606] LustreError: 2397:0:(osc_request.c:3139:osc_enqueue_interpret()) cfs_fail_timeout id 31d sleeping for 2000ms [ 7412.695165] LustreError: 2397:0:(osc_request.c:3139:osc_enqueue_interpret()) cfs_fail_timeout id 31d awake [ 7418.245556] Lustre: DEBUG MARKER: == sanityn test 76: Verify MDT open_files listing ======== 04:18:56 (1788337136) [ 7482.503949] Lustre: DEBUG MARKER: == sanityn test 77a: check FIFO NRS policy =============== 04:20:01 (1788337201) [ 7486.193263] Lustre: DEBUG MARKER: == sanityn test 77b: check CRR-N NRS policy ============== 04:20:04 (1788337204) [ 7491.571538] Lustre: DEBUG MARKER: == sanityn test 77c: check ORR NRS policy ================ 04:20:10 (1788337210) [ 7498.043391] Lustre: DEBUG MARKER: == sanityn test 77d: check TRR nrs policy ================ 04:20:16 (1788337216) [ 7505.172133] Lustre: DEBUG MARKER: == sanityn test 77e: check TBF NID nrs policy ============ 04:20:23 (1788337223) [ 7515.177478] Lustre: DEBUG MARKER: == sanityn test 77f: check TBF JobID nrs policy ========== 04:20:33 (1788337233) [ 7524.496618] Lustre: DEBUG MARKER: == sanityn test 77g: Change TBF type directly ============ 04:20:43 (1788337243) [ 7528.505344] Lustre: DEBUG MARKER: == sanityn test 77h: Wrong policy name should report error, not LBUG ========================================================== 04:20:47 (1788337247) [ 7533.032174] Lustre: DEBUG MARKER: == sanityn test 77i: Change rank of TBF rule ============= 04:20:51 (1788337251) [ 7542.166761] Lustre: DEBUG MARKER: == sanityn test 77j: check TBF-OPCode NRS policy ========= 04:21:00 (1788337260) [ 7584.950891] Lustre: DEBUG MARKER: == sanityn test 77ja: check TBF-UID/GID NRS policy ======= 04:21:43 (1788337303) [ 7676.383291] Lustre: lustre-OST0001-osc-ffff9efb51572000: disconnect after 24s idle [ 7676.389736] Lustre: Skipped 9 previous similar messages [ 7710.655263] Lustre: DEBUG MARKER: == sanityn test 77jb: check TBF-UID/GID NRS policy on files that don't belong to us ========================================================== 04:23:49 (1788337429) [ 7832.814670] Lustre: DEBUG MARKER: == sanityn test 77k: check TBF policy with UID/GID/JobID/OPCode expression ========================================================== 04:25:51 (1788337551) [ 8110.222548] Lustre: DEBUG MARKER: == sanityn test 77kb: Check different granular TBF type combination: jobid+opcode ========================================================== 04:30:28 (1788337828) [ 8137.704544] Lustre: DEBUG MARKER: == sanityn test 77kc: Check different granular TBF type combination: nid+opcode ========================================================== 04:30:56 (1788337856) [ 8164.047983] Lustre: DEBUG MARKER: == sanityn test 77kd: Check different granular TBF type combination: nid+jobid ========================================================== 04:31:22 (1788337882) [ 8186.801680] Lustre: DEBUG MARKER: == sanityn test 77ke: Check different granular TBF type combination: jobid+opcode ========================================================== 04:31:45 (1788337905) [ 8245.115116] Lustre: DEBUG MARKER: == sanityn test 77kf: Check different granular TBF type combination: uid+gid ========================================================== 04:32:43 (1788337963) [ 8299.040622] Lustre: DEBUG MARKER: == sanityn test 77kg: check different granular TBF type combination: uid+opcode ========================================================== 04:33:37 (1788338017) [ 8321.503225] Lustre: lustre-OST0001-osc-ffff9efb51572000: disconnect after 21s idle [ 8321.505501] Lustre: Skipped 10 previous similar messages [ 8386.585040] Lustre: DEBUG MARKER: == sanityn test 77kh: Verify that Project ID support for NRS TBF rule ========================================================== 04:35:05 (1788338105) [ 8387.719117] Lustre: Unmounted lustre-client [ 8388.394423] Lustre: Unmounted lustre-client [ 8446.716803] Lustre: Mounted lustre-client - version 2.17.57_104_g6cc0f2c [ 8448.307170] Lustre: Mounted lustre-client - version 2.17.57_104_g6cc0f2c [ 8449.393461] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 8528.994618] Lustre: DEBUG MARKER: == sanityn test 77ki: Add rule with unsupported TBF type should fail for generic TBF ========================================================== 04:37:27 (1788338247) [ 8539.374716] Lustre: DEBUG MARKER: == sanityn test 77kj: Verify nodemap support for NRS TBF rule ========================================================== 04:37:38 (1788338258) [ 8639.626740] Lustre: DEBUG MARKER: == sanityn test 77l: check the output of NRS policies for generic TBF ========================================================== 04:39:18 (1788338358) [ 8644.994558] Lustre: DEBUG MARKER: == sanityn test 77m: check NRS Delay slows write RPC processing ========================================================== 04:39:23 (1788338363) [ 8697.826636] Lustre: DEBUG MARKER: == sanityn test 77n: check wildcard support for TBF JobID NRS policy ========================================================== 04:40:16 (1788338416) [ 8756.616784] Lustre: DEBUG MARKER: == sanityn test 77o: Changing rank should not panic ====== 04:41:15 (1788338475) [ 8762.478566] Lustre: DEBUG MARKER: == sanityn test 77q: Parallel TBF rule definitions should not panic ========================================================== 04:41:21 (1788338481) [ 8817.615049] Lustre: DEBUG MARKER: == sanityn test 77p: Check validity of rule names for TBF policies ========================================================== 04:42:16 (1788338536) [ 8834.953544] Lustre: DEBUG MARKER: == sanityn test 77r: Change type of tbf policy at run time ========================================================== 04:42:33 (1788338553) [ 8894.690786] Lustre: DEBUG MARKER: == sanityn test 77s: Check TBF LRU shrinker ============== 04:43:31 (1788338611) [ 8941.025690] Lustre: lustre-OST0000-osc-ffff9efb7d94c800: disconnect after 24s idle [ 8941.039360] Lustre: Skipped 14 previous similar messages [ 8965.238771] Lustre: DEBUG MARKER: == sanityn test 78: Enable policy and specify tunings right away ========================================================== 04:44:43 (1788338683) [ 8972.805797] Lustre: DEBUG MARKER: == sanityn test 79: xattr: intent error ================== 04:44:50 (1788338690) [ 8990.060970] Lustre: DEBUG MARKER: == sanityn test 80a: migrate directory when some children is being opened ========================================================== 04:45:08 (1788338708) [ 8998.343105] Lustre: DEBUG MARKER: == sanityn test 80b: Accessing directory during migration ========================================================== 04:45:16 (1788338716) [ 9000.707198] LustreError: 311075:0:(lcommon_cl.c:187:cl_file_inode_init()) lustre: failed to initialize cl_object [0x2000013a1:0x609:0x0]: rc = -5 [ 9000.716229] LustreError: 311075:0:(llite_lib.c:3894:ll_prep_inode()) lustre: new_inode - fatal error: rc = -5 [ 9001.302486] LustreError: 311086:0:(lcommon_cl.c:187:cl_file_inode_init()) lustre: failed to initialize cl_object [0x2000013a1:0x609:0x0]: rc = -5 [ 9001.312176] LustreError: 311086:0:(lcommon_cl.c:187:cl_file_inode_init()) Skipped 1 previous similar message [ 9001.317854] LustreError: 311086:0:(llite_lib.c:3894:ll_prep_inode()) lustre: new_inode - fatal error: rc = -5 [ 9001.322821] LustreError: 311086:0:(llite_lib.c:3894:ll_prep_inode()) Skipped 1 previous similar message [ 9002.741529] LustreError: 311106:0:(lcommon_cl.c:187:cl_file_inode_init()) lustre: failed to initialize cl_object [0x240000bd0:0x32:0x0]: rc = -5 [ 9002.748484] LustreError: 311106:0:(lcommon_cl.c:187:cl_file_inode_init()) Skipped 3 previous similar messages [ 9002.754217] LustreError: 311106:0:(llite_lib.c:3894:ll_prep_inode()) lustre: new_inode - fatal error: rc = -5 [ 9002.761217] LustreError: 311106:0:(llite_lib.c:3894:ll_prep_inode()) Skipped 3 previous similar messages [ 9004.797719] LustreError: 311146:0:(lcommon_cl.c:187:cl_file_inode_init()) lustre: failed to initialize cl_object [0x2000013a1:0x618:0x0]: rc = -5 [ 9004.808183] LustreError: 311146:0:(lcommon_cl.c:187:cl_file_inode_init()) Skipped 7 previous similar messages [ 9004.814201] LustreError: 311146:0:(llite_lib.c:3894:ll_prep_inode()) lustre: new_inode - fatal error: rc = -5 [ 9004.820178] LustreError: 311146:0:(llite_lib.c:3894:ll_prep_inode()) Skipped 7 previous similar messages [ 9008.665369] LustreError: 311225:0:(file.c:251:ll_close_inode_openhandle()) lustre-clilmv-ffff9efb46650800: inode [0x240000bd0:0x5e:0x0] mdc close failed: rc = -2 [ 9008.805950] LustreError: 311228:0:(lcommon_cl.c:187:cl_file_inode_init()) lustre: failed to initialize cl_object [0x240000bd0:0x62:0x0]: rc = -5 [ 9008.819737] LustreError: 311228:0:(lcommon_cl.c:187:cl_file_inode_init()) Skipped 15 previous similar messages [ 9008.830376] LustreError: 311228:0:(llite_lib.c:3894:ll_prep_inode()) lustre: new_inode - fatal error: rc = -5 [ 9008.838836] LustreError: 311228:0:(llite_lib.c:3894:ll_prep_inode()) Skipped 15 previous similar messages [ 9017.155676] LustreError: 311389:0:(lcommon_cl.c:187:cl_file_inode_init()) lustre: failed to initialize cl_object [0x240000bd0:0x8f:0x0]: rc = -5 [ 9017.178341] LustreError: 311389:0:(lcommon_cl.c:187:cl_file_inode_init()) Skipped 44 previous similar messages [ 9017.203122] LustreError: 311389:0:(llite_lib.c:3894:ll_prep_inode()) lustre: new_inode - fatal error: rc = -5 [ 9017.214013] LustreError: 311389:0:(llite_lib.c:3894:ll_prep_inode()) Skipped 44 previous similar messages [ 9033.647460] LustreError: 311705:0:(lcommon_cl.c:187:cl_file_inode_init()) lustre: failed to initialize cl_object [0x240000bd0:0xfe:0x0]: rc = -5 [ 9033.653687] LustreError: 311705:0:(lcommon_cl.c:187:cl_file_inode_init()) Skipped 92 previous similar messages [ 9033.662612] LustreError: 311705:0:(llite_lib.c:3894:ll_prep_inode()) lustre: new_inode - fatal error: rc = -5 [ 9033.671283] LustreError: 311705:0:(llite_lib.c:3894:ll_prep_inode()) Skipped 92 previous similar messages [ 9072.713188] Lustre: DEBUG MARKER: == sanityn test 81a: rename and stat under striped directory ========================================================== 04:46:30 (1788338790) [ 9078.124329] Lustre: DEBUG MARKER: == sanityn test 81b: rename under striped directory doesn't deadlock ========================================================== 04:46:36 (1788338796) [ 9269.250774] Lustre: DEBUG MARKER: == sanityn test 81c: rename revoke LOOKUP lock for remote object ========================================================== 04:49:47 (1788338987) [ 9271.200647] Lustre: DEBUG MARKER: SKIP: sanityn test_81c needs >= 4 MDTs [ 9273.847801] Lustre: DEBUG MARKER: == sanityn test 81d: parallel rename file cross-dir on same MDT ========================================================== 04:49:51 (1788338991) [ 9507.542390] Lustre: DEBUG MARKER: == sanityn test 82: fsetxattr and fgetxattr on orphan files ========================================================== 04:53:45 (1788339225) [ 9513.958904] Lustre: DEBUG MARKER: == sanityn test 83: access striped directory while it is being created/unlinked ========================================================== 04:53:51 (1788339231) [ 9632.223446] Lustre: lustre-OST0001-osc-ffff9efb7d94c800: disconnect after 24s idle [ 9632.231219] Lustre: Skipped 5 previous similar messages [ 9641.308095] Lustre: DEBUG MARKER: == sanityn test 84: 0-nlink race in lu_object_find() ===== 04:55:59 (1788339359) [ 9654.839521] Lustre: DEBUG MARKER: == sanityn test 85: Lustre API root cache race =========== 04:56:12 (1788339372) [ 9666.819651] Lustre: DEBUG MARKER: == sanityn test 90: open/create and unlink striped directory ========================================================== 04:56:24 (1788339384) [ 9854.771896] Lustre: DEBUG MARKER: == sanityn test 91: chmod and unlink striped directory === 04:59:32 (1788339572) [10042.914249] Lustre: DEBUG MARKER: == sanityn test 92: create remote directory under orphan directory ========================================================== 05:02:40 (1788339760) [10050.084359] Lustre: DEBUG MARKER: == sanityn test 93: alloc_rr should not allocate on same ost ========================================================== 05:02:47 (1788339767) [10067.075796] Lustre: DEBUG MARKER: == sanityn test 94: signal vs CP callback race =========== 05:03:05 (1788339785) [10067.472791] Lustre: DEBUG MARKER: write [10067.550195] LustreError: 289901:0:(ldlm_request.c:1533:ldlm_cli_cancel_req()) cfs_fail_timeout id 312 sleeping for 5000ms [10069.556749] Lustre: DEBUG MARKER: kill 342757 [10069.582792] LustreError: 342757:0:(ldlm_request.c:1393:ldlm_cli_cancel_local()) cfs_fail_timeout id 329 sleeping for 6000ms [10072.575121] LustreError: 289901:0:(ldlm_request.c:1533:ldlm_cli_cancel_req()) cfs_fail_timeout id 312 awake [10075.639178] LustreError: 342757:0:(ldlm_request.c:1393:ldlm_cli_cancel_local()) cfs_fail_timeout id 329 awake [10083.793193] Lustre: DEBUG MARKER: == sanityn test 95a: Check readpage() on a page that was removed from page cache ========================================================== 05:03:21 (1788339801) [10086.538162] LustreError: 343372:0:(rw.c:1865:ll_readpage()) cfs_fail_timeout id 1422 sleeping for 10000ms [10096.583888] LustreError: 343372:0:(rw.c:1865:ll_readpage()) cfs_fail_timeout id 1422 awake [10104.673953] Lustre: DEBUG MARKER: == sanityn test 95b: Check readpage() on a page that is no longer uptodate ========================================================== 05:03:42 (1788339822) [10105.197459] LustreError: 343960:0:(rw.c:2112:ll_readpage()) cfs_fail_timeout id 1424 sleeping for 5000ms [10107.287095] LustreError: 343960:0:(rw.c:2112:ll_readpage()) cfs_fail_timeout interrupted [10118.003749] Lustre: DEBUG MARKER: == sanityn test 100a: DoM: glimpse RPCs for stat without IO lock (DoM only file) ========================================================== 05:03:55 (1788339835) [10119.561830] Lustre: DEBUG MARKER: SKIP: sanityn test_100a Reserved for glimpse-ahead [10121.636452] Lustre: DEBUG MARKER: == sanityn test 100b: DoM: no glimpse RPC for stat with IO lock (DoM only file) ========================================================== 05:03:59 (1788339839) [10130.325176] Lustre: DEBUG MARKER: == sanityn test 100c: DoM: write vs stat without IO lock (combined file) ========================================================== 05:04:07 (1788339847) [10138.705323] Lustre: DEBUG MARKER: == sanityn test 100d: DoM: write+truncate vs stat without IO lock (combined file) ========================================================== 05:04:16 (1788339856) [10146.377084] Lustre: DEBUG MARKER: == sanityn test 100e: DoM: read on open and file size ==== 05:04:23 (1788339863) [10154.797911] Lustre: DEBUG MARKER: == sanityn test 101a: Discard DoM data on unlink ========= 05:04:32 (1788339872) [10161.776504] Lustre: DEBUG MARKER: == sanityn test 101b: Discard DoM data on rename ========= 05:04:39 (1788339879) [10168.867837] Lustre: DEBUG MARKER: == sanityn test 101c: Discard DoM data on close-unlink === 05:04:46 (1788339886) [10177.512319] Lustre: DEBUG MARKER: == sanityn test 102: Test open by handle of unlinked file ========================================================== 05:04:55 (1788339895) [10186.292904] Lustre: DEBUG MARKER: == sanityn test 103: Test size correctness with lockahead ========================================================== 05:05:04 (1788339904) [10188.207134] Lustre: *** cfs_fail_loc=415, val=0*** [10200.003399] Lustre: DEBUG MARKER: == sanityn test 104: Verify that MDS stores atime/mtime/ctime during close ========================================================== 05:05:18 (1788339918) [10230.707282] Lustre: DEBUG MARKER: == sanityn test 105: Glimpse and lock cancel race ======== 05:05:48 (1788339948) [10231.085052] LustreError: 289901:0:(osc_lock.c:435:__osc_dlm_blocking_ast()) cfs_fail_timeout id 416 sleeping for 5000ms [10231.092921] LustreError: 289901:0:(osc_lock.c:435:__osc_dlm_blocking_ast()) Skipped 2 previous similar messages [10236.095108] LustreError: 289902:0:(osc_lock.c:435:__osc_dlm_blocking_ast()) cfs_fail_timeout id 416 awake [10236.104287] LustreError: 289902:0:(osc_lock.c:435:__osc_dlm_blocking_ast()) Skipped 1 previous similar message [10246.287305] LustreError: 289901:0:(osc_lock.c:435:__osc_dlm_blocking_ast()) cfs_fail_timeout id 416 awake [10246.292822] LustreError: 289901:0:(osc_lock.c:435:__osc_dlm_blocking_ast()) Skipped 5 previous similar messages [10258.770341] Lustre: DEBUG MARKER: == sanityn test 106a: Verify the btime via statx() ======= 05:06:16 (1788339976) [10267.087083] Lustre: DEBUG MARKER: == sanityn test 106b: Glimpse RPCs test for statx ======== 05:06:24 (1788339984) [10275.215097] Lustre: DEBUG MARKER: == sanityn test 106c: Verify statx attributes mask ======= 05:06:33 (1788339993) [10282.854459] Lustre: DEBUG MARKER: == sanityn test 107a: Basic grouplock conflict =========== 05:06:40 (1788340000) [10292.718072] Lustre: DEBUG MARKER: == sanityn test 107b: Grouplock is added to the head of waiting list ========================================================== 05:06:50 (1788340010) [10307.512281] Lustre: DEBUG MARKER: == sanityn test 108a: lseek: parallel updates ============ 05:07:04 (1788340024) [10308.338070] LustreError: 354707:0:(osc_request.c:2990:osc_build_rpc()) cfs_fail_timeout id 414 sleeping for 4000ms [10308.347567] LustreError: 354707:0:(osc_request.c:2990:osc_build_rpc()) Skipped 6 previous similar messages [10312.423181] LustreError: 354707:0:(osc_request.c:2990:osc_build_rpc()) cfs_fail_timeout id 414 awake [10312.428715] LustreError: 354707:0:(osc_request.c:2990:osc_build_rpc()) Skipped 2 previous similar messages [10320.779419] Lustre: DEBUG MARKER: == sanityn test 109: Race with several mount instances on 1 node ========================================================== 05:07:18 (1788340038) [10325.264133] Lustre: Unmounted lustre-client [10328.398671] Lustre: Unmounted lustre-client [10330.301244] Lustre: DEBUG MARKER: Iteration 0 [10330.876389] LustreError: 355600:0:(llite_lib.c:1509:ll_fill_super()) cfs_race id 1417 sleeping [10330.882210] LustreError: 355602:0:(llite_lib.c:1509:ll_fill_super()) cfs_fail_race id 1417 waking [10330.903774] LustreError: 355600:0:(llite_lib.c:1509:ll_fill_super()) cfs_fail_race id 1417 awake: rc=4982 [10331.292718] Lustre: Mounted lustre-client - version 2.17.57_104_g6cc0f2c [10333.202950] Lustre: Unmounted lustre-client [10336.360829] Key type lgssc unregistered [10336.619814] LNet: 355944:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [10336.623051] LNetError: 355944:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [10336.646424] LNet: Removed LNI 192.168.201.51@tcp [10337.446273] Key type .llcrypt unregistered [10337.452271] Key type ._llcrypt unregistered [10338.427147] Key type ._llcrypt registered [10338.428687] Key type .llcrypt registered [10339.087776] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [10339.101057] alg: No test for adler32 (adler32-zlib) [10340.728608] Lustre: Lustre: Build Version: 2.17.57_104_g6cc0f2c [10341.612112] LNet: Added LNI 192.168.201.51@tcp [8/256/0/180] [10343.359203] Key type lgssc registered [10344.989030] Lustre: Echo OBD driver; http://www.lustre.org/ [10357.040603] Lustre: DEBUG MARKER: Iteration 1 [10357.264118] LustreError: 356773:0:(llite_lib.c:1509:ll_fill_super()) cfs_race id 1417 sleeping [10357.310976] LustreError: 356788:0:(llite_lib.c:1509:ll_fill_super()) cfs_fail_race id 1417 waking [10357.322853] LustreError: 356773:0:(llite_lib.c:1509:ll_fill_super()) cfs_fail_race id 1417 awake: rc=4950 [10359.589789] Lustre: Mounted lustre-client - version 2.17.57_104_g6cc0f2c [10361.718104] Lustre: Unmounted lustre-client [10365.338709] Key type lgssc unregistered [10365.621122] LNet: 357116:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [10365.640466] LNetError: 357116:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [10365.661478] LNet: Removed LNI 192.168.201.51@tcp [10366.629561] Key type .llcrypt unregistered [10366.632406] Key type ._llcrypt unregistered [10367.820448] Key type ._llcrypt registered [10367.822188] Key type .llcrypt registered [10368.342282] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [10368.366559] alg: No test for adler32 (adler32-zlib) [10369.728938] Lustre: Lustre: Build Version: 2.17.57_104_g6cc0f2c [10370.133787] LNet: Added LNI 192.168.201.51@tcp [8/256/0/180] [10371.927981] Key type lgssc registered [10374.328588] Lustre: Echo OBD driver; http://www.lustre.org/ [10386.925878] Lustre: Mounted lustre-client - version 2.17.57_104_g6cc0f2c [10387.502042] Lustre: Mounted lustre-client - version 2.17.57_104_g6cc0f2c [10393.805499] Lustre: DEBUG MARKER: == sanityn test 110: do not grant another lock on resend ========================================================== 05:08:31 (1788340111) [10411.487887] Lustre: 358456:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788340114/real 1788340114] req@ffff9efb791e5880 x1875210497175168/t0(0) o36->lustre-MDT0000-mdc-ffff9efb7d35f800@192.168.201.151@tcp:12/10 lens 496/440 e 0 to 1 dl 1788340130 ref 2 fl Rpc:XQr/200/ffffffff rc 0/-1 job:'ln.0' uid:0 gid:0 projid:4294967295 [10411.530626] Lustre: lustre-MDT0000-mdc-ffff9efb7d35f800: Connection to lustre-MDT0000 (at 192.168.201.151@tcp) was lost; in progress operations using this service will wait for recovery to complete [10411.572623] Lustre: lustre-MDT0000-mdc-ffff9efb7d35f800: Connection restored to 192.168.201.151@tcp (at 192.168.201.151@tcp) [10426.847170] Lustre: 358456:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788340130/real 1788340130] req@ffff9efb791e5880 x1875210497175168/t0(0) o36->lustre-MDT0000-mdc-ffff9efb7d35f800@192.168.201.151@tcp:12/10 lens 496/440 e 0 to 1 dl 1788340146 ref 2 fl Rpc:XQr/202/ffffffff rc 0/-1 job:'ln.0' uid:0 gid:0 projid:4294967295 [10426.888615] Lustre: lustre-MDT0000-mdc-ffff9efb7d35f800: Connection to lustre-MDT0000 (at 192.168.201.151@tcp) was lost; in progress operations using this service will wait for recovery to complete [10426.942767] Lustre: lustre-MDT0000-mdc-ffff9efb7d35f800: Connection restored to 192.168.201.151@tcp (at 192.168.201.151@tcp) [10443.232842] Lustre: 358456:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788340146/real 1788340146] req@ffff9efb791e5880 x1875210497175168/t0(0) o36->lustre-MDT0000-mdc-ffff9efb7d35f800@192.168.201.151@tcp:12/10 lens 496/440 e 0 to 1 dl 1788340162 ref 2 fl Rpc:XQr/202/ffffffff rc 0/-1 job:'ln.0' uid:0 gid:0 projid:4294967295 [10443.269518] Lustre: lustre-MDT0000-mdc-ffff9efb7d35f800: Connection to lustre-MDT0000 (at 192.168.201.151@tcp) was lost; in progress operations using this service will wait for recovery to complete [10443.302241] Lustre: lustre-MDT0000-mdc-ffff9efb7d35f800: Connection restored to 192.168.201.151@tcp (at 192.168.201.151@tcp) [10459.615188] Lustre: 358456:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788340162/real 1788340162] req@ffff9efb791e5880 x1875210497175168/t0(0) o36->lustre-MDT0000-mdc-ffff9efb7d35f800@192.168.201.151@tcp:12/10 lens 496/440 e 0 to 1 dl 1788340178 ref 2 fl Rpc:XQr/202/ffffffff rc 0/-1 job:'ln.0' uid:0 gid:0 projid:4294967295 [10459.651690] Lustre: lustre-MDT0000-mdc-ffff9efb7d35f800: Connection to lustre-MDT0000 (at 192.168.201.151@tcp) was lost; in progress operations using this service will wait for recovery to complete [10459.689427] Lustre: lustre-MDT0000-mdc-ffff9efb7d35f800: Connection restored to 192.168.201.151@tcp (at 192.168.201.151@tcp) [10466.001071] Lustre: DEBUG MARKER: == sanityn test 111: A racy rename/link an open file should not cause fs corruption ========================================================== 05:09:43 (1788340183) [10478.176560] Lustre: DEBUG MARKER: == sanityn test 112: update max-inherit in default LMV === 05:09:56 (1788340196) [10489.474855] Lustre: DEBUG MARKER: == sanityn test 113: check servers of specified fs ======= 05:10:07 (1788340207) [10495.999312] Lustre: DEBUG MARKER: == sanityn test 114: implicit default LMV inherit ======== 05:10:13 (1788340213) [10519.274862] Lustre: DEBUG MARKER: == sanityn test 115: ldiskfs doesn't check direntry for uniqueness ========================================================== 05:10:36 (1788340236) [10554.030173] Lustre: DEBUG MARKER: == sanityn test 116: DNE: Set default LMV layout from a remote client ========================================================== 05:11:11 (1788340271) [10561.841370] Lustre: DEBUG MARKER: == sanityn test 121: trunc append race =================== 05:11:19 (1788340279) [10562.112064] LustreError: 363239:0:(lcommon_cl.c:99:cl_setattr_ost()) cfs_fail_timeout id 1436 sleeping for 2000ms [10564.205589] LustreError: 363239:0:(lcommon_cl.c:99:cl_setattr_ost()) cfs_fail_timeout id 1436 awake [10571.784883] Lustre: DEBUG MARKER: == sanityn test 122: directory size is consistent across mounts ========================================================== 05:11:29 (1788340289) [10587.434146] Lustre: DEBUG MARKER: == sanityn test 200: service remains healthy while able to process request ========================================================== 05:11:45 (1788340305) [10608.991531] Lustre: 357305:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788340312/real 1788340312] req@ffff9efb71ef4000 x1875210498240128/t0(0) o4->lustre-OST0000-osc-ffff9efb7d35f800@192.168.201.151@tcp:6/4 lens 4584/448 e 0 to 1 dl 1788340328 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'dd.0' uid:0 gid:0 projid:0 [10609.028849] Lustre: lustre-OST0000-osc-ffff9efb7d35f800: Connection to lustre-OST0000 (at 192.168.201.151@tcp) was lost; in progress operations using this service will wait for recovery to complete [10609.073683] Lustre: lustre-OST0000-osc-ffff9efb7d35f800: Connection restored to 192.168.201.151@tcp (at 192.168.201.151@tcp) [10625.503739] Lustre: 357307:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788340328/real 1788340328] req@ffff9efb4fd6fb80 x1875210498239488/t0(0) o4->lustre-OST0000-osc-ffff9efb7d35f800@192.168.201.151@tcp:6/4 lens 4584/448 e 0 to 1 dl 1788340344 ref 2 fl Rpc:XQr/602/ffffffff rc -11/-1 job:'dd.0' uid:0 gid:0 projid:0 [10625.504744] Lustre: lustre-OST0000-osc-ffff9efb7d35f800: Connection to lustre-OST0000 (at 192.168.201.151@tcp) was lost; in progress operations using this service will wait for recovery to complete [10625.534959] Lustre: 357307:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 4 previous similar messages [10625.601750] Lustre: lustre-OST0000-osc-ffff9efb7d35f800: Connection restored to 192.168.201.151@tcp (at 192.168.201.151@tcp) [10657.247282] Lustre: 357307:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788340360/real 1788340360] req@ffff9efb4fd6fb80 x1875210498239488/t0(0) o4->lustre-OST0000-osc-ffff9efb7d35f800@192.168.201.151@tcp:6/4 lens 4584/448 e 0 to 1 dl 1788340376 ref 2 fl Rpc:XQr/602/ffffffff rc -11/-1 job:'dd.0' uid:0 gid:0 projid:0 [10657.271042] Lustre: 357307:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 9 previous similar messages [10657.281663] Lustre: lustre-OST0000-osc-ffff9efb7d35f800: Connection to lustre-OST0000 (at 192.168.201.151@tcp) was lost; in progress operations using this service will wait for recovery to complete [10657.302817] Lustre: Skipped 1 previous similar message [10657.337781] Lustre: lustre-OST0000-osc-ffff9efb7d35f800: Connection restored to 192.168.201.151@tcp (at 192.168.201.151@tcp) [10657.345182] Lustre: Skipped 1 previous similar message [10690.241981] Lustre: DEBUG MARKER: oleg151-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0000-osc-ffff9efb42e85800.ost_server_uuid 50 [10691.806500] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9efb42e85800.ost_server_uuid in IDLE state after 0 sec [10693.680032] Lustre: DEBUG MARKER: cleanup: ====================================================== [10695.590503] Lustre: DEBUG MARKER: == sanityn test complete, duration 10396 sec ============= 05:13:33 (1788340413) [10697.198575] Lustre: DEBUG MARKER: === sanityn: start cleanup 05:13:35 (1788340415) === [10948.322522] Lustre: Unmounted lustre-client [10952.082619] Lustre: DEBUG MARKER: === sanityn: finish cleanup 05:17:50 (1788340670) === [10953.924089] Lustre: Unmounted lustre-client [11011.123457] Key type lgssc unregistered [11011.349821] LNet: 367318:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [11011.357160] LNetError: 367318:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [11011.376871] LNet: Removed LNI 192.168.201.51@tcp [11011.998289] Key type .llcrypt unregistered [11012.004087] Key type ._llcrypt unregistered