[ 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 451453033 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.001012] APIC: Switch to symmetric I/O mode setup [ 0.002391] x2apic enabled [ 0.003008] Switched APIC routing to physical x2apic. [ 0.004013] kvm-guest: setup PV IPIs [ 0.007327] ..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.008023] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.009011] pid_max: default: 32768 minimum: 301 [ 0.011007] LSM: Security Framework initializing [ 0.012056] Yama: becoming mindful. [ 0.013047] SELinux: Initializing. [ 0.014000] *** VALIDATE selinux *** [ 0.022056] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.027516] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.028175] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.029166] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.030213] *** VALIDATE tmpfs *** [ 0.032467] *** VALIDATE proc *** [ 0.034299] *** VALIDATE cgroup *** [ 0.035020] *** VALIDATE cgroup2 *** [ 0.036334] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.038201] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.039012] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.040032] Spectre V2 : User space: Vulnerable [ 0.041010] Speculative Store Bypass: Vulnerable [ 0.044163] debug: unmapping init [mem 0xffffffff86859000-0xffffffff86860fff] [ 0.046998] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.047739] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.048025] ... version: 2 [ 0.049014] ... bit width: 48 [ 0.050012] ... generic registers: 4 [ 0.051013] ... value mask: 0000ffffffffffff [ 0.052014] ... max period: 00007fffffffffff [ 0.053011] ... fixed-purpose events: 3 [ 0.054015] ... event mask: 000000070000000f [ 0.055356] rcu: Hierarchical SRCU implementation. [ 0.057460] smp: Bringing up secondary CPUs ... [ 0.058528] x86: Booting SMP configuration: [ 0.059026] .... node #0, CPUs: #1 #2 #3 [ 0.062643] smp: Brought up 1 node, 4 CPUs [ 0.064011] smpboot: Max logical packages: 1 [ 0.065016] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.109852] node 0 deferred pages initialised in 41ms [ 0.111103] devtmpfs: initialized [ 0.113232] x86/mm: Memory block size: 128MB [ 0.116000] gcov: version magic: 0x41383552 [ 0.119425] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.123098] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.125359] pinctrl core: initialized pinctrl subsystem [ 0.127196] [ 0.127836] ************************************************************* [ 0.130012] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.133012] ** ** [ 0.135011] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.137012] ** ** [ 0.139010] ** This means that this kernel is built to expose internal ** [ 0.141052] ** IOMMU data structures, which may compromise security on ** [ 0.143013] ** your system. ** [ 0.145046] ** ** [ 0.148015] ** If you see this message and you are not debugging the ** [ 0.150017] ** kernel, report this immediately to your vendor! ** [ 0.153050] ** ** [ 0.155012] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.157046] ************************************************************* [ 0.160515] NET: Registered protocol family 16 [ 0.162585] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.165067] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.168066] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.172028] cpuidle: using governor menu [ 0.173732] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.176461] PCI: Using configuration type 1 for base access [ 0.178117] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.187200] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.191074] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.194212] cryptd: max_cpu_qlen set to 1000 [ 0.197649] ACPI: Added _OSI(Module Device) [ 0.199014] ACPI: Added _OSI(Processor Device) [ 0.201012] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.202013] ACPI: Added _OSI(Processor Aggregator Device) [ 0.207258] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.213492] ACPI: Interpreter enabled [ 0.214057] ACPI: PM: (supports S0 S3 S4 S5) [ 0.216012] ACPI: Using IOAPIC for interrupt routing [ 0.218105] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.222484] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.233496] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.236043] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.239021] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.242077] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.247000] acpiphp: Slot [2] registered [ 0.247000] acpiphp: Slot [5] registered [ 0.249139] acpiphp: Slot [6] registered [ 0.251084] acpiphp: Slot [3] registered [ 0.253092] acpiphp: Slot [4] registered [ 0.254078] acpiphp: Slot [7] registered [ 0.256105] acpiphp: Slot [8] registered [ 0.257139] acpiphp: Slot [9] registered [ 0.259110] acpiphp: Slot [10] registered [ 0.261113] acpiphp: Slot [11] registered [ 0.263083] acpiphp: Slot [12] registered [ 0.264125] acpiphp: Slot [13] registered [ 0.265151] acpiphp: Slot [14] registered [ 0.266081] acpiphp: Slot [15] registered [ 0.267062] acpiphp: Slot [16] registered [ 0.269060] acpiphp: Slot [17] registered [ 0.270058] acpiphp: Slot [18] registered [ 0.271054] acpiphp: Slot [19] registered [ 0.272065] acpiphp: Slot [20] registered [ 0.273055] acpiphp: Slot [21] registered [ 0.273978] acpiphp: Slot [22] registered [ 0.274060] acpiphp: Slot [23] registered [ 0.276091] acpiphp: Slot [24] registered [ 0.277092] acpiphp: Slot [25] registered [ 0.278073] acpiphp: Slot [26] registered [ 0.279053] acpiphp: Slot [27] registered [ 0.280054] acpiphp: Slot [28] registered [ 0.281059] acpiphp: Slot [29] registered [ 0.282428] acpiphp: Slot [30] registered [ 0.284263] acpiphp: Slot [31] registered [ 0.286058] PCI host bridge to bus 0000:00 [ 0.288020] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.290026] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.293035] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.296024] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.298100] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.301025] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.303236] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.306099] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.309283] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.317015] pci 0000:00:01.1: reg 0x20: [io 0xc120-0xc12f] [ 0.322063] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.325039] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.328021] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.330021] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.333533] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.336823] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.340048] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.343855] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.349018] pci 0000:00:02.0: reg 0x10: [io 0xc100-0xc11f] [ 0.362014] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.366014] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.372093] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.378015] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.384017] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.393013] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.400092] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.403012] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.406890] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.417018] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.423679] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.425404] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.428301] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.430346] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.432144] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.435038] iommu: Default domain type: Passthrough [ 0.437348] SCSI subsystem initialized [ 0.439093] ACPI: bus type USB registered [ 0.440064] usbcore: registered new interface driver usbfs [ 0.441076] usbcore: registered new interface driver hub [ 0.443084] usbcore: registered new device driver usb [ 0.444086] pps_core: LinuxPPS API ver. 1 registered [ 0.445007] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.447086] PTP clock support registered [ 0.449094] EDAC MC: Ver: 3.0.0 [ 0.450235] PCI: Using ACPI for IRQ routing [ 0.451562] NetLabel: Initializing [ 0.452010] NetLabel: domain hash size = 128 [ 0.452825] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.453064] NetLabel: unlabeled traffic allowed by default [ 0.454147] vgaarb: loaded [ 0.455337] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.457014] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.463918] clocksource: Switched to clocksource kvm-clock [ 0.568745] VFS: Disk quotas dquot_6.6.0 [ 0.570421] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.573054] *** VALIDATE ramfs *** [ 0.574462] *** VALIDATE hugetlbfs *** [ 0.576866] pnp: PnP ACPI init [ 0.579423] pnp: PnP ACPI: found 6 devices [ 0.597344] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.600785] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.602919] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.605186] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.607827] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.610483] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.613673] NET: Registered protocol family 2 [ 0.616753] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.622309] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.626761] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.632617] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.636820] TCP: Hash tables configured (established 65536 bind 65536) [ 0.640440] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.644594] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.647728] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.651713] NET: Registered protocol family 1 [ 0.654681] RPC: Registered named UNIX socket transport module. [ 0.657461] RPC: Registered udp transport module. [ 0.659571] RPC: Registered tcp transport module. [ 0.661811] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.664614] NET: Registered protocol family 44 [ 0.666954] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.669026] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.671190] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.673131] PCI: CLS 0 bytes, default 64 [ 0.675087] Unpacking initramfs... [ 2.144114] debug: unmapping init [mem 0xffff9758bcc64000-0xffff9758bffcffff] [ 2.146915] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.148339] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.150482] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 2.662404] Initialise system trusted keyrings [ 2.663636] Key type blacklist registered [ 2.664976] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.675378] zbud: loaded [ 2.678410] *** VALIDATE nfs *** [ 2.679649] *** VALIDATE nfs4 *** [ 2.681522] pstore: using deflate compression [ 2.685706] Platform Keyring initialized [ 2.790807] NET: Registered protocol family 38 [ 2.792954] Key type asymmetric registered [ 2.795273] Asymmetric key parser 'x509' registered [ 2.797678] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 2.801989] io scheduler mq-deadline registered [ 2.804118] io scheduler kyber registered [ 2.806172] io scheduler bfq registered [ 2.808404] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 2.812583] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 2.816278] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 2.819577] ACPI: Power Button [PWRF] [ 2.825510] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 2.832252] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 2.843759] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 2.870367] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 2.899105] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 2.904182] Non-volatile memory driver v1.3 [ 2.906547] Linux agpgart interface v0.103 [ 2.947082] virtio_blk virtio1: [vda] 149952 512-byte logical blocks (76.8 MB/73.2 MiB) [ 2.950273] vda: detected capacity change from 0 to 76775424 [ 2.966438] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 2.969839] vdb: detected capacity change from 0 to 1073741824 [ 2.975918] libphy: Fixed MDIO Bus: probed [ 2.984548] usbcore: registered new interface driver usbserial_generic [ 2.987705] usbserial: USB Serial support registered for generic [ 2.990976] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 2.995470] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 2.997446] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.000277] mousedev: PS/2 mouse device common for all mice [ 3.003573] rtc_cmos 00:05: RTC can wake from S4 [ 3.004751] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.007762] rtc_cmos 00:05: registered as rtc0 [ 3.012438] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.012448] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.017653] intel_pstate: CPU model not supported [ 3.018833] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.024138] hid: raw HID events driver (C) Jiri Kosina [ 3.026369] usbcore: registered new interface driver usbhid [ 3.028521] usbhid: USB HID core driver [ 3.030173] drop_monitor: Initializing network drop monitor service [ 3.032613] Initializing XFRM netlink socket [ 3.034787] NET: Registered protocol family 10 [ 3.037726] Segment Routing with IPv6 [ 3.039173] NET: Registered protocol family 17 [ 3.041427] mpls_gso: MPLS GSO support [ 3.046693] RAS: Correctable Errors collector initialized. [ 3.048851] AVX version of gcm_enc/dec engaged. [ 3.050792] AES CTR mode by8 optimization enabled [ 3.132453] sched_clock: Marking stable (3132421416, 0)->(3993335316, -860913900) [ 3.136256] registered taskstats version 1 [ 3.138561] Loading compiled-in X.509 certificates [ 3.140647] zswap: loaded using pool lzo/zbud [ 3.167678] Key type big_key registered [ 3.180844] Key type encrypted registered [ 3.182156] ima: No TPM chip found, activating TPM-bypass! [ 3.183574] ima: Allocated hash algorithm: sha1 [ 3.184813] ima: No architecture policies found [ 3.186120] evm: Initialising EVM extended attributes: [ 3.187436] evm: security.selinux [ 3.188822] evm: security.ima [ 3.190086] evm: security.capability [ 3.191721] evm: HMAC attrs: 0x1 [ 3.194121] rtc_cmos 00:05: setting system clock to 2026-09-12 02:43:59 UTC (1789181039) [ 3.201578] debug: unmapping init [mem 0xffffffff87803000-0xffffffff879fffff] [ 3.205350] debug: unmapping init [mem 0xffffffff86582000-0xffffffff86858fff] [ 3.217141] Write protecting the kernel read-only data: 28672k [ 3.219824] debug: unmapping init [mem 0xffffffff84c03000-0xffffffff84dfffff] [ 3.222237] debug: unmapping init [mem 0xffffffff85514000-0xffffffff855fffff] [ 3.258352] 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.268517] systemd[1]: Detected virtualization kvm. [ 3.270990] systemd[1]: Detected architecture x86-64. [ 3.273402] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.296365] systemd[1]: No hostname configured. [ 3.298251] systemd[1]: Set hostname to . [ 3.300607] random: systemd: uninitialized urandom read (16 bytes read) [ 3.303208] systemd[1]: Initializing machine ID from random generator. [ 3.461655] random: systemd: uninitialized urandom read (16 bytes read) [ 3.464570] systemd[1]: Reached target Swap. [ OK ] Reached target Swap. [ 3.469301] random: systemd: uninitialized urandom read (16 bytes read) [ 3.471771] systemd[1]: Reached target Initrd Root Device. [ OK ] Reached target Initrd Root Device. [ 3.478085] systemd[1]: Listening on Journal Socket (/dev/log). [ OK ] Listening on Journal Socket (/dev/log). [ OK ] Reached target Local File Systems. [ OK ] Listening on udev Control Socket. [ OK ] Reached target Slices. [ OK ] Listening on udev Kernel Socket. [ OK ] Listening on Journal Socket. [ OK ] Reached target Sockets. Starting Create Volatile Files and Directories... [ OK ] Started Memstrack Anylazing Service. Starting Setup Virtual Console... Starting Apply Kernel Variables... Starting Create list of required st…ce nodes for the current kernel... Starting Journal Service... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. [ OK ] Reached target Timers. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Setup Virtual Console. [ OK ] Started Apply Kernel Variables. [ OK ] Started Create list of required sta…vice nodes for the current kernel. Starting Create Static Device Nodes in /dev... Starting dracut cmdline hook... [ OK ] Started Journal Service. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 4.214559] device-mapper: uevent: version 1.0.3 [ 4.216610] 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. [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting dracut initqueue hook... [ 4.958718] virtio_net virtio0 ens2: renamed from eth0 [ 4.968667] random: fast init done [ 5.015512] scsi host0: ata_piix [ 5.073198] scsi host1: ata_piix [ 5.074891] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc120 irq 14 [ 5.079399] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc128 irq 15 [ 8.859338] dracut-initqueue[581]: RTNETLINK answers: File exists [ 9.698153] random: crng init done [ 9.701944] random: 7 urandom warning(s) missed due to ratelimiting Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. Mounting /sysroot... [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. [ 10.411741] 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... Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Timers. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Paths. [ OK ] Stopped target Slices. [ OK ] Stopped target Sockets. [ OK ] Stopped target System Initialization. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. [ OK ] Stopped target Swap. Stopping udev Kernel Device Manager... [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped udev Kernel Device Manager. [ 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... [ 12.057670] printk: systemd: 25 output lines suppressed due to ratelimiting [ 12.298983] SELinux: Disabled at runtime. [ 12.356234] 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) [ 12.365262] systemd[1]: Detected virtualization kvm. [ 12.367198] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 12.920131] systemd[1]: initrd-switch-root.service: Succeeded. [ 12.924322] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 12.932639] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 12.936636] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 12.940018] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 12.947322] systemd[1]: Starting Journal Service... Starting Journal Service... [ 12.954153] systemd[1]: Activating swap /dev/disk/by-label/SWAP... Activating swap /dev/disk/by-label/SWAP... [ 13.138300] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Created slice system-getty.slice. Mounting Kernel Debug File System... [ OK ] Listening on udev Control Socket. [ OK ] Listening on Process Core Dump Socket. [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd Root File System. [ OK ] Reached target rpc_pipefs.target. Mounting POSIX Message Queue File System... [ OK ] Stopped target Initrd File Systems. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Created slice User and Session Slice. [ OK ] Reached target Slices. [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Started Forward Password Requests to Wall Directory Watch. Mounting Huge Pages File System... Starting Remount Root and Kernel File Systems... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. [ OK ] Listening on udev Kernel Socket. Starting udev Coldplug all Devices... [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Reached target RPC Port Mapper. Starting Apply Kernel Variables... [ OK ] Started Journal Service. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Mounted Kernel Debug File System. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Mounted Huge Pages File System. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Started Apply Kernel Variables. Starting Configure read-only root support... Starting Create Static Device Nodes in /dev... [ OK ] Reached target Swap. Starting Flush Journal to Persistent Storage... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Reached target Local File Systems (Pre). Mounting /home/green/git/lustre-release... Mounting /mnt... Starting udev Kernel Device Manager... [ OK ] Mounted /mnt. [ OK ] Started udev Coldplug all Devices. [ 13.920322] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 14.376420] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 14.402062] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 14.817229] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 14.847131] EDAC sbridge: Ver: 1.1.2 [ 16.169626] Key type dns_resolver registered [ 16.489557] NFS: Registering the id_resolver key type [ 16.491697] Key type id_resolver registered [ 16.493400] Key type id_legacy registered [ OK ] Started Configure read-only root support. [ OK ] Reached target Local File Systems. Starting Mark the need to relabel after reboot... Starting Create Volatile Files and Directories... Starting Rebuild Dynamic Linker Cache... Starting Load/Save Random Seed... [ 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 dnf makecache --timer. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Reached target Timers. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. [ OK ] Started irqbalance daemon. [ OK ] Started D-Bus System Message Bus. Starting Restore /run/initramfs on shutdown... [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting Network Manager... Starting Login Service... [ 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 Dynamic System Tuning Daemon... Starting GSSAPI Proxy Daemon... Starting OpenSSH server daemon... [ OK ] Started Login Service. Starting Hostname Service... [ OK ] Started GSSAPI Proxy Daemon. [ 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 Command Scheduler. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Serial Getty on ttyS1. [ OK ] Started Getty on tty1. [ OK ] Reached target Login Prompts. [ 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. Starting Authorization Manager... [ OK ] Started Authorization Manager. [ OK ] Started Dynamic System Tuning Daemon. [ OK ] Reached target Multi-User System. [ OK ] Reached target Graphical Interface. Starting Update UTMP about System Runlevel Changes... [ OK ] Started Update UTMP about System Runlevel Changes. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg236-client login: [ 68.563316] libcfs: loading out-of-tree module taints kernel. [ 68.637456] Key type ._llcrypt registered [ 68.640166] Key type .llcrypt registered [ 69.141675] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [ 69.152556] alg: No test for adler32 (adler32-zlib) [ 70.594422] Lustre: Lustre: Build Version: 2.17.58_39_g3d58bdf [ 71.291754] LNet: Added LNI 192.168.202.36@tcp [8/256/0/180] [ 73.079253] Key type lgssc registered [ 75.741975] Lustre: Echo OBD driver; http://www.lustre.org/ [ 137.942247] hrtimer: interrupt took 6484145 ns [ 260.035213] Lustre: Mounted lustre-client - version 2.17.58_39_g3d58bdf [ 265.581326] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 283.174519] Lustre: DEBUG MARKER: oleg236-client.virtnet: executing check_logdir /tmp/testlogs/ [ 285.671247] Lustre: lustre-OST0000-osc-ffff97591224c000: disconnect after 23s idle [ 288.488948] Lustre: DEBUG MARKER: oleg236-client.virtnet: executing yml_node [ 292.404657] Lustre: DEBUG MARKER: Client: 2.17.58.39 [ 295.527895] Lustre: DEBUG MARKER: MDS: 2.17.58.39 [ 297.749795] Lustre: DEBUG MARKER: OSS: 2.17.58.39 [ 299.490942] Lustre: DEBUG MARKER: -----============= acceptance-small: sanityn ============----- Fri Sep 11 22:48:54 EDT 2026 [ 316.565261] Lustre: DEBUG MARKER: excepting tests: 27 40a [ 318.448675] Lustre: DEBUG MARKER: skipping tests SLOW=no: 33a [ 320.106149] Lustre: DEBUG MARKER: === sanityn: start setup 22:49:14 (1789181354) === [ 320.837244] Lustre: Mounted lustre-client - version 2.17.58_39_g3d58bdf [ 328.293410] Lustre: DEBUG MARKER: oleg236-client.virtnet: executing check_config_client /mnt/lustre [ 348.206621] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 365.513355] Lustre: DEBUG MARKER: === sanityn: finish setup 22:49:59 (1789181399) === [ 368.381937] Lustre: DEBUG MARKER: == sanityn test 0: do_node_vp() and do_facet_vp() do the right thing ========================================================== 22:50:03 (1789181403) [ 377.370651] Lustre: DEBUG MARKER: == sanityn test 1: Check attribute updates on 2 mount points ========================================================== 22:50:12 (1789181412) [ 384.768259] Lustre: DEBUG MARKER: == sanityn test 2a: check cached attribute updates on 2 mtpt's ================================================================== 22:50:19 (1789181419) [ 391.755447] Lustre: DEBUG MARKER: == sanityn test 2b: check cached attribute updates on 2 mtpt's ================================================================== 22:50:26 (1789181426) [ 398.056135] Lustre: DEBUG MARKER: == sanityn test 2c: check cached attribute updates on 2 mtpt's root ============================================================= 22:50:33 (1789181433) [ 404.094664] Lustre: DEBUG MARKER: == sanityn test 2d: check cached attribute updates on 2 mtpt's root ============================================================= 22:50:39 (1789181439) [ 411.255664] Lustre: DEBUG MARKER: == sanityn test 2e: check chmod on root is propagated to others ========================================================== 22:50:46 (1789181446) [ 419.229474] Lustre: DEBUG MARKER: == sanityn test 2f: check attr/owner updates on DNE with 2 mtpt's ========================================================== 22:50:54 (1789181454) [ 427.142751] Lustre: DEBUG MARKER: == sanityn test 2g: check blocks update on sync write ==== 22:51:02 (1789181462) [ 433.427063] Lustre: DEBUG MARKER: == sanityn test 3: symlink on one mtpt, readlink on another ===================================================================== 22:51:08 (1789181468) [ 439.453344] Lustre: DEBUG MARKER: == sanityn test 4: fstat validation on multiple mount points ==================================================================== 22:51:14 (1789181474) [ 447.302376] Lustre: DEBUG MARKER: == sanityn test 5: create a file on one mount, truncate it on the other ========================================================== 22:51:21 (1789181481) [ 449.003624] Lustre: lustre-OST0001-osc-ffff97591224c000: disconnect after 22s idle [ 449.015202] Lustre: Skipped 1 previous similar message [ 453.362788] Lustre: DEBUG MARKER: == sanityn test 6: remove of open file on other node ============================================================================ 22:51:27 (1789181487) [ 460.532639] Lustre: DEBUG MARKER: == sanityn test 7: remove of open directory on other node ======================================================================= 22:51:35 (1789181495) [ 464.351193] Lustre: lustre-OST0000-osc-ffff9759202f0000: disconnect after 23s idle [ 467.263745] Lustre: DEBUG MARKER: == sanityn test 8: remove of open special file on other node ==================================================================== 22:51:42 (1789181502) [ 473.614422] Lustre: DEBUG MARKER: == sanityn test 9a: append of file with sub-page size on multiple mounts ========================================================== 22:51:48 (1789181508) [ 479.719455] Lustre: lustre-OST0001-osc-ffff97591224c000: disconnect after 21s idle [ 481.169967] Lustre: DEBUG MARKER: == sanityn test 9b: append to striped sparse file ======== 22:51:56 (1789181516) [ 488.176836] Lustre: DEBUG MARKER: == sanityn test 10a: write of file with sub-page size on multiple mounts ========================================================== 22:52:03 (1789181523) [ 495.757572] Lustre: DEBUG MARKER: == sanityn test 10b: write of file with sub-page size on multiple mounts ========================================================== 22:52:10 (1789181530) [ 502.863945] Lustre: DEBUG MARKER: == sanityn test 11: execution of file opened for write should return error ============================================================== 22:52:17 (1789181537) [ 510.356196] Lustre: DEBUG MARKER: == sanityn test 12: test lock ordering (link, stat, unlink) ========================================================== 22:52:25 (1789181545) [ 510.862453] Lustre: DEBUG MARKER: start dir: /mnt/lustre/lockdir=144115205289279518 file: /mnt/lustre/lockdir/lockfile=144115205289279517 [ 657.934364] Lustre: DEBUG MARKER: == sanityn test 13: test directory page revocation ======= 22:54:52 (1789181692) [ 667.877137] Lustre: DEBUG MARKER: == sanityn test 14aa: execution of file open for write returns -ETXTBSY ========================================================== 22:55:02 (1789181702) [ 675.121798] Lustre: DEBUG MARKER: == sanityn test 14ab: open(RDWR) of executing file returns -ETXTBSY ========================================================== 22:55:10 (1789181710) [ 683.806727] Lustre: DEBUG MARKER: == sanityn test 14b: truncate of executing file returns -ETXTBSY ================================================================ 22:55:18 (1789181718) [ 691.226512] Lustre: DEBUG MARKER: == sanityn test 14c: open(O_TRUNC) of executing file return -ETXTBSY ============================================================ 22:55:26 (1789181726) [ 700.244191] Lustre: DEBUG MARKER: == sanityn test 14d: chmod of executing file is still possible ================================================================== 22:55:34 (1789181734) [ 702.671301] Lustre: DEBUG MARKER: chmod [ 709.368794] Lustre: DEBUG MARKER: == sanityn test 15: test out-of-space with multiple writers ===================================================================== 22:55:44 (1789181744) [ 1689.036388] Lustre: DEBUG MARKER: == sanityn test 16a: 2500 iterations of dual-mount fsx === 23:12:04 (1789182724) [ 1821.663242] Lustre: lustre-OST0000-osc-ffff9759202f0000: disconnect after 24s idle [ 1874.764479] Lustre: DEBUG MARKER: == sanityn test 16b: 2500 iterations of dual-mount fsx at small size ========================================================== 23:15:09 (1789182909) [ 1966.535110] Lustre: DEBUG MARKER: == sanityn test 16c: verify data consistency on ldiskfs with cache disabled (b=17397) ========================================================== 23:16:41 (1789183001) [ 2097.739429] Lustre: DEBUG MARKER: == sanityn test 16d: Verify DIO and buffer IO with two clients ========================================================== 23:18:52 (1789183132) [ 2133.989983] Lustre: lustre-OST0001-osc-ffff9759202f0000: disconnect after 21s idle [ 2134.484649] Lustre: DEBUG MARKER: == sanityn test 16e: Verify size consistency for O_DIRECT write ========================================================== 23:19:29 (1789183169) [ 2141.562242] Lustre: DEBUG MARKER: == sanityn test 16f: rw sequential consistency vs drop_caches ========================================================== 23:19:36 (1789183176) [ 2142.596358] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2142.666593] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2142.751245] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2142.824255] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2142.875429] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2142.964212] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2143.019745] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2143.088096] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2143.144322] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2143.230694] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2143.313736] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2143.383390] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2143.449589] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2143.517894] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2143.566899] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2143.624495] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2143.686826] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2143.753253] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2143.825955] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2143.894920] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2143.973071] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2144.045089] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2144.122266] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2144.191737] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2144.258731] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2144.337875] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2144.401268] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2144.443854] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2144.490890] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2144.558592] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2144.612141] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2144.686381] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2144.780044] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2144.877879] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2144.939976] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2144.998287] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2145.065912] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2145.129644] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2145.192465] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2145.255895] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2145.327028] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2145.408897] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2145.471085] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2145.527338] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2145.580674] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2145.639380] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2145.702973] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2145.760445] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2145.816620] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2145.873394] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2145.935325] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2146.004726] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2146.077879] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2146.155138] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2146.207714] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2146.277142] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2146.336875] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2146.412528] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2146.505252] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2146.553980] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2146.605750] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2146.654312] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2146.716540] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2146.774743] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2146.864333] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2146.940328] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2147.024457] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2147.100570] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2147.171927] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2147.242544] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2147.313455] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2147.385132] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2147.464817] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2147.537604] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2147.628730] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2147.707110] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2147.760939] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2147.826885] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2147.884334] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2147.954599] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2148.040817] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2148.120722] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2148.184329] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2148.245668] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2148.317809] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2148.391197] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2148.463041] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2148.553840] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2148.624702] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2148.683950] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2148.747834] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2148.822497] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2148.890182] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2148.949896] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2149.013247] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2149.088947] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2149.151722] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2149.205430] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2149.268576] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2149.334679] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2149.404476] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2149.464989] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2149.520044] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2149.588887] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2149.648050] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2149.741946] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2149.813095] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2149.875850] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2149.941749] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2150.012697] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2150.089859] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2150.178730] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2150.258207] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2150.336739] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2150.417301] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2150.476425] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2150.523444] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2150.583427] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2150.640595] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2150.705918] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2150.769100] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2150.852678] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2150.957529] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2151.033525] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2151.114812] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2151.184529] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2151.266609] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2151.329027] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2151.382307] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2151.446614] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2151.520264] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2151.577957] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2151.633120] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2151.698571] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2151.768889] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2151.837026] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2151.901473] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2151.995418] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2152.071556] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2152.197044] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2152.303361] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2152.418207] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2152.502071] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2152.573766] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2152.639326] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2152.725676] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2152.799520] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2152.869745] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2152.951762] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2153.023653] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2153.099242] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2153.163459] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2153.242895] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2153.309584] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2153.400463] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2153.463671] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2153.524738] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2153.586439] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2153.640966] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2153.707897] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2153.782925] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2153.850344] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2153.914607] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2153.977142] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2154.024291] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2154.075987] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2154.141769] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2154.184261] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2154.240763] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2154.315465] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2154.370251] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2154.434369] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2154.501514] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2154.572806] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2154.642645] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2154.709993] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2154.780974] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2154.852934] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2154.906519] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2154.990677] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2155.075142] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2155.145059] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2155.199597] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2155.258478] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2155.318297] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2155.414864] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2155.477859] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2155.552664] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2155.644948] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2155.716897] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2155.780519] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2155.839175] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2155.898663] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2155.985513] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2156.064938] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2156.152462] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2156.224341] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2156.281196] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2156.321960] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2156.378350] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2156.429780] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2156.492386] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2156.540749] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2156.602496] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2156.652533] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2156.714383] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2156.796401] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2156.869532] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2156.921819] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2156.975813] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2157.078460] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2157.159288] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2157.222659] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2157.298187] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2157.374215] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2157.445133] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2157.513249] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2157.571255] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2157.652727] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2157.738775] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2157.797691] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2157.871631] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2157.950715] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2158.029827] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2158.103571] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2158.179746] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2158.273379] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2158.363838] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2158.445808] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2158.531314] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2158.667927] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2158.754457] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2158.837053] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2158.905849] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2158.971403] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2159.056980] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2159.121411] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2159.201629] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2159.276196] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2159.350978] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2159.437228] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2159.513205] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2159.577906] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2159.583233] Lustre: lustre-OST0000-osc-ffff97591224c000: disconnect after 22s idle [ 2159.656477] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2159.720926] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2159.820550] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2159.899488] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2159.974745] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2160.027968] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2160.093211] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2160.162187] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2160.239174] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2160.309977] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2160.370623] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2160.451964] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2160.507863] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2160.592516] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2160.674436] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2160.770161] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2160.841149] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2160.907136] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2161.008715] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2161.075475] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2161.134470] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2161.196305] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2161.251661] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2161.315973] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2161.402713] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2161.479331] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2161.560897] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2161.645599] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2161.720257] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2161.764488] rw_seq_cst_vs_d (32508): drop_caches: 3 [ 2169.861857] Lustre: DEBUG MARKER: == sanityn test 16g: mmap rw sequential consistency vs drop_caches ========================================================== 23:20:04 (1789183204) [ 2170.308604] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2170.466535] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2170.565686] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2170.736035] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2170.925044] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2170.972886] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2171.081158] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2171.522692] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2171.559126] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2171.622152] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2171.747580] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2171.799430] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2171.908373] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2171.987026] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2172.103393] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2172.214118] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2172.260847] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2172.540210] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2172.672430] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2172.769517] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2172.956595] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2173.095329] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2173.226585] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2173.334448] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2173.524098] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2173.688529] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2173.765164] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2173.803538] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2173.840415] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2173.884925] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2173.944820] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2173.980473] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2174.067454] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2174.130984] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2174.193518] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2174.238719] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2174.391720] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2174.611595] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2174.679310] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2174.725694] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2174.939276] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2175.003992] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2175.163506] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2175.345376] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2175.482517] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2175.554930] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2175.775757] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2175.831775] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2175.945732] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2176.025264] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2176.156303] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2176.280349] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2176.338550] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2176.389788] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2176.775751] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2176.866598] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2176.931729] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2176.980850] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2177.049729] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2177.093874] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2177.127235] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2177.226400] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2177.267320] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2177.303395] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2177.450362] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2177.562911] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2177.699579] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2177.769787] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2177.948256] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2178.097185] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2178.198167] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2178.264113] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2178.413960] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2178.625530] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2178.686511] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2178.835215] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2179.069770] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2179.182953] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2179.261313] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2179.383716] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2179.475409] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2179.581615] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2179.717692] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2179.904598] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2179.966315] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2180.056238] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2180.142726] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2180.275760] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2180.424471] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2180.546454] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2180.749304] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2180.829237] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2180.934574] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2180.980537] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2181.142706] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2181.234953] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2181.294462] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2181.357676] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2181.423559] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2181.486173] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2181.610473] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2181.721683] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2181.799067] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2181.959322] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2182.075947] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2182.217584] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2182.346725] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2182.533664] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2182.634423] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2182.683919] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2182.752051] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2182.796373] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2182.936366] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2183.112794] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2183.287565] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2183.764022] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2184.037194] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2184.145500] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2184.256626] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2184.338300] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2184.411780] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2184.529851] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2184.613333] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2184.868231] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2184.943598] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2185.004746] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2185.047946] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2185.086187] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2185.149747] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2185.183258] Lustre: lustre-OST0001-osc-ffff9759202f0000: disconnect after 23s idle [ 2185.202071] Lustre: Skipped 1 previous similar message [ 2185.226651] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2185.456382] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2185.558536] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2185.626621] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2185.671598] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2185.709575] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2185.736366] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2185.843284] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2185.961859] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2186.068219] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2186.125505] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2186.199169] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2186.247043] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2186.372402] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2186.436359] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2186.666701] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2186.717913] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2186.938943] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2187.016554] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2187.210438] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2187.253409] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2187.369335] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2187.514578] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2187.701055] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2187.743690] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2187.881968] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2188.023926] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2188.137473] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2188.365561] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2188.601639] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2188.743647] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2188.875801] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2189.070954] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2189.242401] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2189.452235] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2189.510992] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2189.562172] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2189.608390] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2189.793840] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2189.852355] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2189.904164] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2189.958548] rw_seq_cst_vs_d (33084): drop_caches: 3 [ 2190.303484] Lustre: lustre-OST0001-osc-ffff97591224c000: disconnect after 23s idle [ 2197.283418] Lustre: DEBUG MARKER: == sanityn test 16h: mmap read after truncate file ======= 23:20:32 (1789183232) [ 2203.438465] Lustre: DEBUG MARKER: == sanityn test 16i: read after truncate file ============ 23:20:38 (1789183238) [ 2210.211249] Lustre: DEBUG MARKER: == sanityn test 16j: race dio with buffered i/o ========== 23:20:45 (1789183245) [ 2237.500573] Lustre: DEBUG MARKER: == sanityn test 16k: Parallel FSX and drop caches should not panic ========================================================== 23:21:11 (1789183271) [ 2238.243960] bash (35580): drop_caches: 3 [ 2241.624751] bash (35580): drop_caches: 3 [ 2244.774787] bash (35580): drop_caches: 3 [ 2247.934199] bash (35580): drop_caches: 3 [ 2251.144904] bash (35580): drop_caches: 3 [ 2254.259110] bash (35580): drop_caches: 3 [ 2257.372048] bash (35580): drop_caches: 3 [ 2260.473833] bash (35580): drop_caches: 3 [ 2264.084408] bash (35580): drop_caches: 3 [ 2267.321413] bash (35580): drop_caches: 3 [ 2270.655227] bash (35580): drop_caches: 3 [ 2273.805177] bash (35580): drop_caches: 3 [ 2276.905782] bash (35580): drop_caches: 3 [ 2280.140153] bash (35580): drop_caches: 3 [ 2285.154352] Lustre: DEBUG MARKER: == sanityn test 17: resource creation/LVB creation race ========================================================================= 23:21:59 (1789183319) [ 2295.362519] Lustre: DEBUG MARKER: == sanityn test 18: mmap sanity check =========================================================================================== 23:22:10 (1789183330) [ 2325.142702] Lustre: DEBUG MARKER: == sanityn test 19: test concurrent uncached read races ========================================================================= 23:22:39 (1789183359) [ 2333.663447] Lustre: lustre-OST0000-osc-ffff97591224c000: disconnect after 20s idle [ 2335.431534] Lustre: DEBUG MARKER: loop 5 [ 2342.741167] Lustre: DEBUG MARKER: loop 10 [ 2349.432340] Lustre: DEBUG MARKER: loop 15 [ 2357.399845] Lustre: DEBUG MARKER: loop 20 [ 2367.040942] Lustre: DEBUG MARKER: == sanityn test 20: test extra readahead page left in cache ============================================================== 23:23:21 (1789183401) [ 2376.468770] Lustre: DEBUG MARKER: == sanityn test 21: Try to remove mountpoint on another dir ============================================================== 23:23:31 (1789183411) [ 2384.866187] Lustre: lustre-OST0001-osc-ffff97591224c000: disconnect after 20s idle [ 2384.874951] Lustre: Skipped 1 previous similar message [ 2384.957927] Lustre: DEBUG MARKER: == sanityn test 23: others should see updated atime while another read============================================================== 23:23:39 (1789183419) [ 2455.238984] Lustre: DEBUG MARKER: == sanityn test 24a: lfs df [-ih] [path] test =================================================================================== 23:24:49 (1789183489) [ 2462.359185] Lustre: DEBUG MARKER: == sanityn test 24b: lfs df should show both filesystems ========================================================================= 23:24:57 (1789183497) [ 2469.063633] Lustre: DEBUG MARKER: == sanityn test 25a: change ACL on one mountpoint be seen on another ============================================================= 23:25:03 (1789183503) [ 2477.761197] Lustre: DEBUG MARKER: == sanityn test 25b: change ACL under remote dir on one mountpoint be seen on another ========================================================== 23:25:12 (1789183512) [ 2487.426567] Lustre: DEBUG MARKER: == sanityn test 26a: allow mtime to get older ============ 23:25:21 (1789183521) [ 2495.853739] Lustre: DEBUG MARKER: == sanityn test 26b: sync mtime between ost and mds ====== 23:25:30 (1789183530) [ 2497.505400] Lustre: lustre-OST0001-osc-ffff97591224c000: disconnect after 22s idle [ 2497.514537] Lustre: Skipped 4 previous similar messages [ 2504.780640] Lustre: DEBUG MARKER: == sanityn test 26c: set-in-past on open file is not lost on close ========================================================== 23:25:39 (1789183539) [ 2512.783375] Lustre: DEBUG MARKER: SKIP: sanityn test_27 skipping excluded test 27 [ 2514.610018] Lustre: DEBUG MARKER: == sanityn test 30: recreate file race =================== 23:25:49 (1789183549) [ 2523.020864] Lustre: DEBUG MARKER: == sanityn test 31a: voluntary cancel / blocking ast race======================================================================== 23:25:57 (1789183557) [ 2523.418417] Lustre: *** cfs_fail_loc=314, val=0*** [ 2524.447273] Lustre: *** cfs_fail_loc=314, val=0*** [ 2524.450415] Lustre: Skipped 2 previous similar messages [ 2530.968923] Lustre: DEBUG MARKER: == sanityn test 31b: voluntary OST cancel / blocking ast race======================================================================== 23:26:05 (1789183565) [ 2541.474235] Lustre: *** cfs_fail_loc=314, val=0*** [ 2541.549604] LustreError: lustre-OST0000-osc-ffff9759202f0000: operation ldlm_enqueue to node 192.168.202.136@tcp failed: rc = -107 [ 2541.555068] Lustre: lustre-OST0000-osc-ffff9759202f0000: Connection to lustre-OST0000 (at 192.168.202.136@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 2541.569985] LustreError: lustre-OST0000-osc-ffff9759202f0000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 2541.583749] LustreError: 46508:0:(ldlm_resource.c:1207:ldlm_resource_complain()) lustre-OST0000-osc-ffff9759202f0000: namespace resource [0x280000401:0x3a:0x0].0x0 (ffff9759124d2800) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 2541.621838] Lustre: lustre-OST0000-osc-ffff9759202f0000: Connection restored to 192.168.202.136@tcp (at 192.168.202.136@tcp) [ 2549.283287] Lustre: DEBUG MARKER: == sanityn test 31r: open-rename(replace) race =========== 23:26:23 (1789183583) [ 2549.699402] LustreError: 47098:0:(file.c:850:ll_intent_file_open()) cfs_fail_timeout id 1419 sleeping for 3000ms [ 2552.727176] LustreError: 47098:0:(file.c:850:ll_intent_file_open()) cfs_fail_timeout id 1419 awake [ 2559.815857] Lustre: DEBUG MARKER: == sanityn test 31s: open should not revalidate invalid dentry ========================================================== 23:26:33 (1789183593) [ 2569.530579] Lustre: DEBUG MARKER: == sanityn test 31t: getattr should not revalidate invalid dentry ========================================================== 23:26:44 (1789183604) [ 2577.037785] Lustre: DEBUG MARKER: == sanityn test 32b: lockless i/o ======================== 23:26:51 (1789183611) [ 2578.482468] Lustre: DEBUG MARKER: SKIP: sanityn test_32b max_nolock_bytes is removed >= 2.17.53 [ 2580.089560] Lustre: DEBUG MARKER: == sanityn test 32c: contention detection ================ 23:26:55 (1789183615) [ 2610.308314] Lustre: DEBUG MARKER: SKIP: sanityn test_33a skipping SLOW test 33a [ 2611.998454] Lustre: DEBUG MARKER: == sanityn test 33b: COS: cross create/delete, 2 clients, benchmark under remote dir ========================================================== 23:27:26 (1789183646) [ 2613.805569] Lustre: DEBUG MARKER: SKIP: sanityn test_33b Need two or more clients, have 1 [ 2615.263150] Lustre: lustre-OST0001-osc-ffff97591224c000: disconnect after 20s idle [ 2615.270129] Lustre: Skipped 2 previous similar messages [ 2615.445496] Lustre: DEBUG MARKER: == sanityn test 33c: Cancel cross-MDT lock should trigger Sync-on-Lock-Cancel ========================================================== 23:27:30 (1789183650) [ 2620.389816] Lustre: lustre-MDT0000-mdc-ffff97591224c000: Connection to lustre-MDT0000 (at 192.168.202.136@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 2620.400141] Lustre: Skipped 1 previous similar message [ 2630.641579] LustreError: MGC192.168.202.136@tcp: Connection to MGS (at 192.168.202.136@tcp) was lost; in progress operations using this service will fail [ 2630.682117] Lustre: Evicted from MGS (at 192.168.202.136@tcp) after server handle changed from 0x27b38bf42719c184 to 0x27b38bf427247b0c [ 2630.695310] Lustre: MGC192.168.202.136@tcp: Connection restored to 192.168.202.136@tcp (at 192.168.202.136@tcp) [ 2632.827065] Lustre: lustre-MDT0000-mdc-ffff97591224c000: Connection restored to 192.168.202.136@tcp (at 192.168.202.136@tcp) [ 2669.279508] Lustre: DEBUG MARKER: == sanityn test 33d: dependent transactions should trigger COS ========================================================== 23:28:23 (1789183703) [ 2728.790331] Lustre: DEBUG MARKER: == sanityn test 33e: independent transactions shouldn't trigger COS ========================================================== 23:29:23 (1789183763) [ 2747.487636] Lustre: DEBUG MARKER: == sanityn test 34: no lock timeout under IO ============= 23:29:41 (1789183781) [ 2758.624331] Lustre: lustre-OST0001-osc-ffff9759202f0000: disconnect after 24s idle [ 2758.627960] Lustre: Skipped 7 previous similar messages [ 2803.652612] Lustre: lustre-OST0000-osc-ffff9759202f0000: Connection to lustre-OST0000 (at 192.168.202.136@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 2803.714608] LustreError: lustre-OST0000-osc-ffff9759202f0000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 2803.738072] LustreError: lustre-OST0000-osc-ffff97591224c000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 2803.738591] Lustre: lustre-OST0000-osc-ffff9759202f0000: Connection restored to 192.168.202.136@tcp (at 192.168.202.136@tcp) [ 2803.793831] Lustre: Skipped 2 previous similar messages [ 2819.024750] Lustre: lustre-OST0001-osc-ffff97591224c000: Connection to lustre-OST0001 (at 192.168.202.136@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 2819.047387] Lustre: Skipped 1 previous similar message [ 2819.060268] LustreError: lustre-OST0001-osc-ffff97591224c000: This client was evicted by lustre-OST0001; in progress operations using this service will fail. [ 2819.086947] Lustre: lustre-OST0001-osc-ffff97591224c000: Connection restored to 192.168.202.136@tcp (at 192.168.202.136@tcp) [ 2838.006139] Lustre: DEBUG MARKER: oleg236-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0000-osc-ffff97591224c000.ost_server_uuid 50 [ 2839.293126] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff97591224c000.ost_server_uuid in IDLE state after 0 sec [ 2844.674858] Lustre: DEBUG MARKER: oleg236-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0001-osc-ffff97591224c000.ost_server_uuid 50 [ 2846.269836] Lustre: DEBUG MARKER: osc.lustre-OST0001-osc-ffff97591224c000.ost_server_uuid in IDLE state after 0 sec [ 2853.128346] Lustre: DEBUG MARKER: oleg236-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0000-osc-ffff97591224c000.ost_server_uuid 50 [ 2854.452873] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff97591224c000.ost_server_uuid in IDLE state after 0 sec [ 2860.042233] Lustre: DEBUG MARKER: oleg236-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0001-osc-ffff97591224c000.ost_server_uuid 50 [ 2861.430799] Lustre: DEBUG MARKER: osc.lustre-OST0001-osc-ffff97591224c000.ost_server_uuid in IDLE state after 0 sec [ 2874.097933] Lustre: DEBUG MARKER: oleg236-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0000-osc-ffff97591224c000.ost_server_uuid 50 [ 2875.618840] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff97591224c000.ost_server_uuid in IDLE state after 0 sec [ 2880.930789] Lustre: DEBUG MARKER: oleg236-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0001-osc-ffff97591224c000.ost_server_uuid 50 [ 2882.436875] Lustre: DEBUG MARKER: osc.lustre-OST0001-osc-ffff97591224c000.ost_server_uuid in IDLE state after 0 sec [ 2884.033586] Lustre: DEBUG MARKER: == sanityn test 35: -EINTR cp_ast vs. bl_ast race does not evict client ========================================================== 23:31:59 (1789183919) [ 2886.812697] Lustre: DEBUG MARKER: Race attempt 0 [ 2890.105243] Lustre: DEBUG MARKER: Wait for 59707 59719 for 60 sec... [ 2955.503874] Lustre: DEBUG MARKER: == sanityn test 36: handle ESTALE/open-unlink correctly == 23:33:10 (1789183990) [ 2963.223415] Lustre: DEBUG MARKER: start test - cycle (0) [ 2987.718943] Lustre: DEBUG MARKER: start test - cycle (1) [ 3015.403404] Lustre: DEBUG MARKER: start test - cycle (2) [ 3019.748529] Lustre: lustre-OST0000-osc-ffff9759202f0000: disconnect after 24s idle [ 3019.755752] Lustre: Skipped 4 previous similar messages [ 3041.525684] Lustre: DEBUG MARKER: start test - cycle (3) [ 3066.273967] Lustre: DEBUG MARKER: start test - cycle (4) [ 3089.809201] Lustre: DEBUG MARKER: start test - cycle (5) [ 3113.537689] Lustre: DEBUG MARKER: start test - cycle (6) [ 3136.333103] Lustre: DEBUG MARKER: start test - cycle (7) [ 3158.298457] Lustre: DEBUG MARKER: start test - cycle (8) [ 3182.790605] Lustre: DEBUG MARKER: start test - cycle (9) [ 3208.416089] Lustre: DEBUG MARKER: start test - cycle (10) [ 3240.452869] Lustre: DEBUG MARKER: == sanityn test 37: check i_size is not updated for directory on close (bug 18695) ======================================================================== 23:37:55 (1789184275) [ 3308.227910] Lustre: DEBUG MARKER: == sanityn test 39a: file mtime does not change after rename ========================================================== 23:39:02 (1789184342) [ 3315.606118] Lustre: DEBUG MARKER: == sanityn test 39b: file mtime the same on clients with/out lock ========================================================== 23:39:10 (1789184350) [ 3323.289400] Lustre: DEBUG MARKER: == sanityn test 39c: check truncate mtime update ================================================================================ 23:39:18 (1789184358) [ 3331.464364] Lustre: DEBUG MARKER: == sanityn test 39d: sync write should update mtime ====== 23:39:26 (1789184366) [ 3331.870827] Lustre: *** cfs_fail_loc=411, val=0*** [ 3337.956762] Lustre: DEBUG MARKER: SKIP: sanityn test_40a skipping ALWAYS excluded test 40a [ 3339.600283] Lustre: DEBUG MARKER: == sanityn test 40b: pdirops: open|create and others ======================================================================== 23:39:34 (1789184374) [ 3357.012756] Lustre: DEBUG MARKER: == sanityn test 40c: pdirops: link and others ======================================================================== 23:39:51 (1789184391) [ 3373.353584] Lustre: DEBUG MARKER: == sanityn test 40d: pdirops: unlink and others ======================================================================== 23:40:08 (1789184408) [ 3389.985855] Lustre: DEBUG MARKER: == sanityn test 40e: pdirops: rename and others ======================================================================== 23:40:24 (1789184424) [ 3405.602811] Lustre: DEBUG MARKER: == sanityn test 41a: pdirops: create vs mkdir ======================================================================== 23:40:40 (1789184440) [ 3416.251520] Lustre: DEBUG MARKER: == sanityn test 41b: pdirops: create vs create ======================================================================== 23:40:51 (1789184451) [ 3427.995333] Lustre: DEBUG MARKER: == sanityn test 41c: pdirops: create vs link ======================================================================== 23:41:03 (1789184463) [ 3441.931945] Lustre: DEBUG MARKER: == sanityn test 41d: pdirops: create vs unlink ======================================================================== 23:41:16 (1789184476) [ 3453.904902] Lustre: DEBUG MARKER: == sanityn test 41e: pdirops: create and rename (tgt) ======================================================================== 23:41:29 (1789184489) [ 3466.835758] Lustre: DEBUG MARKER: == sanityn test 41f: pdirops: create and rename (src) ======================================================================== 23:41:41 (1789184501) [ 3479.972899] Lustre: DEBUG MARKER: == sanityn test 41g: pdirops: create vs getattr ======================================================================== 23:41:54 (1789184514) [ 3492.516365] Lustre: DEBUG MARKER: == sanityn test 41h: pdirops: create vs readdir ======================================================================== 23:42:07 (1789184527) [ 3507.777912] Lustre: DEBUG MARKER: == sanityn test 41i: reint_open: create vs create ======== 23:42:22 (1789184542) [ 4123.616265] Lustre: lustre-OST0000-osc-ffff9759202f0000: disconnect after 21s idle [ 4123.631692] Lustre: Skipped 12 previous similar messages [ 4574.356610] Lustre: DEBUG MARKER: == sanityn test 42a: pdirops: mkdir vs mkdir ======================================================================== 00:00:09 (1789185609) [ 4586.697944] Lustre: DEBUG MARKER: == sanityn test 42b: pdirops: mkdir vs create ======================================================================== 00:00:21 (1789185621) [ 4599.783808] Lustre: DEBUG MARKER: == sanityn test 42c: pdirops: mkdir vs link ======================================================================== 00:00:34 (1789185634) [ 4612.892413] Lustre: DEBUG MARKER: == sanityn test 42d: pdirops: mkdir vs unlink ======================================================================== 00:00:47 (1789185647) [ 4626.251863] Lustre: DEBUG MARKER: == sanityn test 42e: pdirops: mkdir and rename (tgt) ======================================================================== 00:01:01 (1789185661) [ 4639.591840] Lustre: DEBUG MARKER: == sanityn test 42f: pdirops: mkdir and rename (src) ======================================================================== 00:01:14 (1789185674) [ 4652.110295] Lustre: DEBUG MARKER: == sanityn test 42g: pdirops: mkdir vs getattr ======================================================================== 00:01:27 (1789185687) [ 4665.328676] Lustre: DEBUG MARKER: == sanityn test 42h: pdirops: mkdir vs readdir ======================================================================== 00:01:40 (1789185700) [ 4677.736744] Lustre: DEBUG MARKER: == sanityn test 43a: rmdir,mkdir doesn't return -EEXIST ======================================================================== 00:01:52 (1789185712) [ 4769.492743] Lustre: DEBUG MARKER: == sanityn test 43b: pdirops: unlink vs create ======================================================================== 00:03:23 (1789185803) [ 4785.006791] Lustre: DEBUG MARKER: == sanityn test 43c: pdirops: unlink vs link ======================================================================== 00:03:39 (1789185819) [ 4800.211099] Lustre: DEBUG MARKER: == sanityn test 43d: pdirops: unlink vs unlink ======================================================================== 00:03:55 (1789185835) [ 4814.580704] Lustre: DEBUG MARKER: == sanityn test 43e: pdirops: unlink and rename (tgt) ======================================================================== 00:04:09 (1789185849) [ 4827.403697] Lustre: DEBUG MARKER: == sanityn test 43f: pdirops: unlink and rename (src) ======================================================================== 00:04:22 (1789185862) [ 4839.381122] Lustre: DEBUG MARKER: == sanityn test 43g: pdirops: unlink vs getattr ======================================================================== 00:04:34 (1789185874) [ 4851.844736] Lustre: DEBUG MARKER: == sanityn test 43h: pdirops: unlink vs readdir ======================================================================== 00:04:46 (1789185886) [ 4864.815261] Lustre: DEBUG MARKER: == sanityn test 43i: pdirops: unlink vs remote mkdir ===== 00:04:59 (1789185899) [ 4878.360486] Lustre: DEBUG MARKER: == sanityn test 43j: racy mkdir return EEXIST ======================================================================== 00:05:13 (1789185913) [ 4881.379526] Lustre: lustre-OST0000-osc-ffff97591224c000: disconnect after 22s idle [ 4881.388953] Lustre: Skipped 4 previous similar messages [ 4992.728497] Lustre: DEBUG MARKER: == sanityn test 43k: unlink vs create ==================== 00:07:07 (1789186027) [ 5485.535278] Lustre: lustre-OST0001-osc-ffff9759202f0000: disconnect after 23s idle [ 5485.544966] Lustre: Skipped 5 previous similar messages [ 6029.372959] Lustre: DEBUG MARKER: == sanityn test 44a: pdirops: rename tgt vs mkdir ======================================================================== 00:24:24 (1789187064) [ 6040.700408] Lustre: DEBUG MARKER: == sanityn test 44b: pdirops: rename tgt vs create ======================================================================== 00:24:35 (1789187075) [ 6050.688089] Lustre: DEBUG MARKER: == sanityn test 44c: pdirops: rename tgt vs link ======================================================================== 00:24:46 (1789187086) [ 6060.494828] Lustre: DEBUG MARKER: == sanityn test 44d: pdirops: rename tgt vs unlink ======================================================================== 00:24:55 (1789187095) [ 6071.009869] Lustre: DEBUG MARKER: == sanityn test 44e: pdirops: rename tgt and rename (tgt) ======================================================================== 00:25:06 (1789187106) [ 6080.520219] Lustre: DEBUG MARKER: == sanityn test 44f: pdirops: rename tgt and rename (src) ======================================================================== 00:25:15 (1789187115) [ 6089.909224] Lustre: DEBUG MARKER: == sanityn test 44g: pdirops: rename tgt vs getattr ======================================================================== 00:25:25 (1789187125) [ 6099.926112] Lustre: DEBUG MARKER: == sanityn test 44h: pdirops: rename tgt vs readdir ======================================================================== 00:25:35 (1789187135) [ 6110.920549] Lustre: DEBUG MARKER: == sanityn test 44i: pdirops: rename tgt vs remote mkdir ========================================================== 00:25:46 (1789187146) [ 6120.073969] Lustre: DEBUG MARKER: == sanityn test 45a: rename,mkdir doesn't return -EEXIST ======================================================================== 00:25:55 (1789187155) [ 6130.655126] Lustre: lustre-OST0001-osc-ffff97591224c000: disconnect after 22s idle [ 6130.657906] Lustre: Skipped 4 previous similar messages [ 6236.230532] Lustre: DEBUG MARKER: == sanityn test 45b: pdirops: rename src vs create ======================================================================== 00:27:51 (1789187271) [ 6244.549077] Lustre: DEBUG MARKER: == sanityn test 45c: pdirops: rename src vs link ======================================================================== 00:27:59 (1789187279) [ 6253.287287] Lustre: DEBUG MARKER: == sanityn test 45d: pdirops: rename src vs unlink ======================================================================== 00:28:08 (1789187288) [ 6262.028865] Lustre: DEBUG MARKER: == sanityn test 45e: pdirops: rename src and rename (tgt) ======================================================================== 00:28:17 (1789187297) [ 6270.707762] Lustre: DEBUG MARKER: == sanityn test 45f: pdirops: rename src and rename (src) ======================================================================== 00:28:26 (1789187306) [ 6280.583167] Lustre: DEBUG MARKER: == sanityn test 45g: pdirops: rename src vs getattr ======================================================================== 00:28:35 (1789187315) [ 6288.662334] Lustre: DEBUG MARKER: == sanityn test 45h: pdirops: unlink vs readdir ======================================================================== 00:28:44 (1789187324) [ 6295.544345] Lustre: DEBUG MARKER: == sanityn test 45i: pdirops: rename src vs remote mkdir ========================================================== 00:28:51 (1789187331) [ 6303.467267] Lustre: DEBUG MARKER: == sanityn test 45j: read vs rename ====================== 00:28:58 (1789187338) [ 6816.735541] Lustre: lustre-OST0000-osc-ffff97591224c000: disconnect after 23s idle [ 6816.745103] Lustre: Skipped 2 previous similar messages [ 7039.626392] Lustre: DEBUG MARKER: == sanityn test 46a: pdirops: link vs mkdir ======================================================================== 00:41:14 (1789188074) [ 7047.218604] Lustre: DEBUG MARKER: == sanityn test 46b: pdirops: link vs create ======================================================================== 00:41:22 (1789188082) [ 7054.892788] Lustre: DEBUG MARKER: == sanityn test 46c: pdirops: link vs link ======================================================================== 00:41:30 (1789188090) [ 7064.141249] Lustre: DEBUG MARKER: == sanityn test 46d: pdirops: link vs unlink ======================================================================== 00:41:39 (1789188099) [ 7072.449841] Lustre: DEBUG MARKER: == sanityn test 46e: pdirops: link and rename (tgt) ======================================================================== 00:41:47 (1789188107) [ 7079.673931] Lustre: DEBUG MARKER: == sanityn test 46f: pdirops: link and rename (src) ======================================================================== 00:41:55 (1789188115) [ 7087.874126] Lustre: DEBUG MARKER: == sanityn test 46g: pdirops: link vs getattr ======================================================================== 00:42:03 (1789188123) [ 7095.606594] Lustre: DEBUG MARKER: == sanityn test 46h: pdirops: link vs readdir ======================================================================== 00:42:11 (1789188131) [ 7102.517789] Lustre: DEBUG MARKER: == sanityn test 46i: pdirops: link vs remote mkdir ======= 00:42:18 (1789188138) [ 7109.214567] Lustre: DEBUG MARKER: == sanityn test 47a: pdirops: remote mkdir vs mkdir ====== 00:42:24 (1789188144) [ 7116.471355] Lustre: DEBUG MARKER: == sanityn test 47b: pdirops: remote mkdir vs create ===== 00:42:32 (1789188152) [ 7124.350499] Lustre: DEBUG MARKER: == sanityn test 47c: pdirops: remote mkdir vs link ======= 00:42:39 (1789188159) [ 7130.945040] Lustre: DEBUG MARKER: == sanityn test 47d: pdirops: remote mkdir vs unlink ===== 00:42:46 (1789188166) [ 7137.823497] Lustre: DEBUG MARKER: == sanityn test 47e: pdirops: remote mkdir and rename (tgt) ========================================================== 00:42:53 (1789188173) [ 7145.191701] Lustre: DEBUG MARKER: == sanityn test 47f: pdirops: remote mkdir and rename (src) ========================================================== 00:43:00 (1789188180) [ 7151.839255] Lustre: DEBUG MARKER: == sanityn test 47g: pdirops: remote mkdir vs getattr ==== 00:43:07 (1789188187) [ 7159.419933] Lustre: DEBUG MARKER: == sanityn test 50: osc lvb attrs: enqueue vs. CP AST ======================================================================== 00:43:15 (1789188195) [ 7159.511386] LustreError: 22744:0:(ldlm_lockd.c:2079:ldlm_handle_cp_callback()) cfs_fail_timeout id 410 sleeping for 2000ms [ 7161.599124] LustreError: 22744:0:(ldlm_lockd.c:2079:ldlm_handle_cp_callback()) cfs_fail_timeout id 410 awake [ 7167.730723] Lustre: DEBUG MARKER: == sanityn test 51a: layout lock: refresh layout should work ========================================================== 00:43:23 (1789188203) [ 7172.997123] Lustre: DEBUG MARKER: == sanityn test 51b: layout lock: glimpse should be able to restart if layout changed ========================================================== 00:43:28 (1789188208) [ 7173.187812] LustreError: 241193:0:(glimpse.c:206:__cl_glimpse_size()) cfs_fail_timeout id 1404 sleeping for 4000ms [ 7177.255137] LustreError: 241193:0:(glimpse.c:206:__cl_glimpse_size()) cfs_fail_timeout id 1404 awake [ 7177.281421] LustreError: 241193:0:(glimpse.c:206:__cl_glimpse_size()) cfs_fail_timeout id 1404 sleeping for 4000ms [ 7181.344973] LustreError: 241193:0:(glimpse.c:206:__cl_glimpse_size()) cfs_fail_timeout id 1404 awake [ 7181.376391] LustreError: 241199:0:(glimpse.c:206:__cl_glimpse_size()) cfs_fail_timeout id 1404 sleeping for 4000ms [ 7185.440938] LustreError: 241199:0:(glimpse.c:206:__cl_glimpse_size()) cfs_fail_timeout id 1404 awake [ 7188.972443] Lustre: DEBUG MARKER: == sanityn test 51c: layout lock: IT_LAYOUT blocked and correct layout can be returned ========================================================== 00:43:44 (1789188224) [ 7196.467256] Lustre: DEBUG MARKER: == sanityn test 51d: layout lock: losing layout lock should clean up memory map region ========================================================== 00:43:52 (1789188232) [ 7200.691569] Lustre: DEBUG MARKER: == sanityn test 51e: lfs getstripe does not break leases, part 2 ========================================================== 00:43:56 (1789188236) [ 7206.116391] Lustre: DEBUG MARKER: == sanityn test 54: rename locking ======================= 00:44:01 (1789188241) [ 7232.490556] Lustre: DEBUG MARKER: == sanityn test 55a: rename vs unlink target dir ========= 00:44:28 (1789188268) [ 7241.891809] Lustre: DEBUG MARKER: == sanityn test 55b: rename vs unlink source dir ========= 00:44:37 (1789188277) [ 7250.222824] Lustre: DEBUG MARKER: == sanityn test 55c: rename vs unlink orphan target dir == 00:44:45 (1789188285) [ 7263.693753] Lustre: DEBUG MARKER: == sanityn test 55d: rename file vs link ================= 00:44:59 (1789188299) [ 7274.454119] Lustre: DEBUG MARKER: == sanityn test 55e: rename race AB/BA under the same parent dir ========================================================== 00:45:10 (1789188310) [ 7288.892742] Lustre: DEBUG MARKER: == sanityn test 55f: rename: (P1/A -> P2/B) race with (P2/B -> P1/A) ========================================================== 00:45:24 (1789188324) [ 7302.616696] Lustre: DEBUG MARKER: == sanityn test 55g: rename: race with trylock =========== 00:45:38 (1789188338) [ 7318.120444] Lustre: DEBUG MARKER: == sanityn test 56a: test llverdev with single large stripe ========================================================== 00:45:53 (1789188353) [ 7327.295427] Lustre: DEBUG MARKER: == sanityn test 56b: test llverdev and partial verify of wide stripe file ========================================================== 00:46:02 (1789188362) [ 7370.131419] Lustre: DEBUG MARKER: == sanityn test 60: Verify data_version behaviour ======== 00:46:45 (1789188405) [ 7373.899112] Lustre: DEBUG MARKER: == sanityn test 70a: cd directory [ 7377.651259] Lustre: DEBUG MARKER: == sanityn test 70b: remove files after calling rm_entry ========================================================== 00:46:53 (1789188413) [ 7381.950674] Lustre: DEBUG MARKER: == sanityn test 71a: correct file map just after write operation is finished ========================================================== 00:46:57 (1789188417) [ 7385.623962] Lustre: DEBUG MARKER: == sanityn test 71b: check fiemap support for stripecount > 1 ========================================================== 00:47:01 (1789188421) [ 7388.955614] Lustre: DEBUG MARKER: == sanityn test 71c: check FIEMAP_EXTENT_LAST flag with different extents number ========================================================== 00:47:04 (1789188424) [ 7411.579110] Lustre: DEBUG MARKER: == sanityn test 71d: fiemap corruption test with fm_extent_count=0 ========================================================== 00:47:27 (1789188447) [ 7431.135221] Lustre: lustre-OST0001-osc-ffff97591224c000: disconnect after 21s idle [ 7431.141417] Lustre: Skipped 8 previous similar messages [ 7433.733340] Lustre: DEBUG MARKER: == sanityn test 72: getxattr/setxattr cache should be consistent between nodes ========================================================== 00:47:49 (1789188469) [ 7436.569986] Lustre: DEBUG MARKER: == sanityn test 73: getxattr should not cause xattr lock cancellation ========================================================== 00:47:52 (1789188472) [ 7439.444376] Lustre: DEBUG MARKER: == sanityn test 74: flock deadlock: different mounts ======================================================================== 00:47:55 (1789188475) [ 7442.614384] LustreError: lustre-MDT0000-mdc-ffff9759202f0000: operation ldlm_enqueue to node 192.168.202.136@tcp failed: rc = -35 [ 7446.101618] Lustre: DEBUG MARKER: == sanityn test 75: osc: upcall after unuse lock============================================================================= 00:48:01 (1789188481) [ 7446.321727] LustreError: 2412:0:(osc_request.c:3139:osc_enqueue_interpret()) cfs_fail_timeout id 31d sleeping for 2000ms [ 7448.407119] LustreError: 2412:0:(osc_request.c:3139:osc_enqueue_interpret()) cfs_fail_timeout id 31d awake [ 7454.125536] Lustre: DEBUG MARKER: == sanityn test 76: Verify MDT open_files listing ======== 00:48:09 (1789188489) [ 7527.873240] Lustre: DEBUG MARKER: == sanityn test 77a: check FIFO NRS policy =============== 00:49:23 (1789188563) [ 7532.152734] Lustre: DEBUG MARKER: == sanityn test 77b: check CRR-N NRS policy ============== 00:49:27 (1789188567) [ 7538.588551] Lustre: DEBUG MARKER: == sanityn test 77c: check ORR NRS policy ================ 00:49:34 (1789188574) [ 7546.088123] Lustre: DEBUG MARKER: == sanityn test 77d: check TRR nrs policy ================ 00:49:41 (1789188581) [ 7552.955408] Lustre: DEBUG MARKER: == sanityn test 77e: check TBF NID nrs policy ============ 00:49:48 (1789188588) [ 7563.503787] Lustre: DEBUG MARKER: == sanityn test 77f: check TBF JobID nrs policy ========== 00:49:59 (1789188599) [ 7573.067852] Lustre: DEBUG MARKER: == sanityn test 77g: Change TBF type directly ============ 00:50:08 (1789188608) [ 7577.648849] Lustre: DEBUG MARKER: == sanityn test 77h: Wrong policy name should report error, not LBUG ========================================================== 00:50:13 (1789188613) [ 7583.011039] Lustre: DEBUG MARKER: == sanityn test 77i: Change rank of TBF rule ============= 00:50:18 (1789188618) [ 7592.836621] Lustre: DEBUG MARKER: == sanityn test 77j: check TBF-OPCode NRS policy ========= 00:50:28 (1789188628) [ 7638.852733] Lustre: DEBUG MARKER: == sanityn test 77ja: check TBF-UID/GID NRS policy ======= 00:51:14 (1789188674) [ 7755.659275] Lustre: DEBUG MARKER: == sanityn test 77jb: check TBF-UID/GID NRS policy on files that don't belong to us ========================================================== 00:53:11 (1789188791) [ 7869.102048] Lustre: DEBUG MARKER: == sanityn test 77k: check TBF policy with UID/GID/JobID/OPCode expression ========================================================== 00:55:04 (1789188904) [ 8091.615279] Lustre: lustre-OST0001-osc-ffff97591224c000: disconnect after 20s idle [ 8091.619338] Lustre: Skipped 12 previous similar messages [ 8139.420318] Lustre: DEBUG MARKER: == sanityn test 77kb: Check different granular TBF type combination: jobid+opcode ========================================================== 00:59:35 (1789189175) [ 8166.520568] Lustre: DEBUG MARKER: == sanityn test 77kc: Check different granular TBF type combination: nid+opcode ========================================================== 01:00:02 (1789189202) [ 8197.643492] Lustre: DEBUG MARKER: == sanityn test 77kd: Check different granular TBF type combination: nid+jobid ========================================================== 01:00:33 (1789189233) [ 8222.824603] Lustre: DEBUG MARKER: == sanityn test 77ke: Check different granular TBF type combination: jobid+opcode ========================================================== 01:00:58 (1789189258) [ 8282.896524] Lustre: DEBUG MARKER: == sanityn test 77kf: Check different granular TBF type combination: uid+gid ========================================================== 01:01:58 (1789189318) [ 8336.374084] Lustre: DEBUG MARKER: == sanityn test 77kg: check different granular TBF type combination: uid+opcode ========================================================== 01:02:52 (1789189372) [ 8427.265953] Lustre: DEBUG MARKER: == sanityn test 77kh: Verify that Project ID support for NRS TBF rule ========================================================== 01:04:23 (1789189463) [ 8428.406098] Lustre: Unmounted lustre-client [ 8429.070080] Lustre: Unmounted lustre-client [ 8495.927337] Lustre: Mounted lustre-client - version 2.17.58_39_g3d58bdf [ 8497.453348] Lustre: Mounted lustre-client - version 2.17.58_39_g3d58bdf [ 8498.422188] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 8552.848146] Lustre: DEBUG MARKER: == sanityn test 77ki: Add rule with unsupported TBF type should fail for generic TBF ========================================================== 01:06:28 (1789189588) [ 8560.441813] Lustre: DEBUG MARKER: == sanityn test 77kj: Verify nodemap support for NRS TBF rule ========================================================== 01:06:36 (1789189596) [ 8642.822363] Lustre: DEBUG MARKER: == sanityn test 77l: check the output of NRS policies for generic TBF ========================================================== 01:07:58 (1789189678) [ 8645.948254] Lustre: DEBUG MARKER: == sanityn test 77m: check NRS Delay slows write RPC processing ========================================================== 01:08:01 (1789189681) [ 8696.328157] Lustre: DEBUG MARKER: == sanityn test 77n: check wildcard support for TBF JobID NRS policy ========================================================== 01:08:52 (1789189732) [ 8733.151228] Lustre: lustre-OST0001-osc-ffff9759191ab000: disconnect after 21s idle [ 8733.153887] Lustre: Skipped 11 previous similar messages [ 8736.126944] Lustre: DEBUG MARKER: == sanityn test 77o: Changing rank should not panic ====== 01:09:31 (1789189771) [ 8739.703749] Lustre: DEBUG MARKER: == sanityn test 77q: Parallel TBF rule definitions should not panic ========================================================== 01:09:35 (1789189775) [ 8776.065449] Lustre: DEBUG MARKER: == sanityn test 77p: Check validity of rule names for TBF policies ========================================================== 01:10:11 (1789189811) [ 8787.837683] Lustre: DEBUG MARKER: == sanityn test 77r: Change type of tbf policy at run time ========================================================== 01:10:23 (1789189823) [ 8829.397377] Lustre: DEBUG MARKER: == sanityn test 77s: Check TBF LRU shrinker ============== 01:11:05 (1789189865) [ 8840.889950] Lustre: DEBUG MARKER: == sanityn test 78: Enable policy and specify tunings right away ========================================================== 01:11:16 (1789189876) [ 8843.711729] Lustre: DEBUG MARKER: == sanityn test 79: xattr: intent error ================== 01:11:19 (1789189879) [ 8856.453955] Lustre: DEBUG MARKER: == sanityn test 80a: migrate directory when some children is being opened ========================================================== 01:11:32 (1789189892) [ 8860.068214] Lustre: DEBUG MARKER: == sanityn test 80b: Accessing directory during migration ========================================================== 01:11:35 (1789189895) [ 8860.498546] LustreError: 314712:0:(lcommon_cl.c:187:cl_file_inode_init()) lustre: failed to initialize cl_object [0x2000013a1:0x7b2:0x0]: rc = -5 [ 8860.503196] LustreError: 314712:0:(llite_lib.c:3893:ll_prep_inode()) lustre: new_inode - fatal error: rc = -5 [ 8861.005125] LustreError: 314753:0:(lcommon_cl.c:187:cl_file_inode_init()) lustre: failed to initialize cl_object [0x2000013a1:0x7b7:0x0]: rc = -5 [ 8861.008755] LustreError: 314753:0:(lcommon_cl.c:187:cl_file_inode_init()) Skipped 11 previous similar messages [ 8861.011289] LustreError: 314753:0:(llite_lib.c:3893:ll_prep_inode()) lustre: new_inode - fatal error: rc = -5 [ 8861.014633] LustreError: 314753:0:(llite_lib.c:3893:ll_prep_inode()) Skipped 11 previous similar messages [ 8862.006706] LustreError: 314540:0:(lcommon_cl.c:187:cl_file_inode_init()) lustre: failed to initialize cl_object [0x2000013a1:0x7db:0x0]: rc = -5 [ 8862.010199] LustreError: 314540:0:(lcommon_cl.c:187:cl_file_inode_init()) Skipped 25 previous similar messages [ 8862.012389] LustreError: 314540:0:(llite_lib.c:3893:ll_prep_inode()) lustre: new_inode - fatal error: rc = -5 [ 8862.014751] LustreError: 314540:0:(llite_lib.c:3893:ll_prep_inode()) Skipped 25 previous similar messages [ 8864.053428] LustreError: 315039:0:(lcommon_cl.c:187:cl_file_inode_init()) lustre: failed to initialize cl_object [0x2000013a1:0x81e:0x0]: rc = -5 [ 8864.057363] LustreError: 315039:0:(lcommon_cl.c:187:cl_file_inode_init()) Skipped 57 previous similar messages [ 8864.060222] LustreError: 315039:0:(llite_lib.c:3893:ll_prep_inode()) lustre: new_inode - fatal error: rc = -5 [ 8864.063914] LustreError: 315039:0:(llite_lib.c:3893:ll_prep_inode()) Skipped 57 previous similar messages [ 8868.101510] LustreError: 315399:0:(lcommon_cl.c:187:cl_file_inode_init()) lustre: failed to initialize cl_object [0x240000bd0:0x104:0x0]: rc = -5 [ 8868.104190] LustreError: 315399:0:(lcommon_cl.c:187:cl_file_inode_init()) Skipped 101 previous similar messages [ 8868.107049] LustreError: 315399:0:(llite_lib.c:3893:ll_prep_inode()) lustre: new_inode - fatal error: rc = -5 [ 8868.109606] LustreError: 315399:0:(llite_lib.c:3893:ll_prep_inode()) Skipped 101 previous similar messages [ 8876.110639] LustreError: 316148:0:(lcommon_cl.c:187:cl_file_inode_init()) lustre: failed to initialize cl_object [0x2000013a1:0x97a:0x0]: rc = -5 [ 8876.115367] LustreError: 316148:0:(lcommon_cl.c:187:cl_file_inode_init()) Skipped 216 previous similar messages [ 8876.117400] LustreError: 316148:0:(llite_lib.c:3893:ll_prep_inode()) lustre: new_inode - fatal error: rc = -5 [ 8876.119354] LustreError: 316148:0:(llite_lib.c:3893:ll_prep_inode()) Skipped 216 previous similar messages [ 8888.841096] LustreError: 317342:0:(file.c:251:ll_close_inode_openhandle()) lustre-clilmv-ffff97592f732800: inode [0x2000013a1:0xb00:0x0] mdc close failed: rc = -2 [ 8892.111064] LustreError: 317631:0:(lcommon_cl.c:187:cl_file_inode_init()) lustre: failed to initialize cl_object [0x2000013a1:0xb51:0x0]: rc = -5 [ 8892.114376] LustreError: 317631:0:(lcommon_cl.c:187:cl_file_inode_init()) Skipped 434 previous similar messages [ 8892.138397] LustreError: 314540:0:(llite_lib.c:3893:ll_prep_inode()) lustre: new_inode - fatal error: rc = -5 [ 8892.141071] LustreError: 314540:0:(llite_lib.c:3893:ll_prep_inode()) Skipped 435 previous similar messages [ 8927.515403] Lustre: DEBUG MARKER: == sanityn test 81a: rename and stat under striped directory ========================================================== 01:12:43 (1789189963) [ 8929.597765] Lustre: DEBUG MARKER: == sanityn test 81b: rename under striped directory doesn't deadlock ========================================================== 01:12:45 (1789189965) [ 8971.566801] Lustre: DEBUG MARKER: == sanityn test 81c: rename revoke LOOKUP lock for remote object ========================================================== 01:13:27 (1789190007) [ 8972.094982] Lustre: DEBUG MARKER: SKIP: sanityn test_81c needs >= 4 MDTs [ 8972.683710] Lustre: DEBUG MARKER: == sanityn test 81d: parallel rename file cross-dir on same MDT ========================================================== 01:13:28 (1789190008) [ 9013.147986] Lustre: DEBUG MARKER: == sanityn test 82: fsetxattr and fgetxattr on orphan files ========================================================== 01:14:08 (1789190048) [ 9015.381534] Lustre: DEBUG MARKER: == sanityn test 83: access striped directory while it is being created/unlinked ========================================================== 01:14:11 (1789190051) [ 9137.491795] Lustre: DEBUG MARKER: == sanityn test 84: 0-nlink race in lu_object_find() ===== 01:16:13 (1789190173) [ 9144.809604] Lustre: DEBUG MARKER: == sanityn test 85: Lustre API root cache race =========== 01:16:20 (1789190180) [ 9147.546132] Lustre: DEBUG MARKER: == sanityn test 90: open/create and unlink striped directory ========================================================== 01:16:23 (1789190183) [ 9331.918447] Lustre: DEBUG MARKER: == sanityn test 91: chmod and unlink striped directory === 01:19:27 (1789190367) [ 9485.792077] Lustre: lustre-OST0000-osc-ffff9759191ab000: disconnect after 22s idle [ 9485.795163] Lustre: Skipped 7 previous similar messages [ 9514.184922] Lustre: DEBUG MARKER: == sanityn test 92: create remote directory under orphan directory ========================================================== 01:22:30 (1789190550) [ 9516.347214] Lustre: DEBUG MARKER: == sanityn test 93: alloc_rr should not allocate on same ost ========================================================== 01:22:32 (1789190552) [ 9525.009071] Lustre: DEBUG MARKER: == sanityn test 94: signal vs CP callback race =========== 01:22:40 (1789190560) [ 9525.063154] Lustre: DEBUG MARKER: write [ 9525.090644] LustreError: 290271:0:(ldlm_request.c:1533:ldlm_cli_cancel_req()) cfs_fail_timeout id 312 sleeping for 5000ms [ 9527.087345] Lustre: DEBUG MARKER: kill 377100 [ 9527.089198] LustreError: 377100:0:(ldlm_request.c:1393:ldlm_cli_cancel_local()) cfs_fail_timeout id 329 sleeping for 6000ms [ 9530.191087] LustreError: 290271:0:(ldlm_request.c:1533:ldlm_cli_cancel_req()) cfs_fail_timeout id 312 awake [ 9533.127226] LustreError: 377100:0:(ldlm_request.c:1393:ldlm_cli_cancel_local()) cfs_fail_timeout id 329 awake [ 9535.131931] Lustre: DEBUG MARKER: == sanityn test 95a: Check readpage() on a page that was removed from page cache ========================================================== 01:22:50 (1789190570) [ 9537.314898] LustreError: 377713:0:(rw.c:1866:ll_readpage()) cfs_fail_timeout id 1422 sleeping for 10000ms [ 9547.407120] LustreError: 377713:0:(rw.c:1866:ll_readpage()) cfs_fail_timeout id 1422 awake [ 9549.526841] Lustre: DEBUG MARKER: == sanityn test 95b: Check readpage() on a page that is no longer uptodate ========================================================== 01:23:05 (1789190585) [ 9549.613413] LustreError: 378300:0:(rw.c:2113:ll_readpage()) cfs_fail_timeout id 1424 sleeping for 5000ms [ 9551.695066] LustreError: 378300:0:(rw.c:2113:ll_readpage()) cfs_fail_timeout interrupted [ 9557.627492] Lustre: DEBUG MARKER: == sanityn test 100a: DoM: glimpse RPCs for stat without IO lock (DoM only file) ========================================================== 01:23:13 (1789190593) [ 9558.101567] Lustre: DEBUG MARKER: SKIP: sanityn test_100a Reserved for glimpse-ahead [ 9558.704251] Lustre: DEBUG MARKER: == sanityn test 100b: DoM: no glimpse RPC for stat with IO lock (DoM only file) ========================================================== 01:23:14 (1789190594) [ 9561.159651] Lustre: DEBUG MARKER: == sanityn test 100c: DoM: write vs stat without IO lock (combined file) ========================================================== 01:23:17 (1789190597) [ 9563.268767] Lustre: DEBUG MARKER: == sanityn test 100d: DoM: write+truncate vs stat without IO lock (combined file) ========================================================== 01:23:19 (1789190599) [ 9565.341551] Lustre: DEBUG MARKER: == sanityn test 100e: DoM: read on open and file size ==== 01:23:21 (1789190601) [ 9567.396550] Lustre: DEBUG MARKER: == sanityn test 101a: Discard DoM data on unlink ========= 01:23:23 (1789190603) [ 9569.304911] Lustre: DEBUG MARKER: == sanityn test 101b: Discard DoM data on rename ========= 01:23:25 (1789190605) [ 9571.432576] Lustre: DEBUG MARKER: == sanityn test 101c: Discard DoM data on close-unlink === 01:23:27 (1789190607) [ 9574.626686] Lustre: DEBUG MARKER: == sanityn test 102: Test open by handle of unlinked file ========================================================== 01:23:30 (1789190610) [ 9577.378852] Lustre: DEBUG MARKER: == sanityn test 103: Test size correctness with lockahead ========================================================== 01:23:33 (1789190613) [ 9577.997312] Lustre: *** cfs_fail_loc=415, val=0*** [ 9584.592150] Lustre: DEBUG MARKER: == sanityn test 104: Verify that MDS stores atime/mtime/ctime during close ========================================================== 01:23:40 (1789190620) [ 9603.871740] Lustre: DEBUG MARKER: == sanityn test 105: Glimpse and lock cancel race ======== 01:23:59 (1789190639) [ 9603.968527] LustreError: 290993:0:(osc_lock.c:435:__osc_dlm_blocking_ast()) cfs_fail_timeout id 416 sleeping for 5000ms [ 9603.970618] LustreError: 290993:0:(osc_lock.c:435:__osc_dlm_blocking_ast()) Skipped 3 previous similar messages [ 9609.063105] LustreError: 290790:0:(osc_lock.c:435:__osc_dlm_blocking_ast()) cfs_fail_timeout id 416 awake [ 9609.066434] LustreError: 290790:0:(osc_lock.c:435:__osc_dlm_blocking_ast()) Skipped 2 previous similar messages [ 9619.271108] LustreError: 290790:0:(osc_lock.c:435:__osc_dlm_blocking_ast()) cfs_fail_timeout id 416 awake [ 9619.273629] LustreError: 290790:0:(osc_lock.c:435:__osc_dlm_blocking_ast()) Skipped 5 previous similar messages [ 9626.594566] Lustre: DEBUG MARKER: == sanityn test 106a: Verify the btime via statx() ======= 01:24:22 (1789190662) [ 9628.908696] Lustre: DEBUG MARKER: == sanityn test 106b: Glimpse RPCs test for statx ======== 01:24:24 (1789190664) [ 9631.072194] Lustre: DEBUG MARKER: == sanityn test 106c: Verify statx attributes mask ======= 01:24:26 (1789190666) [ 9633.068878] Lustre: DEBUG MARKER: == sanityn test 107a: Basic grouplock conflict =========== 01:24:28 (1789190668) [ 9637.049832] Lustre: DEBUG MARKER: == sanityn test 107b: Grouplock is added to the head of waiting list ========================================================== 01:24:32 (1789190672) [ 9645.327590] Lustre: DEBUG MARKER: == sanityn test 108a: lseek: parallel updates ============ 01:24:41 (1789190681) [ 9645.471618] LustreError: 389031:0:(osc_request.c:2990:osc_build_rpc()) cfs_fail_timeout id 414 sleeping for 4000ms [ 9645.473979] LustreError: 389031:0:(osc_request.c:2990:osc_build_rpc()) Skipped 6 previous similar messages [ 9649.535120] LustreError: 389031:0:(osc_request.c:2990:osc_build_rpc()) cfs_fail_timeout id 414 awake [ 9649.538374] LustreError: 389031:0:(osc_request.c:2990:osc_build_rpc()) Skipped 1 previous similar message [ 9651.662258] Lustre: DEBUG MARKER: == sanityn test 109: Race with several mount instances on 1 node ========================================================== 01:24:47 (1789190687) [ 9652.708096] Lustre: Unmounted lustre-client [ 9653.265060] Lustre: Unmounted lustre-client [ 9653.718274] Lustre: DEBUG MARKER: Iteration 0 [ 9653.815526] LustreError: 389923:0:(llite_lib.c:1508:ll_fill_super()) cfs_race id 1417 sleeping [ 9653.815726] LustreError: 389924:0:(llite_lib.c:1508:ll_fill_super()) cfs_fail_race id 1417 waking [ 9653.819855] LustreError: 389923:0:(llite_lib.c:1508:ll_fill_super()) cfs_fail_race id 1417 awake: rc=4998 [ 9653.852329] Lustre: Mounted lustre-client - version 2.17.58_39_g3d58bdf [ 9654.332477] Lustre: Unmounted lustre-client [ 9655.272939] Key type lgssc unregistered [ 9655.377437] LNet: 390264:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 9655.380743] LNetError: 390264:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 9655.388888] LNet: Removed LNI 192.168.202.36@tcp [ 9655.676086] Key type .llcrypt unregistered [ 9655.677622] Key type ._llcrypt unregistered [ 9655.922927] Key type ._llcrypt registered [ 9655.923929] Key type .llcrypt registered [ 9656.149590] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [ 9656.153815] alg: No test for adler32 (adler32-zlib) [ 9657.149206] Lustre: Lustre: Build Version: 2.17.58_39_g3d58bdf [ 9657.429935] LNet: Added LNI 192.168.202.36@tcp [8/256/0/180] [ 9659.047196] Key type lgssc registered [ 9659.520568] Lustre: Echo OBD driver; http://www.lustre.org/ [ 9663.656142] Lustre: DEBUG MARKER: Iteration 1 [ 9663.760344] LustreError: 391090:0:(llite_lib.c:1508:ll_fill_super()) cfs_race id 1417 sleeping [ 9663.766556] LustreError: 391096:0:(llite_lib.c:1508:ll_fill_super()) cfs_fail_race id 1417 waking [ 9663.768984] LustreError: 391090:0:(llite_lib.c:1508:ll_fill_super()) cfs_fail_race id 1417 awake: rc=4994 [ 9664.823494] Lustre: Mounted lustre-client - version 2.17.58_39_g3d58bdf [ 9664.825943] Lustre: Skipped 1 previous similar message [ 9665.388128] Lustre: Unmounted lustre-client [ 9666.367923] Key type lgssc unregistered [ 9666.478656] LNet: 391436:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 9666.480896] LNetError: 391436:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 9666.487908] LNet: Removed LNI 192.168.202.36@tcp [ 9666.741124] Key type .llcrypt unregistered [ 9666.742483] Key type ._llcrypt unregistered [ 9667.011303] Key type ._llcrypt registered [ 9667.012240] Key type .llcrypt registered [ 9667.222701] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [ 9667.227430] alg: No test for adler32 (adler32-zlib) [ 9668.079604] Lustre: Lustre: Build Version: 2.17.58_39_g3d58bdf [ 9668.159740] LNet: Added LNI 192.168.202.36@tcp [8/256/0/180] [ 9669.735173] Key type lgssc registered [ 9670.128791] Lustre: Echo OBD driver; http://www.lustre.org/ [ 9673.678310] Lustre: DEBUG MARKER: Iteration 2 [ 9673.789085] LustreError: 392263:0:(llite_lib.c:1508:ll_fill_super()) cfs_race id 1417 sleeping [ 9673.789124] LustreError: 392262:0:(llite_lib.c:1508:ll_fill_super()) cfs_fail_race id 1417 waking [ 9673.794870] LustreError: 392263:0:(llite_lib.c:1508:ll_fill_super()) cfs_fail_race id 1417 awake: rc=4997 [ 9674.840484] Lustre: Mounted lustre-client - version 2.17.58_39_g3d58bdf [ 9674.842880] Lustre: Skipped 1 previous similar message [ 9675.458306] Lustre: Unmounted lustre-client [ 9676.488925] Key type lgssc unregistered [ 9676.608516] LNet: 392604:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 9676.611913] LNetError: 392604:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 9676.620613] LNet: Removed LNI 192.168.202.36@tcp [ 9676.882184] Key type .llcrypt unregistered [ 9676.883330] Key type ._llcrypt unregistered [ 9677.175492] Key type ._llcrypt registered [ 9677.177289] Key type .llcrypt registered [ 9677.357555] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [ 9677.363408] alg: No test for adler32 (adler32-zlib) [ 9678.228040] Lustre: Lustre: Build Version: 2.17.58_39_g3d58bdf [ 9678.320187] LNet: Added LNI 192.168.202.36@tcp [8/256/0/180] [ 9679.911192] Key type lgssc registered [ 9680.294414] Lustre: Echo OBD driver; http://www.lustre.org/ [ 9684.564552] Lustre: Mounted lustre-client - version 2.17.58_39_g3d58bdf [ 9686.697128] Lustre: DEBUG MARKER: == sanityn test 110: do not grant another lock on resend ========================================================== 01:25:22 (1789190722) [ 9703.391155] Lustre: 393939:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789190723/real 1789190723] req@ffff9759367d1c00 x1876102442133376/t0(0) o36->lustre-MDT0000-mdc-ffff9759058e5000@192.168.202.136@tcp:12/10 lens 496/440 e 0 to 1 dl 1789190739 ref 2 fl Rpc:XQr/200/ffffffff rc 0/-1 job:'ln.0' uid:0 gid:0 projid:4294967295 [ 9703.402563] Lustre: lustre-MDT0000-mdc-ffff9759058e5000: Connection to lustre-MDT0000 (at 192.168.202.136@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 9703.412730] Lustre: lustre-MDT0000-mdc-ffff9759058e5000: Connection restored to 192.168.202.136@tcp (at 192.168.202.136@tcp) [ 9718.751114] Lustre: 393939:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789190739/real 1789190739] req@ffff9759367d1c00 x1876102442133376/t0(0) o36->lustre-MDT0000-mdc-ffff9759058e5000@192.168.202.136@tcp:12/10 lens 496/440 e 0 to 1 dl 1789190755 ref 2 fl Rpc:XQr/202/ffffffff rc 0/-1 job:'ln.0' uid:0 gid:0 projid:4294967295 [ 9718.761327] Lustre: lustre-MDT0000-mdc-ffff9759058e5000: Connection to lustre-MDT0000 (at 192.168.202.136@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 9718.772219] Lustre: lustre-MDT0000-mdc-ffff9759058e5000: Connection restored to 192.168.202.136@tcp (at 192.168.202.136@tcp) [ 9735.135154] Lustre: 393939:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789190755/real 1789190755] req@ffff9759367d1c00 x1876102442133376/t0(0) o36->lustre-MDT0000-mdc-ffff9759058e5000@192.168.202.136@tcp:12/10 lens 496/440 e 0 to 1 dl 1789190771 ref 2 fl Rpc:XQr/202/ffffffff rc 0/-1 job:'ln.0' uid:0 gid:0 projid:4294967295 [ 9735.143579] Lustre: lustre-MDT0000-mdc-ffff9759058e5000: Connection to lustre-MDT0000 (at 192.168.202.136@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 9735.153542] Lustre: lustre-MDT0000-mdc-ffff9759058e5000: Connection restored to 192.168.202.136@tcp (at 192.168.202.136@tcp) [ 9751.519121] Lustre: 393939:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789190771/real 1789190771] req@ffff9759367d1c00 x1876102442133376/t0(0) o36->lustre-MDT0000-mdc-ffff9759058e5000@192.168.202.136@tcp:12/10 lens 496/440 e 0 to 1 dl 1789190787 ref 2 fl Rpc:XQr/202/ffffffff rc 0/-1 job:'ln.0' uid:0 gid:0 projid:4294967295 [ 9751.526618] Lustre: lustre-MDT0000-mdc-ffff9759058e5000: Connection to lustre-MDT0000 (at 192.168.202.136@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 9751.535198] Lustre: lustre-MDT0000-mdc-ffff9759058e5000: Connection restored to 192.168.202.136@tcp (at 192.168.202.136@tcp) [ 9752.092794] Lustre: DEBUG MARKER: == sanityn test 111: A racy rename/link an open file should not cause fs corruption ========================================================== 01:26:27 (1789190787) [ 9757.838200] Lustre: DEBUG MARKER: == sanityn test 112: update max-inherit in default LMV === 01:26:33 (1789190793) [ 9760.983455] Lustre: DEBUG MARKER: == sanityn test 113: check servers of specified fs ======= 01:26:36 (1789190796) [ 9763.150375] Lustre: DEBUG MARKER: == sanityn test 114: implicit default LMV inherit ======== 01:26:38 (1789190798) [ 9770.153357] Lustre: DEBUG MARKER: == sanityn test 115: ldiskfs doesn't check direntry for uniqueness ========================================================== 01:26:45 (1789190805) [ 9782.594441] Lustre: DEBUG MARKER: == sanityn test 116: DNE: Set default LMV layout from a remote client ========================================================== 01:26:58 (1789190818) [ 9784.891788] Lustre: DEBUG MARKER: == sanityn test 121: trunc append race =================== 01:27:00 (1789190820) [ 9784.964760] LustreError: 398711:0:(lcommon_cl.c:99:cl_setattr_ost()) cfs_fail_timeout id 1436 sleeping for 2000ms [ 9787.047133] LustreError: 398711:0:(lcommon_cl.c:99:cl_setattr_ost()) cfs_fail_timeout id 1436 awake [ 9789.114024] Lustre: DEBUG MARKER: == sanityn test 122: directory size is consistent across mounts ========================================================== 01:27:04 (1789190824) [ 9793.766028] Lustre: DEBUG MARKER: == sanityn test 200: service remains healthy while able to process request ========================================================== 01:27:09 (1789190829) [ 9811.935198] Lustre: 392791:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789190832/real 1789190832] req@ffff97593e471f80 x1876102443177600/t0(0) o4->lustre-OST0000-osc-ffff9759058e5000@192.168.202.136@tcp:6/4 lens 4584/448 e 0 to 1 dl 1789190848 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'dd.0' uid:0 gid:0 projid:0 [ 9811.935198] Lustre: 392793:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789190832/real 1789190832] req@ffff975936f68000 x1876102443177216/t0(0) o4->lustre-OST0000-osc-ffff9759058e5000@192.168.202.136@tcp:6/4 lens 4584/448 e 0 to 1 dl 1789190848 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'dd.0' uid:0 gid:0 projid:0 [ 9811.935224] Lustre: 392791:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 9811.935242] Lustre: lustre-OST0000-osc-ffff9759058e5000: Connection to lustre-OST0000 (at 192.168.202.136@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 9811.939929] Lustre: lustre-OST0000-osc-ffff9759058e5000: Connection restored to 192.168.202.136@tcp (at 192.168.202.136@tcp) [ 9811.947416] Lustre: 392793:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 4 previous similar messages [ 9828.319210] Lustre: 392791:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789190848/real 1789190848] req@ffff97593e471f80 x1876102443177600/t0(0) o4->lustre-OST0000-osc-ffff9759058e5000@192.168.202.136@tcp:6/4 lens 4584/448 e 0 to 1 dl 1789190864 ref 2 fl Rpc:XQr/602/ffffffff rc -11/-1 job:'dd.0' uid:0 gid:0 projid:0 [ 9828.319254] Lustre: lustre-OST0000-osc-ffff9759058e5000: Connection to lustre-OST0000 (at 192.168.202.136@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 9828.327140] Lustre: 392791:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 9828.336708] Lustre: lustre-OST0000-osc-ffff9759058e5000: Connection restored to 192.168.202.136@tcp (at 192.168.202.136@tcp) [ 9844.703219] Lustre: lustre-OST0000-osc-ffff9759058e5000: Connection to lustre-OST0000 (at 192.168.202.136@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 9844.712896] Lustre: lustre-OST0000-osc-ffff9759058e5000: Connection restored to 192.168.202.136@tcp (at 192.168.202.136@tcp) [ 9861.087107] Lustre: 392791:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789190881/real 1789190881] req@ffff9759367d0a80 x1876102443176832/t0(0) o4->lustre-OST0000-osc-ffff9759058e5000@192.168.202.136@tcp:6/4 lens 4584/448 e 0 to 1 dl 1789190897 ref 2 fl Rpc:XQr/602/ffffffff rc -11/-1 job:'dd.0' uid:0 gid:0 projid:0 [ 9861.096442] Lustre: 392791:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 8 previous similar messages [ 9877.471159] Lustre: lustre-OST0000-osc-ffff9759058e5000: Connection to lustre-OST0000 (at 192.168.202.136@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 9877.475322] Lustre: Skipped 1 previous similar message [ 9877.482189] Lustre: lustre-OST0000-osc-ffff9759058e5000: Connection restored to 192.168.202.136@tcp (at 192.168.202.136@tcp) [ 9877.484695] Lustre: Skipped 1 previous similar message [ 9885.075588] Lustre: DEBUG MARKER: oleg236-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0000-osc-ffff9759058e5000.ost_server_uuid 50 [ 9885.551425] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9759058e5000.ost_server_uuid in FULL state after 0 sec [ 9886.092405] Lustre: DEBUG MARKER: cleanup: ====================================================== [ 9886.656790] Lustre: DEBUG MARKER: == sanityn test complete, duration 9586 sec ============== 01:28:42 (1789190922) [ 9887.168458] Lustre: DEBUG MARKER: === sanityn: start cleanup 01:28:43 (1789190923) === [ 9949.204109] Lustre: Unmounted lustre-client [ 9950.488467] Lustre: DEBUG MARKER: === sanityn: finish cleanup 01:29:46 (1789190986) === [ 9950.843732] Lustre: Unmounted lustre-client [ 9986.064864] Key type lgssc unregistered [ 9986.176522] LNet: 402746:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 9986.179146] LNetError: 402746:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 9986.187809] LNet: Removed LNI 192.168.202.36@tcp [ 9986.446100] Key type .llcrypt unregistered [ 9986.447268] Key type ._llcrypt unregistered