[ 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 421241659 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.001009] APIC: Switch to symmetric I/O mode setup [ 0.002301] x2apic enabled [ 0.003007] Switched APIC routing to physical x2apic. [ 0.004012] kvm-guest: setup PV IPIs [ 0.007000] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.007000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.007022] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.008012] pid_max: default: 32768 minimum: 301 [ 0.010126] LSM: Security Framework initializing [ 0.011068] Yama: becoming mindful. [ 0.012036] SELinux: Initializing. [ 0.013051] *** VALIDATE selinux *** [ 0.021598] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.026179] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.027134] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.028084] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.029133] *** VALIDATE tmpfs *** [ 0.030454] *** VALIDATE proc *** [ 0.032212] *** VALIDATE cgroup *** [ 0.033011] *** VALIDATE cgroup2 *** [ 0.034301] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.035130] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.036007] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.037030] Spectre V2 : User space: Vulnerable [ 0.038009] Speculative Store Bypass: Vulnerable [ 0.040958] debug: unmapping init [mem 0xffffffffafc59000-0xffffffffafc60fff] [ 0.041532] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.043238] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.044023] ... version: 2 [ 0.045013] ... bit width: 48 [ 0.046023] ... generic registers: 4 [ 0.047014] ... value mask: 0000ffffffffffff [ 0.048016] ... max period: 00007fffffffffff [ 0.049017] ... fixed-purpose events: 3 [ 0.050010] ... event mask: 000000070000000f [ 0.052232] rcu: Hierarchical SRCU implementation. [ 0.054437] smp: Bringing up secondary CPUs ... [ 0.055580] x86: Booting SMP configuration: [ 0.056025] .... node #0, CPUs: #1 #2 #3 [ 0.059449] smp: Brought up 1 node, 4 CPUs [ 0.061013] smpboot: Max logical packages: 1 [ 0.062020] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.233670] node 0 deferred pages initialised in 169ms [ 0.238347] devtmpfs: initialized [ 0.239223] x86/mm: Memory block size: 128MB [ 0.241864] gcov: version magic: 0x41383552 [ 0.242599] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.247115] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.250422] pinctrl core: initialized pinctrl subsystem [ 0.252257] [ 0.252948] ************************************************************* [ 0.256022] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.259017] ** ** [ 0.261017] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.264019] ** ** [ 0.267020] ** This means that this kernel is built to expose internal ** [ 0.270024] ** IOMMU data structures, which may compromise security on ** [ 0.272014] ** your system. ** [ 0.274019] ** ** [ 0.277018] ** If you see this message and you are not debugging the ** [ 0.281020] ** kernel, report this immediately to your vendor! ** [ 0.284014] ** ** [ 0.287017] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.290016] ************************************************************* [ 0.293851] NET: Registered protocol family 16 [ 0.295504] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.298081] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.301080] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.305138] cpuidle: using governor menu [ 0.306641] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.309400] PCI: Using configuration type 1 for base access [ 0.312121] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.321112] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.324041] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.330244] cryptd: max_cpu_qlen set to 1000 [ 0.332211] ACPI: Added _OSI(Module Device) [ 0.334019] ACPI: Added _OSI(Processor Device) [ 0.336012] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.338016] ACPI: Added _OSI(Processor Aggregator Device) [ 0.342574] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.348292] ACPI: Interpreter enabled [ 0.349050] ACPI: PM: (supports S0 S3 S4 S5) [ 0.352015] ACPI: Using IOAPIC for interrupt routing [ 0.353112] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.356369] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.366106] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.369046] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.371020] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.375084] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.379349] acpiphp: Slot [2] registered [ 0.381177] acpiphp: Slot [5] registered [ 0.382128] acpiphp: Slot [6] registered [ 0.383141] acpiphp: Slot [3] registered [ 0.384103] acpiphp: Slot [4] registered [ 0.386074] acpiphp: Slot [7] registered [ 0.387074] acpiphp: Slot [8] registered [ 0.388100] acpiphp: Slot [9] registered [ 0.389089] acpiphp: Slot [10] registered [ 0.390087] acpiphp: Slot [11] registered [ 0.391071] acpiphp: Slot [12] registered [ 0.393082] acpiphp: Slot [13] registered [ 0.394074] acpiphp: Slot [14] registered [ 0.395080] acpiphp: Slot [15] registered [ 0.396112] acpiphp: Slot [16] registered [ 0.398181] acpiphp: Slot [17] registered [ 0.400157] acpiphp: Slot [18] registered [ 0.402164] acpiphp: Slot [19] registered [ 0.404164] acpiphp: Slot [20] registered [ 0.406209] acpiphp: Slot [21] registered [ 0.408154] acpiphp: Slot [22] registered [ 0.409159] acpiphp: Slot [23] registered [ 0.411163] acpiphp: Slot [24] registered [ 0.413151] acpiphp: Slot [25] registered [ 0.415164] acpiphp: Slot [26] registered [ 0.416156] acpiphp: Slot [27] registered [ 0.418188] acpiphp: Slot [28] registered [ 0.420172] acpiphp: Slot [29] registered [ 0.421133] acpiphp: Slot [30] registered [ 0.423141] acpiphp: Slot [31] registered [ 0.425128] PCI host bridge to bus 0000:00 [ 0.427049] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.429070] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.431026] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.433025] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.435022] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.438023] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.439177] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.441932] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.444148] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.451016] pci 0000:00:01.1: reg 0x20: [io 0xc120-0xc12f] [ 0.454856] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.456018] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.459016] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.461027] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.463555] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.467306] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.471061] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.475879] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.481020] pci 0000:00:02.0: reg 0x10: [io 0xc100-0xc11f] [ 0.492025] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.496020] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.503086] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.508022] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.513957] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.533016] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.542591] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.551025] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.556019] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.573023] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.585601] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.588282] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.590387] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.591246] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.593187] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.598138] iommu: Default domain type: Passthrough [ 0.600305] SCSI subsystem initialized [ 0.601087] ACPI: bus type USB registered [ 0.602078] usbcore: registered new interface driver usbfs [ 0.604123] usbcore: registered new interface driver hub [ 0.605052] usbcore: registered new device driver usb [ 0.606118] pps_core: LinuxPPS API ver. 1 registered [ 0.607009] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.609071] PTP clock support registered [ 0.611150] EDAC MC: Ver: 3.0.0 [ 0.613184] PCI: Using ACPI for IRQ routing [ 0.615870] NetLabel: Initializing [ 0.617018] NetLabel: domain hash size = 128 [ 0.619018] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.621123] NetLabel: unlabeled traffic allowed by default [ 0.624048] vgaarb: loaded [ 0.625252] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.626012] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.631215] clocksource: Switched to clocksource kvm-clock [ 0.743245] VFS: Disk quotas dquot_6.6.0 [ 0.744807] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.747645] *** VALIDATE ramfs *** [ 0.749018] *** VALIDATE hugetlbfs *** [ 0.750518] pnp: PnP ACPI init [ 0.752867] pnp: PnP ACPI: found 6 devices [ 0.771516] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.775466] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.778162] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.780785] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.783186] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.785540] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.788363] NET: Registered protocol family 2 [ 0.791361] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.796841] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.800935] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.806640] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.810603] TCP: Hash tables configured (established 65536 bind 65536) [ 0.813871] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.817285] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.820773] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.824622] NET: Registered protocol family 1 [ 0.827540] RPC: Registered named UNIX socket transport module. [ 0.830062] RPC: Registered udp transport module. [ 0.832077] RPC: Registered tcp transport module. [ 0.834184] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.836835] NET: Registered protocol family 44 [ 0.838661] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.841102] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.843681] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.846193] PCI: CLS 0 bytes, default 64 [ 0.847832] Unpacking initramfs... [ 2.291422] debug: unmapping init [mem 0xffff96687cc64000-0xffff96687ffcffff] [ 2.300255] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.302857] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.308071] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 3.994769] Initialise system trusted keyrings [ 3.997620] Key type blacklist registered [ 4.002326] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 4.031806] zbud: loaded [ 4.037986] *** VALIDATE nfs *** [ 4.043955] *** VALIDATE nfs4 *** [ 4.051219] pstore: using deflate compression [ 4.062453] Platform Keyring initialized [ 4.393030] NET: Registered protocol family 38 [ 4.394990] Key type asymmetric registered [ 4.397633] Asymmetric key parser 'x509' registered [ 4.402893] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 4.409355] io scheduler mq-deadline registered [ 4.412729] io scheduler kyber registered [ 4.414232] io scheduler bfq registered [ 4.421373] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 4.434176] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 4.443484] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 4.448675] ACPI: Power Button [PWRF] [ 4.458475] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 4.473757] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 4.496510] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 4.535162] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 4.569384] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 4.598288] Non-volatile memory driver v1.3 [ 4.600418] Linux agpgart interface v0.103 [ 4.695502] virtio_blk virtio1: [vda] 149984 512-byte logical blocks (76.8 MB/73.2 MiB) [ 4.712050] vda: detected capacity change from 0 to 76791808 [ 4.756700] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 4.771418] vdb: detected capacity change from 0 to 1073741824 [ 4.806750] libphy: Fixed MDIO Bus: probed [ 4.824818] usbcore: registered new interface driver usbserial_generic [ 4.834097] usbserial: USB Serial support registered for generic [ 4.836655] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 4.860248] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 4.863378] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 4.866958] mousedev: PS/2 mouse device common for all mice [ 4.870959] rtc_cmos 00:05: RTC can wake from S4 [ 4.878506] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 4.885923] rtc_cmos 00:05: registered as rtc0 [ 4.890973] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 4.895788] intel_pstate: CPU model not supported [ 4.902381] hid: raw HID events driver (C) Jiri Kosina [ 4.903375] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 4.915802] usbcore: registered new interface driver usbhid [ 4.922838] usbhid: USB HID core driver [ 4.924926] drop_monitor: Initializing network drop monitor service [ 4.927881] Initializing XFRM netlink socket [ 4.931211] NET: Registered protocol family 10 [ 4.934196] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 4.941791] Segment Routing with IPv6 [ 4.953261] NET: Registered protocol family 17 [ 4.958471] mpls_gso: MPLS GSO support [ 4.980208] RAS: Correctable Errors collector initialized. [ 4.982616] AVX version of gcm_enc/dec engaged. [ 4.985667] AES CTR mode by8 optimization enabled [ 5.260509] sched_clock: Marking stable (5260479730, 0)->(6134066365, -873586635) [ 5.301818] registered taskstats version 1 [ 5.308069] Loading compiled-in X.509 certificates [ 5.314411] zswap: loaded using pool lzo/zbud [ 5.435540] Key type big_key registered [ 5.483464] Key type encrypted registered [ 5.485889] ima: No TPM chip found, activating TPM-bypass! [ 5.487648] ima: Allocated hash algorithm: sha1 [ 5.490881] ima: No architecture policies found [ 5.497260] evm: Initialising EVM extended attributes: [ 5.499886] evm: security.selinux [ 5.501471] evm: security.ima [ 5.502817] evm: security.capability [ 5.504662] evm: HMAC attrs: 0x1 [ 5.508299] rtc_cmos 00:05: setting system clock to 2026-09-10 14:02:04 UTC (1789048924) [ 5.548544] debug: unmapping init [mem 0xffffffffb0c03000-0xffffffffb0dfffff] [ 5.555823] debug: unmapping init [mem 0xffffffffaf982000-0xffffffffafc58fff] [ 5.564371] Write protecting the kernel read-only data: 28672k [ 5.570798] debug: unmapping init [mem 0xffffffffae003000-0xffffffffae1fffff] [ 5.575602] debug: unmapping init [mem 0xffffffffae914000-0xffffffffae9fffff] [ 5.639415] 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) [ 5.653963] systemd[1]: Detected virtualization kvm. [ 5.657648] systemd[1]: Detected architecture x86-64. [ 5.661163] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 5.696581] systemd[1]: No hostname configured. [ 5.700629] systemd[1]: Set hostname to . [ 5.704038] random: systemd: uninitialized urandom read (16 bytes read) [ 5.709244] systemd[1]: Initializing machine ID from random generator. [ 5.777848] random: ln: uninitialized urandom read (6 bytes read) [ 5.935924] random: systemd: uninitialized urandom read (16 bytes read) [ 5.941617] systemd[1]: Reached target Local File Systems. [ OK ] Reached target Local File Systems. [ 5.957120] systemd[1]: Listening on Journal Socket (/dev/log). [ OK ] Listening on Journal Socket (/dev/log). [ 5.974161] systemd[1]: Reached target Timers. [ OK ] Reached target Timers. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Listening on udev Control Socket. [ OK ] Reached target Swap. [ OK ] Listening on Journal Socket. Starting Create list of required st…ce nodes for the current kernel... Starting Setup Virtual Console... Starting Apply Kernel Variables... Starting Journal Service... [ OK ] Reached target Paths. [ OK ] Reached target Initrd Root Device. [ OK ] Started Memstrack Anylazing Service. [ OK ] Reached target Slices. [ OK ] Listening on udev Kernel Socket. [ OK ] Reached target Sockets. Starting Create Volatile Files and Directories... [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Setup Virtual Console. [ OK ] Started Apply Kernel Variables. [ OK ] Started Create Volatile Files and Directories. Starting dracut cmdline hook... [ 6.522497] hrtimer: interrupt took 9413410 ns Starting Create Static Device Nodes in /dev... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started Journal Service. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 7.829788] device-mapper: uevent: version 1.0.3 [ 7.841692] 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... [ 9.490681] virtio_net virtio0 ens2: renamed from eth0 [ 9.682929] scsi host0: ata_piix [ 9.718296] scsi host1: ata_piix [ 9.931627] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc120 irq 14 [ 9.935606] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc128 irq 15 [ 14.030441] random: crng init done [ 14.032037] random: 7 urandom warning(s) missed due to ratelimiting [ 15.779555] dracut-initqueue[585]: RTNETLINK answers: File exists 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. [ 18.266397] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped target Timers. [ OK ] Stopped target Initrd Root Device. Stopping Hardware RNG Entropy Gatherer Daemon... [ 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 udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. [ OK ] Stopped Apply Kernel Variables. Stopping udev Kernel Device Manager... [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Swap. [ OK ] Stopped target Local File Systems. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Closed udev Control Socket. [ OK ] Closed udev Kernel Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 20.988723] printk: systemd: 26 output lines suppressed due to ratelimiting [ 22.017712] SELinux: Disabled at runtime. [ 22.183794] 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) [ 22.212355] systemd[1]: Detected virtualization kvm. [ 22.232958] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 23.936565] systemd[1]: initrd-switch-root.service: Succeeded. [ 23.955835] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 23.971946] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 23.986652] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 24.002801] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 24.038690] systemd[1]: Starting Journal Service... Starting Journal Service... [ 24.075793] systemd[1]: Listening on Process Core Dump Socket. [ OK ] Listening on Process Core Dump Socket. [ OK ] Created slice system-getty.slice. [ OK ] Reached target rpc_pipefs.target. [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. Starting Remount Root and Kernel File Systems... [ OK ] Listening on RPCbind Server Activation Socket. Activating swap /dev/disk/by-label/SWAP... [ OK ] Listening on udev Kernel Socket. [ OK ] Listening on initctl Compatibility Named Pipe. Mounting Huge Pages File System... Starting Apply Kernel Variables... [ 24.495224] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Reached target RPC Port Mapper. Mounting Kernel Debug File System... [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd Root File System. [ OK ] Stopped target Initrd File Systems. [ OK ] Created slice User and Session Slice. [ OK ] Reached target Slices. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Created slice system-sshd\x2dkeygen.slice. Mounting POSIX Message Queue File System... [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Reached target Paths. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Listening on udev Control Socket. Starting udev Coldplug all Devices... [ OK ] Started Journal Service. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Mounted Huge Pages File System. [ OK ] Started Apply Kernel Variables. [ OK ] Mounted Kernel Debug File System. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Reached target Swap. Starting Create Static Device Nodes in /dev... Starting Configure read-only root support... Starting Flush Journal to Persistent Storage... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started udev Coldplug all Devices. Starting udev Kernel Device Manager... [ OK ] Reached target Local File Systems (Pre). Mounting /home/green/git/lustre-release... Mounting /mnt... [ OK ] Mounted /mnt. [ 25.684209] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 26.656365] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 26.773108] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 27.379316] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 27.534649] EDAC sbridge: Ver: 1.1.2 [ 30.589651] Key type dns_resolver registered [ 31.338337] NFS: Registering the id_resolver key type [ 31.340434] Key type id_resolver registered [ 31.344108] Key type id_legacy registered [* ] A start job is running for Configur…-only root support (7s / no limit) [ OK ] Started Configure read-only root support. Starting Load/Save Random Seed... [ OK ] Reached target Local File Systems. Starting Create Volatile Files and Directories... Starting Mark the need to relabel after reboot... Starting Rebuild Dynamic Linker Cache... [ OK ] Started Load/Save Random Seed. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Mark the need to relabel after reboot. Starting RPC Bind... Starting Update UTMP about System Boot/Shutdown... [ 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 ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Reached target Basic System. Starting Restore /run/initramfs on shutdown... [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Started irqbalance daemon. [ OK ] Started D-Bus System Message Bus. Starting Network Manager... [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Started dnf makecache --timer. [ OK ] Reached target Timers. Starting Login Service... [ OK ] Reached target sshd-keygen.target. [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Login Service. [ OK ] Started Network Manager. [ OK ] Reached target Network. Starting GSSAPI Proxy Daemon... Starting Dynamic System Tuning Daemon... Starting OpenSSH server daemon... Starting Network Manager Wait Online... [ OK ] Started OpenSSH server daemon. [ OK ] Started GSSAPI Proxy Daemon. Starting Hostname Service... [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... [ OK ] Started Permit User Sessions. [ OK ] Started Command Scheduler. [ OK ] Started Getty on tty1. [ OK ] Started Serial Getty on ttyS1. [ OK ] Started Serial Getty on ttyS0. [ 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 Notify NFS peers of a restart... Starting Crash recovery kernel arming... Starting System Logging Service... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg341-client login: [ 88.833708] libcfs: loading out-of-tree module taints kernel. [ 88.911958] Key type ._llcrypt registered [ 88.918926] Key type .llcrypt registered [ 89.470795] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [ 89.480122] alg: No test for adler32 (adler32-zlib) [ 90.898120] Lustre: Lustre: Build Version: 2.17.58_40_gb4686d2 [ 91.754799] LNet: Added LNI 192.168.203.41@tcp [8/256/0/180] [ 93.599204] Key type lgssc registered [ 95.170690] Lustre: Echo OBD driver; http://www.lustre.org/ [ 220.584672] Lustre: Mounted lustre-client - version 2.17.58_40_gb4686d2 [ 225.122382] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 235.012639] Lustre: DEBUG MARKER: oleg341-client.virtnet: executing check_logdir /tmp/testlogs/ [ 239.388089] Lustre: DEBUG MARKER: oleg341-client.virtnet: executing yml_node [ 243.234216] Lustre: DEBUG MARKER: Client: 2.17.58.40 [ 245.625314] Lustre: DEBUG MARKER: MDS: 2.17.58.40 [ 246.239233] Lustre: lustre-OST0000-osc-ffff9668d8375800: disconnect after 24s idle [ 247.808304] Lustre: DEBUG MARKER: OSS: 2.17.58.40 [ 249.461758] Lustre: DEBUG MARKER: -----============= acceptance-small: sanityn ============----- Thu Sep 10 10:06:07 EDT 2026 [ 264.750299] Lustre: DEBUG MARKER: excepting tests: 27 40a [ 266.263585] Lustre: DEBUG MARKER: skipping tests SLOW=no: 33a [ 267.747122] Lustre: DEBUG MARKER: === sanityn: start setup 10:06:25 (1789049185) === [ 268.413440] Lustre: Mounted lustre-client - version 2.17.58_40_gb4686d2 [ 273.778310] Lustre: DEBUG MARKER: oleg341-client.virtnet: executing check_config_client /mnt/lustre [ 290.206374] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 301.626117] Lustre: DEBUG MARKER: === sanityn: finish setup 10:06:58 (1789049218) === [ 303.866816] Lustre: DEBUG MARKER: == sanityn test 0: do_node_vp() and do_facet_vp() do the right thing ========================================================== 10:07:01 (1789049221) [ 312.420160] Lustre: DEBUG MARKER: == sanityn test 1: Check attribute updates on 2 mount points ========================================================== 10:07:10 (1789049230) [ 319.997775] Lustre: DEBUG MARKER: == sanityn test 2a: check cached attribute updates on 2 mtpt's ================================================================== 10:07:17 (1789049237) [ 327.815580] Lustre: DEBUG MARKER: == sanityn test 2b: check cached attribute updates on 2 mtpt's ================================================================== 10:07:25 (1789049245) [ 334.235407] Lustre: DEBUG MARKER: == sanityn test 2c: check cached attribute updates on 2 mtpt's root ============================================================= 10:07:31 (1789049251) [ 340.971599] Lustre: DEBUG MARKER: == sanityn test 2d: check cached attribute updates on 2 mtpt's root ============================================================= 10:07:38 (1789049258) [ 346.983263] Lustre: DEBUG MARKER: == sanityn test 2e: check chmod on root is propagated to others ========================================================== 10:07:44 (1789049264) [ 353.241603] Lustre: DEBUG MARKER: == sanityn test 2f: check attr/owner updates on DNE with 2 mtpt's ========================================================== 10:07:50 (1789049270) [ 354.531446] Lustre: DEBUG MARKER: SKIP: sanityn test_2f needs >= 2 MDTs [ 356.684414] Lustre: DEBUG MARKER: == sanityn test 2g: check blocks update on sync write ==== 10:07:53 (1789049273) [ 363.235534] Lustre: DEBUG MARKER: == sanityn test 3: symlink on one mtpt, readlink on another ===================================================================== 10:08:00 (1789049280) [ 369.356933] Lustre: DEBUG MARKER: == sanityn test 4: fstat validation on multiple mount points ==================================================================== 10:08:07 (1789049287) [ 376.019923] Lustre: DEBUG MARKER: == sanityn test 5: create a file on one mount, truncate it on the other ========================================================== 10:08:13 (1789049293) [ 381.408550] Lustre: lustre-OST0001-osc-ffff9668d8375800: disconnect after 24s idle [ 381.413246] Lustre: Skipped 1 previous similar message [ 381.562833] Lustre: DEBUG MARKER: == sanityn test 6: remove of open file on other node ============================================================================ 10:08:19 (1789049299) [ 387.151959] Lustre: DEBUG MARKER: == sanityn test 7: remove of open directory on other node ======================================================================= 10:08:25 (1789049305) [ 391.648530] Lustre: lustre-OST0000-osc-ffff9668d169d000: disconnect after 21s idle [ 392.452926] Lustre: DEBUG MARKER: == sanityn test 8: remove of open special file on other node ==================================================================== 10:08:30 (1789049310) [ 397.505937] Lustre: DEBUG MARKER: == sanityn test 9a: append of file with sub-page size on multiple mounts ========================================================== 10:08:35 (1789049315) [ 403.146317] Lustre: DEBUG MARKER: == sanityn test 9b: append to striped sparse file ======== 10:08:41 (1789049321) [ 409.103325] Lustre: DEBUG MARKER: == sanityn test 10a: write of file with sub-page size on multiple mounts ========================================================== 10:08:46 (1789049326) [ 417.706993] Lustre: DEBUG MARKER: == sanityn test 10b: write of file with sub-page size on multiple mounts ========================================================== 10:08:55 (1789049335) [ 424.044230] Lustre: DEBUG MARKER: == sanityn test 11: execution of file opened for write should return error ============================================================== 10:09:02 (1789049342) [ 430.425568] Lustre: DEBUG MARKER: == sanityn test 12: test lock ordering (link, stat, unlink) ========================================================== 10:09:07 (1789049347) [ 431.242416] Lustre: DEBUG MARKER: start dir: /mnt/lustre/lockdir=144115205272502304 file: /mnt/lustre/lockdir/lockfile=144115205272502302 [ 580.508740] Lustre: DEBUG MARKER: == sanityn test 13: test directory page revocation ======= 10:11:37 (1789049497) [ 588.268145] Lustre: DEBUG MARKER: == sanityn test 14aa: execution of file open for write returns -ETXTBSY ========================================================== 10:11:45 (1789049505) [ 594.715201] Lustre: DEBUG MARKER: == sanityn test 14ab: open(RDWR) of executing file returns -ETXTBSY ========================================================== 10:11:52 (1789049512) [ 600.499825] Lustre: DEBUG MARKER: == sanityn test 14b: truncate of executing file returns -ETXTBSY ================================================================ 10:11:58 (1789049518) [ 606.374408] Lustre: DEBUG MARKER: == sanityn test 14c: open(O_TRUNC) of executing file return -ETXTBSY ============================================================ 10:12:04 (1789049524) [ 611.849516] Lustre: DEBUG MARKER: == sanityn test 14d: chmod of executing file is still possible ================================================================== 10:12:09 (1789049529) [ 613.397978] Lustre: DEBUG MARKER: chmod [ 618.215855] Lustre: DEBUG MARKER: == sanityn test 15: test out-of-space with multiple writers ===================================================================== 10:12:16 (1789049536) [ 649.298450] Lustre: DEBUG MARKER: SKIP: oos2 test_15 oos2.sh: 7531520KB free > 800000KB, increase MAXFREE (or reduce fs size) [ 663.324743] Lustre: DEBUG MARKER: == sanityn test 16a: 500 iterations of dual-mount fsx ==== 10:13:01 (1789049581) [ 708.400414] Lustre: DEBUG MARKER: == sanityn test 16b: 500 iterations of dual-mount fsx at small size ========================================================== 10:13:46 (1789049626) [ 737.759823] Lustre: DEBUG MARKER: == sanityn test 16c: verify data consistency on ldiskfs with cache disabled (b=17397) ========================================================== 10:14:15 (1789049655) [ 739.723967] Lustre: DEBUG MARKER: SKIP: sanityn test_16c dio on ldiskfs only [ 741.343547] Lustre: DEBUG MARKER: == sanityn test 16d: Verify DIO and buffer IO with two clients ========================================================== 10:14:19 (1789049659) [ 782.850511] Lustre: DEBUG MARKER: == sanityn test 16e: Verify size consistency for O_DIRECT write ========================================================== 10:15:00 (1789049700) [ 788.612427] Lustre: DEBUG MARKER: == sanityn test 16f: rw sequential consistency vs drop_caches ========================================================== 10:15:06 (1789049706) [ 789.664718] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 789.770138] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 789.863713] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 789.955374] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 790.017960] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 790.100863] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 790.188763] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 790.268944] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 790.322479] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 790.387719] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 790.449306] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 790.500511] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 790.540869] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 790.639355] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 790.732582] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 790.835387] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 790.928959] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 791.051712] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 791.113897] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 791.199497] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 791.262319] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 791.321768] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 791.395083] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 791.474828] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 791.534974] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 791.586685] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 791.643423] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 791.711138] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 791.794974] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 791.850512] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 791.915987] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 791.974847] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 792.042746] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 792.093542] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 792.148387] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 792.237404] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 792.309809] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 792.380375] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 792.449734] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 792.514961] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 792.591232] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 792.650755] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 792.725989] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 792.792891] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 792.843879] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 792.887707] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 792.940610] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 792.994423] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 793.045886] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 793.119597] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 793.167173] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 793.234432] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 793.287777] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 793.345859] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 793.402174] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 793.478589] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 793.564396] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 793.647842] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 793.702769] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 793.766582] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 793.828593] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 793.911743] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 793.985716] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 794.075684] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 794.151391] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 794.242990] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 794.301449] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 794.372950] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 794.435678] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 794.497646] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 794.561024] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 794.646019] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 794.726514] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 794.799597] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 794.857709] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 794.949543] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 795.003372] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 795.068709] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 795.126129] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 795.187490] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 795.257564] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 795.323345] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 795.380878] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 795.441876] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 795.507171] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 795.586860] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 795.670186] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 795.744255] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 795.806439] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 795.850579] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 795.900697] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 795.953731] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 796.017506] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 796.082996] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 796.146212] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 796.223308] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 796.315592] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 796.421101] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 796.502808] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 796.597673] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 796.676166] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 796.735944] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 796.789793] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 796.853532] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 796.926868] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 797.038263] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 797.125178] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 797.234666] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 797.310110] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 797.409313] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 797.503306] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 797.636523] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 797.755104] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 797.859937] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 797.994091] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 798.064255] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 798.120959] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 798.195691] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 798.259744] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 798.327894] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 798.387812] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 798.454507] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 798.516816] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 798.570220] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 798.638981] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 798.700485] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 798.774093] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 798.856354] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 798.937305] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 799.028401] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 799.121845] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 799.189886] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 799.269206] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 799.359947] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 799.426557] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 799.478437] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 799.539217] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 799.599893] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 799.674786] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 799.745795] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 799.824083] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 799.925626] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 800.025768] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 800.098940] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 800.176845] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 800.236804] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 800.314997] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 800.381631] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 800.484766] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 800.559393] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 800.635330] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 800.696040] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 800.766403] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 800.842760] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 800.901578] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 800.975891] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 801.069853] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 801.130926] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 801.191269] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 801.272218] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 801.346625] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 801.429771] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 801.527589] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 801.620889] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 801.694245] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 801.788836] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 801.855087] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 801.941607] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 802.006715] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 802.111824] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 802.186734] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 802.282349] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 802.369760] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 802.435808] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 802.502690] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 802.580691] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 802.646971] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 802.717937] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 802.765840] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 802.828951] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 802.882916] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 802.958977] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 803.015982] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 803.073685] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 803.156239] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 803.241103] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 803.326503] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 803.399323] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 803.474315] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 803.526911] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 803.585940] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 803.656891] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 803.724905] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 803.785869] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 803.835359] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 803.890597] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 803.949985] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 804.009766] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 804.068168] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 804.124381] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 804.179923] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 804.250437] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 804.335612] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 804.396273] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 804.444816] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 804.508690] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 804.551915] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 804.615450] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 804.673906] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 804.749964] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 804.830903] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 804.897221] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 804.990021] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 805.071602] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 805.135750] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 805.209407] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 805.286316] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 805.350542] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 805.412765] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 805.485645] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 805.551033] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 805.631334] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 805.701959] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 805.771212] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 805.858803] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 805.920268] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 805.991327] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 806.043097] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 806.098751] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 806.151928] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 806.232841] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 806.348068] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 806.368604] Lustre: lustre-OST0001-osc-ffff9668d169d000: disconnect after 23s idle [ 806.470769] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 806.540618] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 806.582705] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 806.635620] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 806.673783] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 806.761980] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 806.839540] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 806.892819] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 806.941743] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 806.997546] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 807.071349] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 807.148825] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 807.219148] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 807.290840] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 807.351427] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 807.418923] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 807.488425] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 807.558529] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 807.652816] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 807.718478] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 807.804326] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 807.894932] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 807.982408] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 808.069750] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 808.127989] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 808.173486] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 808.256541] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 808.312819] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 808.361343] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 808.434375] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 808.497874] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 808.551933] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 808.617412] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 808.676683] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 808.732448] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 808.783535] rw_seq_cst_vs_d (29667): drop_caches: 3 [ 811.487600] Lustre: lustre-OST0001-osc-ffff9668d8375800: disconnect after 24s idle [ 815.684453] Lustre: DEBUG MARKER: == sanityn test 16g: mmap rw sequential consistency vs drop_caches ========================================================== 10:15:33 (1789049733) [ 816.109672] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 816.236587] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 816.293702] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 816.452340] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 816.504045] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 816.592855] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 816.630780] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 816.784445] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 816.870595] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 817.034030] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 817.156456] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 817.330937] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 817.423145] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 817.447565] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 817.631592] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 817.665333] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 817.759737] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 817.885860] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 817.950767] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 818.120664] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 818.232112] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 818.273872] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 818.368933] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 818.428326] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 818.664396] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 818.705975] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 818.743216] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 818.874630] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 818.910535] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 818.960810] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 819.001269] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 819.108878] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 819.239510] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 819.626472] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 819.746118] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 819.783080] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 819.816506] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 819.898908] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 819.944768] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 820.121586] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 820.156898] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 820.264806] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 820.393540] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 820.441598] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 820.488259] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 820.629563] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 820.788692] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 821.054710] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 821.107382] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 821.328125] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 821.367564] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 821.402962] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 821.476883] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 821.510635] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 821.555701] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 821.634435] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 821.692615] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 821.733425] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 821.939888] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 822.024229] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 822.137398] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 822.179043] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 822.229443] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 822.260939] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 822.300832] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 822.386374] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 822.505676] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 822.584494] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 822.781124] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 822.843445] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 822.891600] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 822.937691] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 823.001211] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 823.094463] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 823.147106] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 823.209143] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 823.341119] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 823.404219] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 823.453288] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 823.616524] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 823.777401] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 823.839444] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 823.879327] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 823.988904] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 824.052877] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 824.202564] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 824.266669] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 824.308323] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 824.350662] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 824.389862] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 824.515487] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 824.632246] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 824.730593] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 824.793582] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 824.848591] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 825.113648] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 825.214523] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 825.329469] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 825.399758] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 825.568734] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 825.610601] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 825.734356] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 825.901381] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 825.981363] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 826.083644] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 826.146818] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 826.231823] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 826.291260] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 826.398301] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 826.428330] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 826.695442] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 826.763947] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 826.836716] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 826.873627] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 826.998383] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 827.046920] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 827.102717] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 827.294309] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 827.420822] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 827.527631] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 827.568627] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 827.710396] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 827.897806] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 827.936208] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 828.014491] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 828.059544] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 828.144221] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 828.182364] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 828.308775] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 828.410407] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 828.458531] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 828.565733] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 828.650720] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 828.758550] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 828.799300] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 828.845949] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 828.982349] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 829.190361] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 829.290683] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 829.453616] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 829.539734] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 829.656787] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 829.717693] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 829.827200] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 829.933326] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 830.024790] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 830.222895] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 830.332570] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 830.368773] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 830.460424] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 830.528857] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 830.613986] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 830.680217] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 830.725796] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 830.798521] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 830.978267] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 831.119556] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 831.229984] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 831.277838] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 831.339722] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 831.430031] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 831.467148] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 831.503361] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 831.599850] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 831.648443] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 831.756474] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 831.805859] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 831.919603] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 831.967279] Lustre: lustre-OST0000-osc-ffff9668d169d000: disconnect after 23s idle [ 832.061540] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 832.106960] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 832.186348] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 832.262795] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 832.411547] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 832.513727] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 832.578119] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 832.622204] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 832.654598] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 832.694973] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 832.825806] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 832.885456] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 832.936477] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 832.984321] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 833.038537] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 833.093794] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 833.216770] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 833.271152] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 833.311126] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 833.351257] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 833.493828] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 833.542376] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 833.684597] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 833.914802] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 834.051301] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 834.109866] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 834.198678] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 834.248242] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 834.336425] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 834.405976] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 834.557173] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 834.629793] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 834.797297] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 834.935279] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 835.019106] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 835.054830] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 835.154534] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 835.196693] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 835.301947] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 835.416595] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 835.655697] rw_seq_cst_vs_d (30240): drop_caches: 3 [ 842.383629] Lustre: DEBUG MARKER: == sanityn test 16h: mmap read after truncate file ======= 10:16:00 (1789049760) [ 848.604726] Lustre: DEBUG MARKER: == sanityn test 16i: read after truncate file ============ 10:16:06 (1789049766) [ 854.850049] Lustre: DEBUG MARKER: == sanityn test 16j: race dio with buffered i/o ========== 10:16:12 (1789049772) [ 893.436379] Lustre: DEBUG MARKER: == sanityn test 16k: Parallel FSX and drop caches should not panic ========================================================== 10:16:51 (1789049811) [ 894.021644] bash (32688): drop_caches: 3 [ 897.302211] bash (32688): drop_caches: 3 [ 900.648575] bash (32688): drop_caches: 3 [ 904.736150] bash (32688): drop_caches: 3 [ 907.891673] bash (32688): drop_caches: 3 [ 911.079843] bash (32688): drop_caches: 3 [ 914.196590] bash (32688): drop_caches: 3 [ 917.332391] bash (32688): drop_caches: 3 [ 920.498876] bash (32688): drop_caches: 3 [ 923.602910] bash (32688): drop_caches: 3 [ 926.740119] bash (32688): drop_caches: 3 [ 929.943432] bash (32688): drop_caches: 3 [ 933.141395] bash (32688): drop_caches: 3 [ 936.330841] bash (32688): drop_caches: 3 [ 939.461104] bash (32688): drop_caches: 3 [ 942.667046] bash (32688): drop_caches: 3 [ 945.862550] bash (32688): drop_caches: 3 [ 951.451278] Lustre: DEBUG MARKER: == sanityn test 17: resource creation/LVB creation race ========================================================================= 10:17:48 (1789049868) [ 962.618645] Lustre: DEBUG MARKER: == sanityn test 18: mmap sanity check =========================================================================================== 10:17:59 (1789049879) [ 986.700203] Lustre: DEBUG MARKER: == sanityn test 19: test concurrent uncached read races ========================================================================= 10:18:24 (1789049904) [ 989.245632] Lustre: DEBUG MARKER: SKIP: sanityn test_19 not cache-capable obdfilter [ 990.701363] Lustre: DEBUG MARKER: == sanityn test 20: test extra readahead page left in cache ============================================================== 10:18:28 (1789049908) [ 997.315223] Lustre: DEBUG MARKER: == sanityn test 21: Try to remove mountpoint on another dir ============================================================== 10:18:34 (1789049914) [ 1000.930204] Lustre: lustre-OST0001-osc-ffff9668d8375800: disconnect after 22s idle [ 1000.938177] Lustre: Skipped 1 previous similar message [ 1002.986502] Lustre: DEBUG MARKER: == sanityn test 23: others should see updated atime while another read============================================================== 10:18:40 (1789049920) [ 1070.446685] Lustre: DEBUG MARKER: == sanityn test 24a: lfs df [-ih] [path] test =================================================================================== 10:19:48 (1789049988) [ 1076.312848] Lustre: DEBUG MARKER: == sanityn test 24b: lfs df should show both filesystems ========================================================================= 10:19:54 (1789049994) [ 1082.142404] Lustre: DEBUG MARKER: == sanityn test 25a: change ACL on one mountpoint be seen on another ============================================================= 10:19:59 (1789049999) [ 1089.140306] Lustre: DEBUG MARKER: == sanityn test 25b: change ACL under remote dir on one mountpoint be seen on another ========================================================== 10:20:06 (1789050006) [ 1090.409654] Lustre: DEBUG MARKER: SKIP: sanityn test_25b needs >= 2 MDTs [ 1092.081867] Lustre: DEBUG MARKER: == sanityn test 26a: allow mtime to get older ============ 10:20:09 (1789050009) [ 1098.182701] Lustre: DEBUG MARKER: == sanityn test 26b: sync mtime between ost and mds ====== 10:20:16 (1789050016) [ 1098.210219] Lustre: lustre-OST0001-osc-ffff9668d8375800: disconnect after 22s idle [ 1098.224047] Lustre: Skipped 4 previous similar messages [ 1106.499732] Lustre: DEBUG MARKER: == sanityn test 26c: set-in-past on open file is not lost on close ========================================================== 10:20:24 (1789050024) [ 1114.188751] Lustre: DEBUG MARKER: SKIP: sanityn test_27 skipping excluded test 27 [ 1116.032751] Lustre: DEBUG MARKER: == sanityn test 30: recreate file race =================== 10:20:33 (1789050033) [ 1125.831730] Lustre: DEBUG MARKER: == sanityn test 31a: voluntary cancel / blocking ast race======================================================================== 10:20:43 (1789050043) [ 1126.344235] Lustre: *** cfs_fail_loc=314, val=0*** [ 1127.392728] Lustre: *** cfs_fail_loc=314, val=0*** [ 1127.406220] Lustre: Skipped 2 previous similar messages [ 1134.889852] Lustre: DEBUG MARKER: == sanityn test 31b: voluntary OST cancel / blocking ast race======================================================================== 10:20:52 (1789050052) [ 1150.385755] Lustre: *** cfs_fail_loc=314, val=0*** [ 1150.516258] LustreError: lustre-OST0000-osc-ffff9668d169d000: operation ldlm_enqueue to node 192.168.203.141@tcp failed: rc = -107 [ 1150.524501] Lustre: lustre-OST0000-osc-ffff9668d169d000: Connection to lustre-OST0000 (at 192.168.203.141@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1150.570386] LustreError: lustre-OST0000-osc-ffff9668d169d000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 1150.602483] Lustre: 2358:0:(llite_lib.c:4353:ll_dirty_page_discard_warn()) lustre: dirty page discard: 192.168.203.141@tcp:/lustre/fid: [0x200000402:0x26:0x0]// may get corrupted (rc -108) [ 1150.641756] LustreError: 41980:0:(ldlm_resource.c:1208:ldlm_resource_complain()) lustre-OST0000-osc-ffff9668d169d000: namespace resource [0x240000400:0x35:0x0].0x0 (ffff9668d2ad8800) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 1150.665445] Lustre: lustre-OST0000-osc-ffff9668d169d000: Connection restored to 192.168.203.141@tcp (at 192.168.203.141@tcp) [ 1157.420278] Lustre: DEBUG MARKER: == sanityn test 31r: open-rename(replace) race =========== 10:21:15 (1789050075) [ 1157.694251] LustreError: 42562:0:(file.c:850:ll_intent_file_open()) cfs_fail_timeout id 1419 sleeping for 3000ms [ 1160.735325] LustreError: 42562:0:(file.c:850:ll_intent_file_open()) cfs_fail_timeout id 1419 awake [ 1166.084217] Lustre: DEBUG MARKER: == sanityn test 31s: open should not revalidate invalid dentry ========================================================== 10:21:23 (1789050083) [ 1172.530991] Lustre: DEBUG MARKER: == sanityn test 31t: getattr should not revalidate invalid dentry ========================================================== 10:21:30 (1789050090) [ 1179.417271] Lustre: DEBUG MARKER: == sanityn test 32b: lockless i/o ======================== 10:21:37 (1789050097) [ 1181.002781] Lustre: DEBUG MARKER: SKIP: sanityn test_32b max_nolock_bytes is removed >= 2.17.53 [ 1182.533963] Lustre: DEBUG MARKER: == sanityn test 32c: contention detection ================ 10:21:40 (1789050100) [ 1207.876946] Lustre: DEBUG MARKER: SKIP: sanityn test_33a skipping SLOW test 33a [ 1209.522389] Lustre: DEBUG MARKER: == sanityn test 33b: COS: cross create/delete, 2 clients, benchmark under remote dir ========================================================== 10:22:07 (1789050127) [ 1210.997419] Lustre: DEBUG MARKER: SKIP: sanityn test_33b Need two or more clients, have 1 [ 1212.576743] Lustre: DEBUG MARKER: == sanityn test 33c: Cancel cross-MDT lock should trigger Sync-on-Lock-Cancel ========================================================== 10:22:10 (1789050130) [ 1214.122609] Lustre: DEBUG MARKER: SKIP: sanityn test_33c needs >= 2 MDTs [ 1215.766708] Lustre: DEBUG MARKER: == sanityn test 33d: dependent transactions should trigger COS ========================================================== 10:22:13 (1789050133) [ 1215.972238] Lustre: lustre-OST0001-osc-ffff9668d8375800: disconnect after 20s idle [ 1215.983954] Lustre: Skipped 1 previous similar message [ 1217.147532] Lustre: DEBUG MARKER: SKIP: sanityn test_33d needs >= 2 MDTs [ 1218.828521] Lustre: DEBUG MARKER: == sanityn test 33e: independent transactions shouldn't trigger COS ========================================================== 10:22:16 (1789050136) [ 1220.308497] Lustre: DEBUG MARKER: SKIP: sanityn test_33e needs >= 2 MDTs [ 1222.004720] Lustre: DEBUG MARKER: == sanityn test 34: no lock timeout under IO ============= 10:22:19 (1789050139) [ 1276.360216] Lustre: lustre-OST0001-osc-ffff9668d169d000: Connection to lustre-OST0001 (at 192.168.203.141@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1276.395363] LustreError: lustre-OST0001-osc-ffff9668d8375800: This client was evicted by lustre-OST0001; in progress operations using this service will fail. [ 1276.409204] LustreError: lustre-OST0001-osc-ffff9668d169d000: This client was evicted by lustre-OST0001; in progress operations using this service will fail. [ 1276.411098] Lustre: lustre-OST0001-osc-ffff9668d8375800: Connection restored to 192.168.203.141@tcp (at 192.168.203.141@tcp) [ 1276.446689] Lustre: Skipped 1 previous similar message [ 1291.750174] Lustre: lustre-OST0000-osc-ffff9668d8375800: Connection to lustre-OST0000 (at 192.168.203.141@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1291.762519] Lustre: Skipped 1 previous similar message [ 1291.781424] LustreError: lustre-OST0000-osc-ffff9668d8375800: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 1291.791056] Lustre: lustre-OST0000-osc-ffff9668d8375800: Connection restored to 192.168.203.141@tcp (at 192.168.203.141@tcp) [ 1310.240842] Lustre: DEBUG MARKER: oleg341-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0000-osc-ffff9668d169d000.ost_server_uuid 50 [ 1311.864722] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9668d169d000.ost_server_uuid in FULL state after 0 sec [ 1318.539407] Lustre: DEBUG MARKER: oleg341-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0001-osc-ffff9668d169d000.ost_server_uuid 50 [ 1320.033770] Lustre: DEBUG MARKER: osc.lustre-OST0001-osc-ffff9668d169d000.ost_server_uuid in IDLE state after 0 sec [ 1327.430924] Lustre: DEBUG MARKER: oleg341-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0000-osc-ffff9668d169d000.ost_server_uuid 50 [ 1329.224439] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9668d169d000.ost_server_uuid in FULL state after 0 sec [ 1334.607657] Lustre: DEBUG MARKER: oleg341-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0001-osc-ffff9668d169d000.ost_server_uuid 50 [ 1335.942549] Lustre: DEBUG MARKER: osc.lustre-OST0001-osc-ffff9668d169d000.ost_server_uuid in IDLE state after 0 sec [ 1347.982370] Lustre: DEBUG MARKER: oleg341-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0000-osc-ffff9668d169d000.ost_server_uuid 50 [ 1349.616400] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9668d169d000.ost_server_uuid in FULL state after 0 sec [ 1354.781520] Lustre: DEBUG MARKER: oleg341-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0001-osc-ffff9668d169d000.ost_server_uuid 50 [ 1356.101337] Lustre: DEBUG MARKER: osc.lustre-OST0001-osc-ffff9668d169d000.ost_server_uuid in IDLE state after 0 sec [ 1358.325965] Lustre: DEBUG MARKER: == sanityn test 35: -EINTR cp_ast vs. bl_ast race does not evict client ========================================================== 10:24:35 (1789050275) [ 1360.920994] Lustre: DEBUG MARKER: Race attempt 0 [ 1363.716952] Lustre: DEBUG MARKER: Wait for 50438 50473 for 60 sec... [ 1430.289445] Lustre: DEBUG MARKER: == sanityn test 36: handle ESTALE/open-unlink correctly == 10:25:47 (1789050347) [ 1437.864151] Lustre: DEBUG MARKER: start test - cycle (0) [ 1466.847362] Lustre: lustre-OST0000-osc-ffff9668d8375800: disconnect after 21s idle [ 1466.855253] Lustre: Skipped 6 previous similar messages [ 1467.325301] Lustre: DEBUG MARKER: start test - cycle (1) [ 1493.160502] Lustre: DEBUG MARKER: start test - cycle (2) [ 1518.719104] Lustre: DEBUG MARKER: start test - cycle (3) [ 1537.298674] Lustre: DEBUG MARKER: start test - cycle (4) [ 1565.256489] Lustre: DEBUG MARKER: start test - cycle (5) [ 1593.184883] Lustre: DEBUG MARKER: start test - cycle (6) [ 1619.674756] Lustre: DEBUG MARKER: start test - cycle (7) [ 1647.402738] Lustre: DEBUG MARKER: start test - cycle (8) [ 1677.560287] Lustre: DEBUG MARKER: start test - cycle (9) [ 1695.699739] Lustre: DEBUG MARKER: start test - cycle (10) [ 1722.851461] Lustre: lustre-OST0000-osc-ffff9668d8375800: disconnect after 20s idle [ 1722.867394] Lustre: Skipped 13 previous similar messages [ 1731.896381] Lustre: DEBUG MARKER: == sanityn test 37: check i_size is not updated for directory on close (bug 18695) ======================================================================== 10:30:49 (1789050649) [ 1817.753154] Lustre: DEBUG MARKER: == sanityn test 39a: file mtime does not change after rename ========================================================== 10:32:15 (1789050735) [ 1824.408252] Lustre: DEBUG MARKER: == sanityn test 39b: file mtime the same on clients with/out lock ========================================================== 10:32:22 (1789050742) [ 1831.927032] Lustre: DEBUG MARKER: == sanityn test 39c: check truncate mtime update ================================================================================ 10:32:29 (1789050749) [ 1839.271389] Lustre: DEBUG MARKER: == sanityn test 39d: sync write should update mtime ====== 10:32:36 (1789050756) [ 1839.567670] Lustre: *** cfs_fail_loc=411, val=0*** [ 1845.673774] Lustre: DEBUG MARKER: SKIP: sanityn test_40a skipping ALWAYS excluded test 40a [ 1847.948260] Lustre: DEBUG MARKER: == sanityn test 40b: pdirops: open|create and others ======================================================================== 10:32:45 (1789050765) [ 1865.448488] Lustre: DEBUG MARKER: == sanityn test 40c: pdirops: link and others ======================================================================== 10:33:03 (1789050783) [ 1880.536730] Lustre: DEBUG MARKER: == sanityn test 40d: pdirops: unlink and others ======================================================================== 10:33:18 (1789050798) [ 1896.362146] Lustre: DEBUG MARKER: == sanityn test 40e: pdirops: rename and others ======================================================================== 10:33:33 (1789050813) [ 1912.400791] Lustre: DEBUG MARKER: == sanityn test 41a: pdirops: create vs mkdir ======================================================================== 10:33:50 (1789050830) [ 1926.239083] Lustre: DEBUG MARKER: == sanityn test 41b: pdirops: create vs create ======================================================================== 10:34:03 (1789050843) [ 1939.891854] Lustre: DEBUG MARKER: == sanityn test 41c: pdirops: create vs link ======================================================================== 10:34:17 (1789050857) [ 1953.339137] Lustre: DEBUG MARKER: == sanityn test 41d: pdirops: create vs unlink ======================================================================== 10:34:30 (1789050870) [ 1965.415848] Lustre: DEBUG MARKER: == sanityn test 41e: pdirops: create and rename (tgt) ======================================================================== 10:34:43 (1789050883) [ 1979.147891] Lustre: DEBUG MARKER: == sanityn test 41f: pdirops: create and rename (src) ======================================================================== 10:34:56 (1789050896) [ 1990.897157] Lustre: DEBUG MARKER: == sanityn test 41g: pdirops: create vs getattr ======================================================================== 10:35:08 (1789050908) [ 2003.421288] Lustre: DEBUG MARKER: == sanityn test 41h: pdirops: create vs readdir ======================================================================== 10:35:21 (1789050921) [ 2016.089755] Lustre: DEBUG MARKER: == sanityn test 41i: reint_open: create vs create ======== 10:35:33 (1789050933) [ 2634.207290] Lustre: lustre-OST0000-osc-ffff9668d169d000: disconnect after 21s idle [ 2634.214283] Lustre: Skipped 13 previous similar messages [ 3066.265375] Lustre: DEBUG MARKER: == sanityn test 42a: pdirops: mkdir vs mkdir ======================================================================== 10:53:03 (1789051983) [ 3083.189120] Lustre: DEBUG MARKER: == sanityn test 42b: pdirops: mkdir vs create ======================================================================== 10:53:20 (1789052000) [ 3094.645574] Lustre: DEBUG MARKER: == sanityn test 42c: pdirops: mkdir vs link ======================================================================== 10:53:32 (1789052012) [ 3107.991487] Lustre: DEBUG MARKER: == sanityn test 42d: pdirops: mkdir vs unlink ======================================================================== 10:53:45 (1789052025) [ 3123.194039] Lustre: DEBUG MARKER: == sanityn test 42e: pdirops: mkdir and rename (tgt) ======================================================================== 10:54:00 (1789052040) [ 3140.647252] Lustre: DEBUG MARKER: == sanityn test 42f: pdirops: mkdir and rename (src) ======================================================================== 10:54:18 (1789052058) [ 3156.380362] Lustre: DEBUG MARKER: == sanityn test 42g: pdirops: mkdir vs getattr ======================================================================== 10:54:33 (1789052073) [ 3169.684865] Lustre: DEBUG MARKER: == sanityn test 42h: pdirops: mkdir vs readdir ======================================================================== 10:54:47 (1789052087) [ 3181.666598] Lustre: DEBUG MARKER: == sanityn test 43a: rmdir,mkdir doesn't return -EEXIST ======================================================================== 10:54:59 (1789052099) [ 3253.847665] Lustre: DEBUG MARKER: == sanityn test 43b: pdirops: unlink vs create ======================================================================== 10:56:11 (1789052171) [ 3266.763120] Lustre: DEBUG MARKER: == sanityn test 43c: pdirops: unlink vs link ======================================================================== 10:56:24 (1789052184) [ 3280.042466] Lustre: DEBUG MARKER: == sanityn test 43d: pdirops: unlink vs unlink ======================================================================== 10:56:37 (1789052197) [ 3293.699250] Lustre: DEBUG MARKER: == sanityn test 43e: pdirops: unlink and rename (tgt) ======================================================================== 10:56:51 (1789052211) [ 3294.687140] Lustre: lustre-OST0000-osc-ffff9668d8375800: disconnect after 20s idle [ 3294.703672] Lustre: Skipped 4 previous similar messages [ 3308.008853] Lustre: DEBUG MARKER: == sanityn test 43f: pdirops: unlink and rename (src) ======================================================================== 10:57:05 (1789052225) [ 3323.092330] Lustre: DEBUG MARKER: == sanityn test 43g: pdirops: unlink vs getattr ======================================================================== 10:57:20 (1789052240) [ 3337.805019] Lustre: DEBUG MARKER: == sanityn test 43h: pdirops: unlink vs readdir ======================================================================== 10:57:35 (1789052255) [ 3352.188729] Lustre: DEBUG MARKER: == sanityn test 43i: pdirops: unlink vs remote mkdir ===== 10:57:49 (1789052269) [ 3354.209819] Lustre: DEBUG MARKER: SKIP: sanityn test_43i needs >= 2 MDTs [ 3356.844489] Lustre: DEBUG MARKER: == sanityn test 43j: racy mkdir return EEXIST ======================================================================== 10:57:53 (1789052273) [ 3501.400928] Lustre: DEBUG MARKER: == sanityn test 43k: unlink vs create ==================== 11:00:18 (1789052418) [ 3950.052777] Lustre: lustre-OST0001-osc-ffff9668d8375800: disconnect after 21s idle [ 3950.062040] Lustre: Skipped 5 previous similar messages [ 4744.824868] Lustre: DEBUG MARKER: == sanityn test 44a: pdirops: rename tgt vs mkdir ======================================================================== 11:21:02 (1789053662) [ 4748.767218] Lustre: lustre-OST0001-osc-ffff9668d169d000: disconnect after 22s idle [ 4748.776101] Lustre: Skipped 5 previous similar messages [ 4756.866666] Lustre: DEBUG MARKER: == sanityn test 44b: pdirops: rename tgt vs create ======================================================================== 11:21:14 (1789053674) [ 4769.064265] Lustre: DEBUG MARKER: == sanityn test 44c: pdirops: rename tgt vs link ======================================================================== 11:21:26 (1789053686) [ 4781.428055] Lustre: DEBUG MARKER: == sanityn test 44d: pdirops: rename tgt vs unlink ======================================================================== 11:21:39 (1789053699) [ 4792.968216] Lustre: DEBUG MARKER: == sanityn test 44e: pdirops: rename tgt and rename (tgt) ======================================================================== 11:21:50 (1789053710) [ 4804.872834] Lustre: DEBUG MARKER: == sanityn test 44f: pdirops: rename tgt and rename (src) ======================================================================== 11:22:02 (1789053722) [ 4818.176809] Lustre: DEBUG MARKER: == sanityn test 44g: pdirops: rename tgt vs getattr ======================================================================== 11:22:15 (1789053735) [ 4833.174605] Lustre: DEBUG MARKER: == sanityn test 44h: pdirops: rename tgt vs readdir ======================================================================== 11:22:30 (1789053750) [ 4847.533572] Lustre: DEBUG MARKER: == sanityn test 44i: pdirops: rename tgt vs remote mkdir ========================================================== 11:22:44 (1789053764) [ 4849.666052] Lustre: DEBUG MARKER: SKIP: sanityn test_44i needs >= 2 MDTs [ 4852.019797] Lustre: DEBUG MARKER: == sanityn test 45a: rename,mkdir doesn't return -EEXIST ======================================================================== 11:22:49 (1789053769) [ 4993.513243] Lustre: DEBUG MARKER: == sanityn test 45b: pdirops: rename src vs create ======================================================================== 11:25:10 (1789053910) [ 5009.315639] Lustre: DEBUG MARKER: == sanityn test 45c: pdirops: rename src vs link ======================================================================== 11:25:27 (1789053927) [ 5021.035861] Lustre: DEBUG MARKER: == sanityn test 45d: pdirops: rename src vs unlink ======================================================================== 11:25:38 (1789053938) [ 5035.028390] Lustre: DEBUG MARKER: == sanityn test 45e: pdirops: rename src and rename (tgt) ======================================================================== 11:25:52 (1789053952) [ 5050.226201] Lustre: DEBUG MARKER: == sanityn test 45f: pdirops: rename src and rename (src) ======================================================================== 11:26:07 (1789053967) [ 5065.121863] Lustre: DEBUG MARKER: == sanityn test 45g: pdirops: rename src vs getattr ======================================================================== 11:26:22 (1789053982) [ 5080.450709] Lustre: DEBUG MARKER: == sanityn test 45h: pdirops: unlink vs readdir ======================================================================== 11:26:37 (1789053997) [ 5094.904396] Lustre: DEBUG MARKER: == sanityn test 45i: pdirops: rename src vs remote mkdir ========================================================== 11:26:52 (1789054012) [ 5096.530124] Lustre: DEBUG MARKER: SKIP: sanityn test_45i needs >= 2 MDTs [ 5098.987991] Lustre: DEBUG MARKER: == sanityn test 45j: read vs rename ====================== 11:26:56 (1789054016) [ 5521.887210] Lustre: lustre-OST0000-osc-ffff9668d8375800: disconnect after 20s idle [ 5521.901222] Lustre: Skipped 12 previous similar messages [ 6286.311484] Lustre: DEBUG MARKER: == sanityn test 46a: pdirops: link vs mkdir ======================================================================== 11:46:44 (1789055204) [ 6297.977904] Lustre: DEBUG MARKER: == sanityn test 46b: pdirops: link vs create ======================================================================== 11:46:55 (1789055215) [ 6300.127223] Lustre: lustre-OST0000-osc-ffff9668d169d000: disconnect after 24s idle [ 6300.130376] Lustre: Skipped 1 previous similar message [ 6310.508198] Lustre: DEBUG MARKER: == sanityn test 46c: pdirops: link vs link ======================================================================== 11:47:08 (1789055228) [ 6322.456544] Lustre: DEBUG MARKER: == sanityn test 46d: pdirops: link vs unlink ======================================================================== 11:47:20 (1789055240) [ 6334.672347] Lustre: DEBUG MARKER: == sanityn test 46e: pdirops: link and rename (tgt) ======================================================================== 11:47:32 (1789055252) [ 6348.517431] Lustre: DEBUG MARKER: == sanityn test 46f: pdirops: link and rename (src) ======================================================================== 11:47:45 (1789055265) [ 6361.553847] Lustre: DEBUG MARKER: == sanityn test 46g: pdirops: link vs getattr ======================================================================== 11:47:59 (1789055279) [ 6373.975976] Lustre: DEBUG MARKER: == sanityn test 46h: pdirops: link vs readdir ======================================================================== 11:48:11 (1789055291) [ 6386.031861] Lustre: DEBUG MARKER: == sanityn test 46i: pdirops: link vs remote mkdir ======= 11:48:23 (1789055303) [ 6387.300477] Lustre: DEBUG MARKER: SKIP: sanityn test_46i needs >= 2 MDTs [ 6389.176919] Lustre: DEBUG MARKER: == sanityn test 47a: pdirops: remote mkdir vs mkdir ====== 11:48:26 (1789055306) [ 6390.680622] Lustre: DEBUG MARKER: SKIP: sanityn test_47a needs >= 2 MDTs [ 6392.569498] Lustre: DEBUG MARKER: == sanityn test 47b: pdirops: remote mkdir vs create ===== 11:48:30 (1789055310) [ 6394.055990] Lustre: DEBUG MARKER: SKIP: sanityn test_47b needs >= 2 MDTs [ 6395.563968] Lustre: DEBUG MARKER: == sanityn test 47c: pdirops: remote mkdir vs link ======= 11:48:33 (1789055313) [ 6396.858623] Lustre: DEBUG MARKER: SKIP: sanityn test_47c needs >= 2 MDTs [ 6399.064663] Lustre: DEBUG MARKER: == sanityn test 47d: pdirops: remote mkdir vs unlink ===== 11:48:36 (1789055316) [ 6400.731102] Lustre: DEBUG MARKER: SKIP: sanityn test_47d needs >= 2 MDTs [ 6402.566816] Lustre: DEBUG MARKER: == sanityn test 47e: pdirops: remote mkdir and rename (tgt) ========================================================== 11:48:40 (1789055320) [ 6403.740962] Lustre: DEBUG MARKER: SKIP: sanityn test_47e needs >= 2 MDTs [ 6405.228827] Lustre: DEBUG MARKER: == sanityn test 47f: pdirops: remote mkdir and rename (src) ========================================================== 11:48:43 (1789055323) [ 6406.821842] Lustre: DEBUG MARKER: SKIP: sanityn test_47f needs >= 2 MDTs [ 6408.287462] Lustre: DEBUG MARKER: == sanityn test 47g: pdirops: remote mkdir vs getattr ==== 11:48:46 (1789055326) [ 6409.944474] Lustre: DEBUG MARKER: SKIP: sanityn test_47g needs >= 2 MDTs [ 6411.977501] Lustre: DEBUG MARKER: == sanityn test 50: osc lvb attrs: enqueue vs. CP AST ======================================================================== 11:48:49 (1789055329) [ 6412.360535] LustreError: 5585:0:(ldlm_lockd.c:2079:ldlm_handle_cp_callback()) cfs_fail_timeout id 410 sleeping for 2000ms [ 6414.455793] LustreError: 5585:0:(ldlm_lockd.c:2079:ldlm_handle_cp_callback()) cfs_fail_timeout id 410 awake [ 6423.642099] Lustre: DEBUG MARKER: == sanityn test 51a: layout lock: refresh layout should work ========================================================== 11:49:01 (1789055341) [ 6431.420879] Lustre: DEBUG MARKER: == sanityn test 51b: layout lock: glimpse should be able to restart if layout changed ========================================================== 11:49:09 (1789055349) [ 6431.726302] LustreError: 219267:0:(glimpse.c:206:__cl_glimpse_size()) cfs_fail_timeout id 1404 sleeping for 4000ms [ 6435.799128] LustreError: 219267:0:(glimpse.c:206:__cl_glimpse_size()) cfs_fail_timeout id 1404 awake [ 6435.826036] LustreError: 219267:0:(glimpse.c:206:__cl_glimpse_size()) cfs_fail_timeout id 1404 sleeping for 4000ms [ 6439.903174] LustreError: 219267:0:(glimpse.c:206:__cl_glimpse_size()) cfs_fail_timeout id 1404 awake [ 6439.986650] LustreError: 219274:0:(glimpse.c:206:__cl_glimpse_size()) cfs_fail_timeout id 1404 sleeping for 4000ms [ 6444.063224] LustreError: 219274:0:(glimpse.c:206:__cl_glimpse_size()) cfs_fail_timeout id 1404 awake [ 6450.529657] Lustre: DEBUG MARKER: == sanityn test 51c: layout lock: IT_LAYOUT blocked and correct layout can be returned ========================================================== 11:49:28 (1789055368) [ 6462.424206] Lustre: DEBUG MARKER: == sanityn test 51d: layout lock: losing layout lock should clean up memory map region ========================================================== 11:49:39 (1789055379) [ 6470.419510] Lustre: DEBUG MARKER: == sanityn test 51e: lfs getstripe does not break leases, part 2 ========================================================== 11:49:47 (1789055387) [ 6478.997341] Lustre: DEBUG MARKER: == sanityn test 54: rename locking ======================= 11:49:56 (1789055396) [ 6513.298548] Lustre: DEBUG MARKER: == sanityn test 55a: rename vs unlink target dir ========= 11:50:30 (1789055430) [ 6527.483676] Lustre: DEBUG MARKER: == sanityn test 55b: rename vs unlink source dir ========= 11:50:44 (1789055444) [ 6540.610857] Lustre: DEBUG MARKER: == sanityn test 55c: rename vs unlink orphan target dir == 11:50:58 (1789055458) [ 6560.884719] Lustre: DEBUG MARKER: == sanityn test 55d: rename file vs link ================= 11:51:18 (1789055478) [ 6576.147500] Lustre: DEBUG MARKER: == sanityn test 55e: rename race AB/BA under the same parent dir ========================================================== 11:51:34 (1789055494) [ 6577.572722] Lustre: DEBUG MARKER: SKIP: sanityn test_55e needs >= 2 MDTs [ 6579.368197] Lustre: DEBUG MARKER: == sanityn test 55f: rename: (P1/A -> P2/B) race with (P2/B -> P1/A) ========================================================== 11:51:36 (1789055496) [ 6599.003273] Lustre: DEBUG MARKER: == sanityn test 55g: rename: race with trylock =========== 11:51:56 (1789055516) [ 6627.219404] Lustre: DEBUG MARKER: == sanityn test 56a: test llverdev with single large stripe ========================================================== 11:52:24 (1789055544) [ 6779.296585] Lustre: DEBUG MARKER: == sanityn test 56b: test llverdev and partial verify of wide stripe file ========================================================== 11:54:56 (1789055696) [ 6916.822590] Lustre: DEBUG MARKER: == sanityn test 60: Verify data_version behaviour ======== 11:57:14 (1789055834) [ 6924.804659] Lustre: DEBUG MARKER: == sanityn test 70a: cd directory [ 6932.465764] Lustre: DEBUG MARKER: == sanityn test 70b: remove files after calling rm_entry ========================================================== 11:57:29 (1789055849) [ 6941.240735] Lustre: DEBUG MARKER: == sanityn test 71a: correct file map just after write operation is finished ========================================================== 11:57:38 (1789055858) [ 6943.988711] Lustre: DEBUG MARKER: SKIP: sanityn test_71a ORI-366/LU-1941: FIEMAP unimplemented on ZFS [ 6946.715656] Lustre: DEBUG MARKER: == sanityn test 71b: check fiemap support for stripecount > 1 ========================================================== 11:57:43 (1789055863) [ 6948.855636] Lustre: DEBUG MARKER: SKIP: sanityn test_71b ORI-366/LU-1941: FIEMAP unimplemented on ZFS [ 6950.640778] Lustre: DEBUG MARKER: == sanityn test 71c: check FIEMAP_EXTENT_LAST flag with different extents number ========================================================== 11:57:48 (1789055868) [ 6952.575832] Lustre: DEBUG MARKER: SKIP: sanityn test_71c support only ldiskfs ost [ 6954.539828] Lustre: DEBUG MARKER: == sanityn test 71d: fiemap corruption test with fm_extent_count=0 ========================================================== 11:57:51 (1789055871) [ 6956.238579] Lustre: DEBUG MARKER: SKIP: sanityn test_71d ORI-366/LU-1941: FIEMAP unimplemented on ZFS [ 6958.108862] Lustre: DEBUG MARKER: == sanityn test 72: getxattr/setxattr cache should be consistent between nodes ========================================================== 11:57:55 (1789055875) [ 6964.763602] Lustre: DEBUG MARKER: == sanityn test 73: getxattr should not cause xattr lock cancellation ========================================================== 11:58:02 (1789055882) [ 6971.670576] Lustre: DEBUG MARKER: == sanityn test 74: flock deadlock: different mounts ======================================================================== 11:58:09 (1789055889) [ 6974.934107] LustreError: lustre-MDT0000-mdc-ffff9668d169d000: operation ldlm_enqueue to node 192.168.203.141@tcp failed: rc = -35 [ 6983.461486] Lustre: DEBUG MARKER: == sanityn test 75: osc: upcall after unuse lock============================================================================= 11:58:20 (1789055900) [ 6984.342176] LustreError: 2358:0:(osc_request.c:3150:osc_enqueue_interpret()) cfs_fail_timeout id 31d sleeping for 2000ms [ 6986.431116] LustreError: 2358:0:(osc_request.c:3150:osc_enqueue_interpret()) cfs_fail_timeout id 31d awake [ 6996.719768] Lustre: DEBUG MARKER: == sanityn test 76: Verify MDT open_files listing ======== 11:58:34 (1789055914) [ 7006.687612] Lustre: lustre-OST0000-osc-ffff9668d169d000: disconnect after 22s idle [ 7006.708384] Lustre: Skipped 6 previous similar messages [ 7078.799160] Lustre: DEBUG MARKER: == sanityn test 77a: check FIFO NRS policy =============== 11:59:56 (1789055996) [ 7088.225483] Lustre: DEBUG MARKER: == sanityn test 77b: check CRR-N NRS policy ============== 12:00:05 (1789056005) [ 7101.647534] Lustre: DEBUG MARKER: == sanityn test 77c: check ORR NRS policy ================ 12:00:19 (1789056019) [ 7117.071321] Lustre: DEBUG MARKER: == sanityn test 77d: check TRR nrs policy ================ 12:00:34 (1789056034) [ 7132.318750] Lustre: DEBUG MARKER: == sanityn test 77e: check TBF NID nrs policy ============ 12:00:49 (1789056049) [ 7160.586268] Lustre: DEBUG MARKER: == sanityn test 77f: check TBF JobID nrs policy ========== 12:01:17 (1789056077) [ 7187.094723] Lustre: DEBUG MARKER: == sanityn test 77g: Change TBF type directly ============ 12:01:44 (1789056104) [ 7198.330702] Lustre: DEBUG MARKER: == sanityn test 77h: Wrong policy name should report error, not LBUG ========================================================== 12:01:55 (1789056115) [ 7211.657245] Lustre: DEBUG MARKER: == sanityn test 77i: Change rank of TBF rule ============= 12:02:09 (1789056129) [ 7238.775711] Lustre: DEBUG MARKER: == sanityn test 77j: check TBF-OPCode NRS policy ========= 12:02:36 (1789056156) [ 7313.630662] Lustre: DEBUG MARKER: == sanityn test 77ja: check TBF-UID/GID NRS policy ======= 12:03:51 (1789056231) [ 7468.450895] Lustre: DEBUG MARKER: == sanityn test 77jb: check TBF-UID/GID NRS policy on files that don't belong to us ========================================================== 12:06:25 (1789056385) [ 7610.848185] Lustre: lustre-OST0000-osc-ffff9668d8375800: disconnect after 21s idle [ 7610.860555] Lustre: Skipped 14 previous similar messages [ 7626.582289] Lustre: DEBUG MARKER: == sanityn test 77k: check TBF policy with UID/GID/JobID/OPCode expression ========================================================== 12:09:03 (1789056543) [ 8084.001839] Lustre: DEBUG MARKER: == sanityn test 77kb: Check different granular TBF type combination: jobid+opcode ========================================================== 12:16:41 (1789057001) [ 8133.949518] Lustre: DEBUG MARKER: == sanityn test 77kc: Check different granular TBF type combination: nid+opcode ========================================================== 12:17:31 (1789057051) [ 8184.026167] Lustre: DEBUG MARKER: == sanityn test 77kd: Check different granular TBF type combination: nid+jobid ========================================================== 12:18:21 (1789057101) [ 8225.248555] Lustre: lustre-OST0000-osc-ffff9668d8375800: disconnect after 22s idle [ 8225.255230] Lustre: Skipped 21 previous similar messages [ 8231.029074] Lustre: DEBUG MARKER: == sanityn test 77ke: Check different granular TBF type combination: jobid+opcode ========================================================== 12:19:08 (1789057148) [ 8329.621420] Lustre: DEBUG MARKER: == sanityn test 77kf: Check different granular TBF type combination: uid+gid ========================================================== 12:20:46 (1789057246) [ 8405.173860] Lustre: DEBUG MARKER: == sanityn test 77kg: check different granular TBF type combination: uid+opcode ========================================================== 12:22:02 (1789057322) [ 8554.182496] Lustre: DEBUG MARKER: == sanityn test 77kh: Verify that Project ID support for NRS TBF rule ========================================================== 12:24:31 (1789057471) [ 8558.738235] Lustre: Unmounted lustre-client [ 8561.079996] Lustre: Unmounted lustre-client [ 8644.026118] Lustre: Mounted lustre-client - version 2.17.58_40_gb4686d2 [ 8646.884995] Lustre: Mounted lustre-client - version 2.17.58_40_gb4686d2 [ 8649.920795] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 8764.637545] Lustre: DEBUG MARKER: == sanityn test 77ki: Add rule with unsupported TBF type should fail for generic TBF ========================================================== 12:28:01 (1789057681) [ 8783.396962] Lustre: DEBUG MARKER: == sanityn test 77kj: Verify nodemap support for NRS TBF rule ========================================================== 12:28:21 (1789057701) [ 8836.575247] Lustre: lustre-OST0000-osc-ffff9668d03a8000: disconnect after 24s idle [ 8836.588258] Lustre: Skipped 17 previous similar messages [ 8972.708342] Lustre: DEBUG MARKER: == sanityn test 77l: check the output of NRS policies for generic TBF ========================================================== 12:31:30 (1789057890) [ 8982.481392] Lustre: DEBUG MARKER: == sanityn test 77m: check NRS Delay slows write RPC processing ========================================================== 12:31:40 (1789057900) [ 9040.675814] Lustre: DEBUG MARKER: == sanityn test 77n: check wildcard support for TBF JobID NRS policy ========================================================== 12:32:37 (1789057957) [ 9129.829330] Lustre: DEBUG MARKER: == sanityn test 77o: Changing rank should not panic ====== 12:34:07 (1789058047) [ 9140.328926] Lustre: DEBUG MARKER: == sanityn test 77q: Parallel TBF rule definitions should not panic ========================================================== 12:34:17 (1789058057) [ 9255.636507] Lustre: DEBUG MARKER: == sanityn test 77p: Check validity of rule names for TBF policies ========================================================== 12:36:13 (1789058173) [ 9287.729438] Lustre: DEBUG MARKER: == sanityn test 77r: Change type of tbf policy at run time ========================================================== 12:36:45 (1789058205) [ 9340.945089] Lustre: DEBUG MARKER: == sanityn test 77s: Check TBF LRU shrinker ============== 12:37:38 (1789058258) [ 9404.949333] Lustre: DEBUG MARKER: == sanityn test 78: Enable policy and specify tunings right away ========================================================== 12:38:42 (1789058322) [ 9415.099721] Lustre: DEBUG MARKER: == sanityn test 79: xattr: intent error ================== 12:38:52 (1789058332) [ 9433.532742] Lustre: DEBUG MARKER: == sanityn test 80a: migrate directory when some children is being opened ========================================================== 12:39:11 (1789058351) [ 9435.182953] Lustre: DEBUG MARKER: SKIP: sanityn test_80a needs >= 2 MDTs [ 9436.592264] Lustre: DEBUG MARKER: == sanityn test 80b: Accessing directory during migration ========================================================== 12:39:14 (1789058354) [ 9438.335544] Lustre: DEBUG MARKER: SKIP: sanityn test_80b needs >= 2 MDTs [ 9440.139710] Lustre: DEBUG MARKER: == sanityn test 81a: rename and stat under striped directory ========================================================== 12:39:17 (1789058357) [ 9441.584589] Lustre: DEBUG MARKER: SKIP: sanityn test_81a needs >= 2 MDTs [ 9443.046026] Lustre: DEBUG MARKER: == sanityn test 81b: rename under striped directory doesn't deadlock ========================================================== 12:39:20 (1789058360) [ 9444.245016] Lustre: DEBUG MARKER: SKIP: sanityn test_81b We need at least 2 MDTs for this test [ 9445.748249] Lustre: DEBUG MARKER: == sanityn test 81c: rename revoke LOOKUP lock for remote object ========================================================== 12:39:23 (1789058363) [ 9447.193454] Lustre: DEBUG MARKER: SKIP: sanityn test_81c needs >= 4 MDTs [ 9448.592688] Lustre: DEBUG MARKER: == sanityn test 81d: parallel rename file cross-dir on same MDT ========================================================== 12:39:26 (1789058366) [ 9582.084973] Lustre: DEBUG MARKER: == sanityn test 82: fsetxattr and fgetxattr on orphan files ========================================================== 12:41:39 (1789058499) [ 9587.639265] Lustre: DEBUG MARKER: == sanityn test 83: access striped directory while it is being created/unlinked ========================================================== 12:41:45 (1789058505) [ 9589.072698] Lustre: DEBUG MARKER: SKIP: sanityn test_83 needs >= 2 MDTs [ 9590.467188] Lustre: DEBUG MARKER: == sanityn test 84: 0-nlink race in lu_object_find() ===== 12:41:48 (1789058508) [ 9602.818052] Lustre: DEBUG MARKER: == sanityn test 85: Lustre API root cache race =========== 12:42:00 (1789058520) [ 9604.579679] Lustre: lustre-OST0001-osc-ffff9668d03a8000: disconnect after 22s idle [ 9604.585922] Lustre: Skipped 12 previous similar messages [ 9614.615369] Lustre: DEBUG MARKER: == sanityn test 90: open/create and unlink striped directory ========================================================== 12:42:12 (1789058532) [ 9616.483692] Lustre: DEBUG MARKER: SKIP: sanityn test_90 needs >= 2 MDTs [ 9618.959402] Lustre: DEBUG MARKER: == sanityn test 91: chmod and unlink striped directory === 12:42:15 (1789058535) [ 9620.452051] Lustre: DEBUG MARKER: SKIP: sanityn test_91 needs >= 2 MDTs [ 9622.266717] Lustre: DEBUG MARKER: == sanityn test 92: create remote directory under orphan directory ========================================================== 12:42:19 (1789058539) [ 9623.999234] Lustre: DEBUG MARKER: SKIP: sanityn test_92 needs >= 2 MDTs [ 9626.004767] Lustre: DEBUG MARKER: == sanityn test 93: alloc_rr should not allocate on same ost ========================================================== 12:42:23 (1789058543) [ 9649.136560] Lustre: DEBUG MARKER: == sanityn test 94: signal vs CP callback race =========== 12:42:45 (1789058565) [ 9650.174605] Lustre: DEBUG MARKER: write [ 9650.245533] LustreError: 260550:0:(ldlm_request.c:1533:ldlm_cli_cancel_req()) cfs_fail_timeout id 312 sleeping for 5000ms [ 9652.227924] Lustre: DEBUG MARKER: kill 290455 [ 9652.232699] LustreError: 290455:0:(ldlm_request.c:1393:ldlm_cli_cancel_local()) cfs_fail_timeout id 329 sleeping for 6000ms [ 9655.263211] LustreError: 260550:0:(ldlm_request.c:1533:ldlm_cli_cancel_req()) cfs_fail_timeout id 312 awake [ 9658.311160] LustreError: 290455:0:(ldlm_request.c:1393:ldlm_cli_cancel_local()) cfs_fail_timeout id 329 awake [ 9670.234373] Lustre: DEBUG MARKER: == sanityn test 95a: Check readpage() on a page that was removed from page cache ========================================================== 12:43:07 (1789058587) [ 9673.838857] LustreError: 291061:0:(rw.c:1865:ll_readpage()) cfs_fail_timeout id 1422 sleeping for 10000ms [ 9683.855370] LustreError: 291061:0:(rw.c:1865:ll_readpage()) cfs_fail_timeout id 1422 awake [ 9693.234822] Lustre: DEBUG MARKER: == sanityn test 95b: Check readpage() on a page that is no longer uptodate ========================================================== 12:43:29 (1789058609) [ 9693.736775] LustreError: 291641:0:(rw.c:2112:ll_readpage()) cfs_fail_timeout id 1424 sleeping for 5000ms [ 9695.831154] LustreError: 291641:0:(rw.c:2112:ll_readpage()) cfs_fail_timeout interrupted [ 9706.823755] Lustre: DEBUG MARKER: == sanityn test 100a: DoM: glimpse RPCs for stat without IO lock (DoM only file) ========================================================== 12:43:44 (1789058624) [ 9708.457646] Lustre: DEBUG MARKER: SKIP: sanityn test_100a Reserved for glimpse-ahead [ 9710.492765] Lustre: DEBUG MARKER: == sanityn test 100b: DoM: no glimpse RPC for stat with IO lock (DoM only file) ========================================================== 12:43:47 (1789058627) [ 9718.662965] Lustre: DEBUG MARKER: == sanityn test 100c: DoM: write vs stat without IO lock (combined file) ========================================================== 12:43:56 (1789058636) [ 9726.948810] Lustre: DEBUG MARKER: == sanityn test 100d: DoM: write+truncate vs stat without IO lock (combined file) ========================================================== 12:44:04 (1789058644) [ 9733.767638] Lustre: DEBUG MARKER: == sanityn test 100e: DoM: read on open and file size ==== 12:44:11 (1789058651) [ 9740.933362] Lustre: DEBUG MARKER: == sanityn test 101a: Discard DoM data on unlink ========= 12:44:18 (1789058658) [ 9749.554908] Lustre: DEBUG MARKER: == sanityn test 101b: Discard DoM data on rename ========= 12:44:26 (1789058666) [ 9757.312979] Lustre: DEBUG MARKER: == sanityn test 101c: Discard DoM data on close-unlink === 12:44:34 (1789058674) [ 9765.180967] Lustre: DEBUG MARKER: == sanityn test 102: Test open by handle of unlinked file ========================================================== 12:44:42 (1789058682) [ 9772.518680] Lustre: DEBUG MARKER: == sanityn test 103: Test size correctness with lockahead ========================================================== 12:44:49 (1789058689) [ 9774.112851] Lustre: *** cfs_fail_loc=415, val=0*** [ 9785.680355] Lustre: DEBUG MARKER: == sanityn test 104: Verify that MDS stores atime/mtime/ctime during close ========================================================== 12:45:03 (1789058703) [ 9787.049449] Lustre: DEBUG MARKER: SKIP: sanityn test_104 ldiskfs only test [ 9788.940744] Lustre: DEBUG MARKER: == sanityn test 105: Glimpse and lock cancel race ======== 12:45:06 (1789058706) [ 9789.263163] LustreError: 261242:0:(osc_lock.c:445:__osc_dlm_blocking_ast()) cfs_fail_timeout id 416 sleeping for 5000ms [ 9794.359187] LustreError: 261242:0:(osc_lock.c:445:__osc_dlm_blocking_ast()) cfs_fail_timeout id 416 awake [ 9794.370720] LustreError: 261242:0:(osc_lock.c:445:__osc_dlm_blocking_ast()) Skipped 2 previous similar messages [ 9804.407757] LustreError: 261242:0:(osc_lock.c:445:__osc_dlm_blocking_ast()) cfs_fail_timeout id 416 awake [ 9804.412619] LustreError: 261242:0:(osc_lock.c:445:__osc_dlm_blocking_ast()) Skipped 3 previous similar messages [ 9817.220917] Lustre: DEBUG MARKER: == sanityn test 106a: Verify the btime via statx() ======= 12:45:34 (1789058734) [ 9819.047836] Lustre: DEBUG MARKER: SKIP: sanityn test_106a Test only for ldiskfs and statx() supported [ 9821.882950] Lustre: DEBUG MARKER: == sanityn test 106b: Glimpse RPCs test for statx ======== 12:45:38 (1789058738) [ 9829.746644] Lustre: DEBUG MARKER: == sanityn test 106c: Verify statx attributes mask ======= 12:45:47 (1789058747) [ 9837.215353] Lustre: DEBUG MARKER: == sanityn test 107a: Basic grouplock conflict =========== 12:45:54 (1789058754) [ 9846.803890] Lustre: DEBUG MARKER: == sanityn test 107b: Grouplock is added to the head of waiting list ========================================================== 12:46:04 (1789058764) [ 9861.409567] Lustre: DEBUG MARKER: == sanityn test 108a: lseek: parallel updates ============ 12:46:18 (1789058778) [ 9862.238729] LustreError: 266458:0:(osc_request.c:3001:osc_build_rpc()) cfs_fail_timeout id 414 sleeping for 4000ms [ 9862.251013] LustreError: 266458:0:(osc_request.c:3001:osc_build_rpc()) Skipped 8 previous similar messages [ 9866.320624] LustreError: 266458:0:(osc_request.c:3001:osc_build_rpc()) cfs_fail_timeout id 414 awake [ 9866.332821] LustreError: 266458:0:(osc_request.c:3001:osc_build_rpc()) Skipped 1 previous similar message [ 9875.107210] Lustre: DEBUG MARKER: == sanityn test 109: Race with several mount instances on 1 node ========================================================== 12:46:32 (1789058792) [ 9879.163682] Lustre: Unmounted lustre-client [ 9881.811568] Lustre: Unmounted lustre-client [ 9883.542599] Lustre: DEBUG MARKER: Iteration 0 [ 9884.050992] LustreError: 302249:0:(llite_lib.c:1511:ll_fill_super()) cfs_race id 1417 sleeping [ 9884.054182] LustreError: 302250:0:(llite_lib.c:1511:ll_fill_super()) cfs_fail_race id 1417 waking [ 9884.078168] LustreError: 302249:0:(llite_lib.c:1511:ll_fill_super()) cfs_fail_race id 1417 awake: rc=4986 [ 9884.344655] Lustre: Mounted lustre-client - version 2.17.58_40_gb4686d2 [ 9885.820239] Lustre: Unmounted lustre-client [ 9889.612726] Key type lgssc unregistered [ 9889.933485] LNet: 302590:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 9889.949675] LNetError: 302590:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 9889.982037] LNet: Removed LNI 192.168.203.41@tcp [ 9890.998153] Key type .llcrypt unregistered [ 9891.003828] Key type ._llcrypt unregistered [ 9892.188492] Key type ._llcrypt registered [ 9892.192991] Key type .llcrypt registered [ 9892.589440] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [ 9892.606534] alg: No test for adler32 (adler32-zlib) [ 9894.341326] Lustre: Lustre: Build Version: 2.17.58_40_gb4686d2 [ 9895.454416] LNet: Added LNI 192.168.203.41@tcp [8/256/0/180] [ 9897.335545] Key type lgssc registered [ 9899.443169] Lustre: Echo OBD driver; http://www.lustre.org/ [ 9915.053446] Lustre: Mounted lustre-client - version 2.17.58_40_gb4686d2 [ 9915.648658] Lustre: Mounted lustre-client - version 2.17.58_40_gb4686d2 [ 9922.289738] Lustre: DEBUG MARKER: == sanityn test 110: do not grant another lock on resend ========================================================== 12:47:19 (1789058839) [ 9978.847139] Lustre: 303912:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789058842/real 1789058842] req@ffff9668feaa5880 x1875964134958720/t0(0) o36->lustre-MDT0000-mdc-ffff9668d1cd5800@192.168.203.141@tcp:12/10 lens 496/440 e 0 to 1 dl 1789058897 ref 2 fl Rpc:XQr/200/ffffffff rc 0/-1 job:'ln.0' uid:0 gid:0 projid:4294967295 [ 9978.886670] Lustre: lustre-MDT0000-mdc-ffff9668d1cd5800: Connection to lustre-MDT0000 (at 192.168.203.141@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 9978.926764] Lustre: lustre-MDT0000-mdc-ffff9668d1cd5800: Connection restored to 192.168.203.141@tcp (at 192.168.203.141@tcp) [10033.121267] Lustre: 303912:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789058897/real 1789058897] req@ffff9668feaa5880 x1875964134958720/t0(0) o36->lustre-MDT0000-mdc-ffff9668d1cd5800@192.168.203.141@tcp:12/10 lens 496/440 e 0 to 1 dl 1789058952 ref 2 fl Rpc:XQr/202/ffffffff rc 0/-1 job:'ln.0' uid:0 gid:0 projid:4294967295 [10033.157111] Lustre: lustre-MDT0000-mdc-ffff9668d1cd5800: Connection to lustre-MDT0000 (at 192.168.203.141@tcp) was lost; in progress operations using this service will wait for recovery to complete [10033.189052] Lustre: lustre-MDT0000-mdc-ffff9668d1cd5800: Connection restored to 192.168.203.141@tcp (at 192.168.203.141@tcp) [10088.421892] Lustre: 303912:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789058952/real 1789058952] req@ffff9668feaa5880 x1875964134958720/t0(0) o36->lustre-MDT0000-mdc-ffff9668d1cd5800@192.168.203.141@tcp:12/10 lens 496/440 e 0 to 1 dl 1789059007 ref 2 fl Rpc:XQr/202/ffffffff rc 0/-1 job:'ln.0' uid:0 gid:0 projid:4294967295 [10088.459838] Lustre: lustre-MDT0000-mdc-ffff9668d1cd5800: Connection to lustre-MDT0000 (at 192.168.203.141@tcp) was lost; in progress operations using this service will wait for recovery to complete [10088.516140] Lustre: lustre-MDT0000-mdc-ffff9668d1cd5800: Connection restored to 192.168.203.141@tcp (at 192.168.203.141@tcp) [10090.430938] Lustre: DEBUG MARKER: == sanityn test 111: A racy rename/link an open file should not cause fs corruption ========================================================== 12:50:07 (1789059007) [10092.186727] Lustre: DEBUG MARKER: SKIP: sanityn test_111 needs >= 2 MDTs [10094.534638] Lustre: DEBUG MARKER: == sanityn test 112: update max-inherit in default LMV === 12:50:11 (1789059011) [10096.263493] Lustre: DEBUG MARKER: SKIP: sanityn test_112 We need at least 2 MDTs for this test [10098.400980] Lustre: DEBUG MARKER: == sanityn test 113: check servers of specified fs ======= 12:50:15 (1789059015) [10104.973699] Lustre: DEBUG MARKER: == sanityn test 114: implicit default LMV inherit ======== 12:50:22 (1789059022) [10106.365617] Lustre: DEBUG MARKER: SKIP: sanityn test_114 We need at least 2 MDTs for this test [10107.824471] Lustre: DEBUG MARKER: == sanityn test 115: ldiskfs doesn't check direntry for uniqueness ========================================================== 12:50:25 (1789059025) [10109.082306] Lustre: DEBUG MARKER: SKIP: sanityn test_115 ldiskfs only test [10110.620914] Lustre: DEBUG MARKER: == sanityn test 116: DNE: Set default LMV layout from a remote client ========================================================== 12:50:28 (1789059028) [10111.838707] Lustre: DEBUG MARKER: SKIP: sanityn test_116 needs >= 2 MDTs [10113.322414] Lustre: DEBUG MARKER: == sanityn test 121: trunc append race =================== 12:50:31 (1789059031) [10113.703950] LustreError: 306582:0:(lcommon_cl.c:102:cl_setattr_ost()) cfs_fail_timeout id 1436 sleeping for 2000ms [10115.799173] LustreError: 306582:0:(lcommon_cl.c:102:cl_setattr_ost()) cfs_fail_timeout id 1436 awake [10122.473834] Lustre: DEBUG MARKER: == sanityn test 122: directory size is consistent across mounts ========================================================== 12:50:40 (1789059040) [10132.054968] Lustre: DEBUG MARKER: == sanityn test 200: service remains healthy while able to process request ========================================================== 12:50:49 (1789059049) [10154.917207] Lustre: 302779:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789059057/real 1789059057] req@ffff9668f4c56d80 x1875964135006208/t0(0) o4->lustre-OST0000-osc-ffff9668d1cd5800@192.168.203.141@tcp:6/4 lens 4584/448 e 0 to 1 dl 1789059073 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'dd.0' uid:0 gid:0 projid:0 [10154.962653] Lustre: lustre-OST0000-osc-ffff9668d1cd5800: Connection to lustre-OST0000 (at 192.168.203.141@tcp) was lost; in progress operations using this service will wait for recovery to complete [10171.359388] Lustre: 302780:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789059074/real 1789059074] req@ffff9668f1e91c00 x1875964135007360/t0(0) o4->lustre-OST0000-osc-ffff9668d1cd5800@192.168.203.141@tcp:6/4 lens 4584/448 e 0 to 1 dl 1789059090 ref 2 fl Rpc:XQr/602/ffffffff rc 0/-1 job:'dd.0' uid:0 gid:0 projid:0 [10171.414266] Lustre: 302780:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 8 previous similar messages [10171.433067] Lustre: lustre-OST0000-osc-ffff9668d1cd5800: Connection to lustre-OST0000 (at 192.168.203.141@tcp) was lost; in progress operations using this service will wait for recovery to complete [10171.493775] Lustre: lustre-OST0000-osc-ffff9668d1cd5800: Connection restored to 192.168.203.141@tcp (at 192.168.203.141@tcp) [10187.679254] Lustre: 302780:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789059090/real 1789059090] req@ffff9668f1e91c00 x1875964135007360/t0(0) o4->lustre-OST0000-osc-ffff9668d1cd5800@192.168.203.141@tcp:6/4 lens 4584/448 e 0 to 1 dl 1789059106 ref 2 fl Rpc:XQr/602/ffffffff rc 0/-1 job:'dd.0' uid:0 gid:0 projid:0 [10187.725021] Lustre: 302780:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 1 previous similar message [10187.737192] Lustre: lustre-OST0000-osc-ffff9668d1cd5800: Connection to lustre-OST0000 (at 192.168.203.141@tcp) was lost; in progress operations using this service will wait for recovery to complete [10187.798899] Lustre: lustre-OST0000-osc-ffff9668d1cd5800: Connection restored to 192.168.203.141@tcp (at 192.168.203.141@tcp) [10210.839117] Lustre: DEBUG MARKER: oleg341-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0000-osc-ffff9668d0c85800.ost_server_uuid 50 [10212.189849] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9668d0c85800.ost_server_uuid in IDLE state after 0 sec [10213.584971] Lustre: DEBUG MARKER: cleanup: ====================================================== [10215.176258] Lustre: DEBUG MARKER: == sanityn test complete, duration 9964 sec ============== 12:52:12 (1789059132) [10217.046458] Lustre: DEBUG MARKER: === sanityn: start cleanup 12:52:14 (1789059134) === [10475.637686] Lustre: Unmounted lustre-client [10479.019456] Lustre: DEBUG MARKER: === sanityn: finish cleanup 12:56:36 (1789059396) === [10481.058596] Lustre: Unmounted lustre-client [10499.868611] Key type lgssc unregistered [10500.174515] LNet: 310107:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [10500.190918] LNetError: 310107:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [10500.216252] LNet: Removed LNI 192.168.203.41@tcp [10500.960153] Key type .llcrypt unregistered [10500.963163] Key type ._llcrypt unregistered