[ 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-0x00000000bffcdfff] usable [ 0.000000] BIOS-e820: [mem 0x00000000bffce000-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-8.fc42 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 1123619473 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2400.000 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 = 0xbffce max_arch_pfn = 0x400000000 [ 0.000000] found SMP MP-table at [mem 0x000f54b0-0x000f54bf] [ 0.000000] RAMDISK: [mem 0xbcc54000-0xbffbffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F52D0 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE2439 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE22D5 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 002295 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE2349 000090 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE23D9 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE2411 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe22d5-0xbffe2348] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe22d4] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe2349-0xbffe23d8] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe23d9-0xbffe2410] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe2411-0xbffe2438] [ 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-0x00000000bffcdfff] [ 0.000000] node 0: [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Zeroed struct page in unavailable ranges: 4756 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 0xbffce000-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: 1059606 [ 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: 2829652K/4306352K 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.001011] APIC: Switch to symmetric I/O mode setup [ 0.002384] x2apic enabled [ 0.003010] Switched APIC routing to physical x2apic. [ 0.004000] kvm-guest: setup PV IPIs [ 0.004000] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.004000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x22983777dd9, max_idle_ns: 440795300422 ns [ 0.004000] Calibrating delay loop (skipped) preset value.. 4800.00 BogoMIPS (lpj=2400000) [ 0.004000] pid_max: default: 32768 minimum: 301 [ 0.004000] LSM: Security Framework initializing [ 0.004000] Yama: becoming mindful. [ 0.004000] SELinux: Initializing. [ 0.004000] *** VALIDATE selinux *** [ 0.010000] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.010000] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.010000] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.010000] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.010110] *** VALIDATE tmpfs *** [ 0.012381] *** VALIDATE proc *** [ 0.014263] *** VALIDATE cgroup *** [ 0.016009] *** VALIDATE cgroup2 *** [ 0.018033] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.020166] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.021009] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.022032] Spectre V2 : User space: Vulnerable [ 0.023015] Speculative Store Bypass: Vulnerable [ 0.027166] debug: unmapping init [mem 0xffffffffae459000-0xffffffffae460fff] [ 0.031000] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.032314] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.034027] ... version: 2 [ 0.035018] ... bit width: 48 [ 0.036015] ... generic registers: 4 [ 0.037019] ... value mask: 0000ffffffffffff [ 0.038017] ... max period: 00007fffffffffff [ 0.039020] ... fixed-purpose events: 3 [ 0.040019] ... event mask: 000000070000000f [ 0.042040] rcu: Hierarchical SRCU implementation. [ 0.045952] smp: Bringing up secondary CPUs ... [ 0.047515] x86: Booting SMP configuration: [ 0.048024] .... node #0, CPUs: #1 #2 #3 [ 0.069012] smp: Brought up 1 node, 4 CPUs [ 0.071016] smpboot: Max logical packages: 1 [ 0.072667] smpboot: Total of 4 processors activated (19200.00 BogoMIPS) [ 0.142536] node 0 deferred pages initialised in 67ms [ 0.153007] devtmpfs: initialized [ 0.186388] x86/mm: Memory block size: 128MB [ 0.190212] gcov: version magic: 0x41383552 [ 0.194449] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.196102] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.200924] pinctrl core: initialized pinctrl subsystem [ 0.212206] [ 0.227021] ************************************************************* [ 0.239014] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.250016] ** ** [ 0.256013] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.264015] ** ** [ 0.273408] ** This means that this kernel is built to expose internal ** [ 0.278013] ** IOMMU data structures, which may compromise security on ** [ 0.285015] ** your system. ** [ 0.290018] ** ** [ 0.295013] ** If you see this message and you are not debugging the ** [ 0.300014] ** kernel, report this immediately to your vendor! ** [ 0.305014] ** ** [ 0.309015] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.315013] ************************************************************* [ 0.322646] NET: Registered protocol family 16 [ 0.330673] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.337063] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.340067] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.347457] cpuidle: using governor menu [ 0.352435] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.357926] PCI: Using configuration type 1 for base access [ 0.360738] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.375627] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.376021] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.378243] cryptd: max_cpu_qlen set to 1000 [ 0.383040] ACPI: Added _OSI(Module Device) [ 0.386017] ACPI: Added _OSI(Processor Device) [ 0.388016] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.390503] ACPI: Added _OSI(Processor Aggregator Device) [ 0.401139] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.420106] ACPI: Interpreter enabled [ 0.424075] ACPI: PM: (supports S0 S3 S4 S5) [ 0.425000] ACPI: Using IOAPIC for interrupt routing [ 0.425000] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.425000] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.437637] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.440113] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.443102] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.447111] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.463861] acpiphp: Slot [2] registered [ 0.464186] acpiphp: Slot [5] registered [ 0.465187] acpiphp: Slot [6] registered [ 0.467248] acpiphp: Slot [7] registered [ 0.468203] acpiphp: Slot [8] registered [ 0.469138] acpiphp: Slot [9] registered [ 0.474580] acpiphp: Slot [10] registered [ 0.475177] acpiphp: Slot [3] registered [ 0.477120] acpiphp: Slot [4] registered [ 0.478292] acpiphp: Slot [11] registered [ 0.480086] acpiphp: Slot [12] registered [ 0.485481] acpiphp: Slot [13] registered [ 0.487147] acpiphp: Slot [14] registered [ 0.488129] acpiphp: Slot [15] registered [ 0.490293] acpiphp: Slot [16] registered [ 0.492176] acpiphp: Slot [17] registered [ 0.493121] acpiphp: Slot [18] registered [ 0.495107] acpiphp: Slot [19] registered [ 0.496000] acpiphp: Slot [20] registered [ 0.497205] acpiphp: Slot [21] registered [ 0.499176] acpiphp: Slot [22] registered [ 0.501134] acpiphp: Slot [23] registered [ 0.503186] acpiphp: Slot [24] registered [ 0.504115] acpiphp: Slot [25] registered [ 0.506318] acpiphp: Slot [26] registered [ 0.507098] acpiphp: Slot [27] registered [ 0.509278] acpiphp: Slot [28] registered [ 0.510110] acpiphp: Slot [29] registered [ 0.512312] acpiphp: Slot [30] registered [ 0.514114] acpiphp: Slot [31] registered [ 0.515062] PCI host bridge to bus 0000:00 [ 0.516000] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.517021] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.519029] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.522031] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.524241] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.525029] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.526361] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.527000] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.530459] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.540021] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.544508] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.546023] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.548018] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.549000] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.550762] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.551000] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.552061] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.561104] pci 0000:00:01.3: quirk_piix4_acpi+0x0/0x1e0 took 10742 usecs [ 0.564150] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.566022] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.576000] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.576000] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.576000] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.578000] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.584045] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.593000] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.593000] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.594000] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.602058] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.607000] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.607997] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.613000] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.619036] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.639027] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.647000] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.652026] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.660000] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.662000] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.671000] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.676000] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.687025] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.704000] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 0.720458] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.732033] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.736000] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.747040] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 0.772000] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.772000] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.772000] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.772000] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.772000] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.772138] iommu: Default domain type: Passthrough [ 0.773000] SCSI subsystem initialized [ 0.774148] ACPI: bus type USB registered [ 0.775000] usbcore: registered new interface driver usbfs [ 0.775000] usbcore: registered new interface driver hub [ 0.780149] usbcore: registered new device driver usb [ 0.782208] pps_core: LinuxPPS API ver. 1 registered [ 0.783011] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.785106] PTP clock support registered [ 0.787145] EDAC MC: Ver: 3.0.0 [ 0.818309] PCI: Using ACPI for IRQ routing [ 0.821178] NetLabel: Initializing [ 0.825020] NetLabel: domain hash size = 128 [ 0.832018] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.833225] NetLabel: unlabeled traffic allowed by default [ 0.843922] vgaarb: loaded [ 0.847053] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.853020] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.860327] clocksource: Switched to clocksource kvm-clock [ 1.095734] VFS: Disk quotas dquot_6.6.0 [ 1.099111] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 1.108525] *** VALIDATE ramfs *** [ 1.109951] *** VALIDATE hugetlbfs *** [ 1.111780] pnp: PnP ACPI init [ 1.115213] pnp: PnP ACPI: found 6 devices [ 1.141458] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 1.144402] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 1.146507] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 1.148611] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 1.151060] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 1.154138] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 1.157504] NET: Registered protocol family 2 [ 1.160081] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 1.166441] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 1.170507] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 1.176741] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 1.181594] TCP: Hash tables configured (established 65536 bind 65536) [ 1.196192] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 1.201809] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 1.207121] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 1.211417] NET: Registered protocol family 1 [ 1.214419] RPC: Registered named UNIX socket transport module. [ 1.217181] RPC: Registered udp transport module. [ 1.219124] RPC: Registered tcp transport module. [ 1.221903] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 1.225294] NET: Registered protocol family 44 [ 1.227895] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 1.231541] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 1.235077] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 1.237880] PCI: CLS 0 bytes, default 64 [ 1.240452] Unpacking initramfs... [ 6.888124] debug: unmapping init [mem 0xffff8b017cc54000-0xffff8b017ffbffff] [ 6.915213] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 6.920202] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 6.930907] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x22983777dd9, max_idle_ns: 440795300422 ns [ 10.258937] Initialise system trusted keyrings [ 10.263586] Key type blacklist registered [ 10.279828] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 10.310465] zbud: loaded [ 10.322472] *** VALIDATE nfs *** [ 10.323750] *** VALIDATE nfs4 *** [ 10.340517] pstore: using deflate compression [ 10.392816] Platform Keyring initialized [ 11.023523] NET: Registered protocol family 38 [ 11.027666] Key type asymmetric registered [ 11.032701] Asymmetric key parser 'x509' registered [ 11.041651] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 11.044514] io scheduler mq-deadline registered [ 11.046161] io scheduler kyber registered [ 11.056158] io scheduler bfq registered [ 11.071042] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 11.085264] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 11.096041] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 11.102190] ACPI: Power Button [PWRF] [ 11.134416] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 11.158414] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 11.189604] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 11.208962] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 11.274171] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 11.339503] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 11.418694] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 11.439379] Non-volatile memory driver v1.3 [ 11.442473] Linux agpgart interface v0.103 [ 11.638672] virtio_blk virtio1: [vda] 134144 512-byte logical blocks (68.7 MB/65.5 MiB) [ 11.654847] vda: detected capacity change from 0 to 68681728 [ 11.739428] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 11.743885] vdb: detected capacity change from 0 to 1073741824 [ 11.837172] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 11.851576] vdc: detected capacity change from 0 to 2621440000 [ 11.899249] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 11.906301] vdd: detected capacity change from 0 to 2621440000 [ 12.034518] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 12.037428] vde: detected capacity change from 0 to 4294967296 [ 12.132430] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 12.139358] vdf: detected capacity change from 0 to 4294967296 [ 12.176342] libphy: Fixed MDIO Bus: probed [ 12.204576] usbcore: registered new interface driver usbserial_generic [ 12.214497] usbserial: USB Serial support registered for generic [ 12.219624] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 12.240001] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 12.241736] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 12.251430] mousedev: PS/2 mouse device common for all mice [ 12.266549] rtc_cmos 00:05: RTC can wake from S4 [ 12.267584] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 12.292594] rtc_cmos 00:05: registered as rtc0 [ 12.295209] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 12.324597] intel_pstate: CPU model not supported [ 12.326688] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 12.347681] hid: raw HID events driver (C) Jiri Kosina [ 12.347949] usbcore: registered new interface driver usbhid [ 12.347953] usbhid: USB HID core driver [ 12.348122] drop_monitor: Initializing network drop monitor service [ 12.358618] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 12.366845] Initializing XFRM netlink socket [ 12.376206] NET: Registered protocol family 10 [ 12.420960] Segment Routing with IPv6 [ 12.422515] NET: Registered protocol family 17 [ 12.426194] mpls_gso: MPLS GSO support [ 12.440545] RAS: Correctable Errors collector initialized. [ 12.446258] AVX version of gcm_enc/dec engaged. [ 12.448956] AES CTR mode by8 optimization enabled [ 12.756024] sched_clock: Marking stable (12756013910, 0)->(15850577333, -3094563423) [ 12.790024] registered taskstats version 1 [ 12.798431] Loading compiled-in X.509 certificates [ 12.802577] zswap: loaded using pool lzo/zbud [ 12.850505] Key type big_key registered [ 12.879312] Key type encrypted registered [ 12.887312] ima: No TPM chip found, activating TPM-bypass! [ 12.892518] ima: Allocated hash algorithm: sha1 [ 12.897698] ima: No architecture policies found [ 12.902611] evm: Initialising EVM extended attributes: [ 12.907503] evm: security.selinux [ 12.914699] evm: security.ima [ 12.917613] evm: security.capability [ 12.920934] evm: HMAC attrs: 0x1 [ 12.924554] rtc_cmos 00:05: setting system clock to 2026-05-09 17:14:54 UTC (1778346894) [ 12.934753] debug: unmapping init [mem 0xffffffffaf403000-0xffffffffaf5fffff] [ 12.938797] debug: unmapping init [mem 0xffffffffae182000-0xffffffffae458fff] [ 12.949312] Write protecting the kernel read-only data: 28672k [ 12.959815] debug: unmapping init [mem 0xffffffffac803000-0xffffffffac9fffff] [ 12.970566] debug: unmapping init [mem 0xffffffffad114000-0xffffffffad1fffff] [ 13.095651] 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) [ 13.116852] systemd[1]: Detected virtualization kvm. [ 13.120776] systemd[1]: Detected architecture x86-64. [ 13.124701] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 13.190598] systemd[1]: No hostname configured. [ 13.202522] systemd[1]: Set hostname to . [ 13.209160] random: systemd: uninitialized urandom read (16 bytes read) [ 13.215788] systemd[1]: Initializing machine ID from random generator. [ 13.305878] random: ln: uninitialized urandom read (6 bytes read) [ 13.701644] random: systemd: uninitialized urandom read (16 bytes read) [ 13.714651] systemd[1]: Reached target Timers. [ OK ] Reached target Timers. [ 13.737700] systemd[1]: Reached target Initrd Root Device. [ OK ] Reached target Initrd Root Device. [ 13.766716] systemd[1]: Started Dispatch Password Requests to Console Directory Watch. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Listening on Journal Socket. Starting Setup Virtual Console... [ OK ] Listening on udev Kernel Socket. [ OK ] Reached target Paths. [ OK ] Listening on Journal Socket (/dev/log). Starting Create list of required st…ce nodes for the current kernel... [ OK ] Listening on udev Control Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Swap. [ OK ] Reached target Local File Systems. Starting Journal Service... [ OK ] Started Memstrack Anylazing Service. [ OK ] Reached target Slices. Starting Create Volatile Files and Directories... Starting Apply Kernel Variables... [ OK ] Started Setup Virtual Console. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Journal Service. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Apply Kernel Variables. Starting Create Static Device Nodes in /dev... Starting dracut cmdline hook... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 15.881355] device-mapper: uevent: version 1.0.3 [ 15.896229] 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... [ 19.142424] virtio_net virtio0 ens2: renamed from eth0 [ 19.179594] random: fast init done [ 19.184846] scsi host0: ata_piix [ 19.243489] scsi host1: ata_piix [ 19.247056] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 19.250989] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 24.447823] random: crng init done [ 24.464105] random: 7 urandom warning(s) missed due to ratelimiting [ 27.585580] dracut-initqueue[583]: 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. [ 30.372674] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... Stopping Hardware RNG Entropy Gatherer Daemon... [ 32.667214] hrtimer: interrupt took 5747718 ns [ 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 Initrd Root Device. [ OK ] Stopped target Timers. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Sockets. [ OK ] Stopped target Slices. [ OK ] Stopped target Paths. [ OK ] Stopped target System Initialization. [ OK ] Stopped target Swap. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. 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 Local File Systems. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Closed udev Control Socket. [ OK ] Closed udev Kernel Socket. Starting Cleanup udevd DB... [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 34.887846] printk: systemd: 21 output lines suppressed due to ratelimiting [ 36.409428] SELinux: Disabled at runtime. [ 36.605669] 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) [ 36.644627] systemd[1]: Detected virtualization kvm. [ 36.646371] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 39.792397] systemd[1]: initrd-switch-root.service: Succeeded. [ 39.814037] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 39.844833] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 39.856302] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 39.875531] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 39.927733] systemd[1]: Starting Journal Service... Starting Journal Service... [ 39.969857] systemd[1]: Created slice system-sshd\x2dkeygen.slice. [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Listening on udev Control Socket. [ OK ] Stopped target Switch Root. Mounting Kernel Debug File System... [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Reached target RPC Port Mapper. Starting Apply Kernel Variables... [ OK ] Reached target rpc_pipefs.target. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Listening on udev Kernel Socket. [ OK ] Listening on Process Core Dump Socket. [ OK ] Stopped target Initrd File Systems. Activating swap /dev/disk/by-label/SWAP... Mounting Huge Pages File System... [ OK ] Created slice User and Session Slice. [ OK ] Reached target Slices. [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. [ OK ] Stopped target Initrd Root File System. [ 40.552349] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS Starting Remount Root and Kernel File Systems... Starting udev Coldplug all Devices... [ OK ] Created slice system-getty.slice. Starting Create list of required st…ce nodes for the current kernel... Mounting POSIX Message Queue File System... [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Mounted Kernel Debug File System. [ OK ] Started Apply Kernel Variables. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Mounted Huge Pages File System. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Started Journal Service. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Mounted POSIX Message Queue File System. Starting Create Static Device Nodes in /dev... Starting Configure read-only root support... Starting Flush Journal to Persistent Storage... [ OK ] Reached target Swap. [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started udev Coldplug all Devices. [ OK ] Started Create Static Device Nodes in /dev. Starting udev Kernel Device Manager... [ OK ] Reached target Local File Systems (Pre). Mounting /home/green/git/lustre-release... Mounting /mnt... [ OK ] Mounted /mnt. [ 42.344366] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 44.138049] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 44.258378] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 45.216289] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 45.376932] EDAC sbridge: Ver: 1.1.2 [* ] A start job is running for Configur…-only root support (8s / no limit) [** ] A start job is running for Configur…-only root support (9s / no limit) [*** ] A start job is running for Configur…-only root support (9s / no limit) [ *** ] A start job is running for Configur…only root support (10s / no limit) [ *** ] A start job is running for Configur…only root support (10s / no limit) [ ***] A start job is running for Configur…only root support (11s / no limit) [ **] A start job is running for Configur…only root support (11s / no limit) [ *] A start job is running for Configur…only root support (12s / no limit) [ **] A start job is running for Configur…only root support (12s / no limit) [ ***] A start job is running for Configur…only root support (13s / no limit) [ *** ] A start job is running for Configur…only root support (13s / no limit) [ *** ] A start job is running for Configur…only root support (14s / no limit) [*** ] A start job is running for Configur…only root support (15s / no limit)[ 55.066115] Key type dns_resolver registered [** ] A start job is running for Configur…only root support (15s / no limit) [* ] A start job is running for Configur…only root support (16s / no limit) [** ] A start job is running for Configur…only root support (16s / no limit)[ 56.753754] NFS: Registering the id_resolver key type [ 56.764074] Key type id_resolver registered [ 56.767205] Key type id_legacy registered [*** ] A start job is running for Configur…only root support (17s / no limit) [ *** ] A start job is running for Configur…only root support (17s / 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 Mark the need to relabel after reboot. [ OK ] Started Create Volatile Files and Directories. Starting Update UTMP about System Boot/Shutdown... Starting RPC Bind... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Started dnf makecache --timer. [ OK ] Reached target Timers. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. [ OK ] Started irqbalance daemon. Starting Login Service... [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting Restore /run/initramfs on shutdown... [ OK ] Reached target sshd-keygen.target. [ OK ] Started D-Bus System Message Bus. Starting Network Manager... [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Network Manager. [ OK ] Reached target Network. Starting Dynamic System Tuning Daemon... Starting OpenSSH server daemon... Starting GSSAPI Proxy Daemon... Starting Network Manager Wait Online... [ OK ] Started Login Service. Starting Hostname Service... [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... [ OK ] Started OpenSSH server daemon. [ OK ] Started Permit User Sessions. [ OK ] Started Command Scheduler. [ OK ] Started Serial Getty on ttyS1. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Getty on tty1. [ OK ] Reached target Login Prompts. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting Notify NFS peers of a restart... Starting System Logging Service... Starting Crash recovery kernel arming... [ OK ] Started Notify NFS peers of a restart. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg435-server login: [ 105.454186] spl: loading out-of-tree module taints kernel. [ 110.648504] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 119.663168] Key type ._llcrypt registered [ 119.665191] Key type .llcrypt registered [ 119.727936] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_hostid [ 133.960940] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing load_modules_local [ 134.923480] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 134.937899] alg: No test for adler32 (adler32-zlib) [ 136.189285] Lustre: Lustre: Build Version: 2.17.52_4_g786747d [ 136.754564] LNet: Added LNI 192.168.204.135@tcp [8/256/0/180] [ 138.440159] Key type lgssc registered [ 140.070139] Lustre: Echo OBD driver; http://www.lustre.org/ [ 148.948642] vdc: vdc1 vdc9 [ 157.267976] vde: vde1 vde9 [ 165.717469] vdf: vdf1 vdf9 [ 181.376490] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing load_modules_local [ 188.225221] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 189.515433] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 189.793735] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 189.882876] Lustre: lustre-MDT0000: new disk, initializing [ 190.331721] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 190.378620] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 193.756800] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 197.875310] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 202.502136] Lustre: lustre-OST0000: new disk, initializing [ 202.505648] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 202.513370] Lustre: Skipped 1 previous similar message [ 202.590111] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 203.518253] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:0:ost [ 203.525111] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:0:ost] [ 203.625478] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x240000400 [ 206.859060] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 215.132274] Lustre: lustre-OST0001: new disk, initializing [ 215.139834] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 215.203928] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 220.177413] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 224.325162] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:1:ost [ 224.331031] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:1:ost] [ 224.426651] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x280000400 [ 229.237411] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 240.556992] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 250.357196] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing check_logdir /tmp/testlogs/ [ 253.935829] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing yml_node [ 257.155400] Lustre: DEBUG MARKER: Client: 2.17.52.4 [ 258.846600] Lustre: DEBUG MARKER: MDS: 2.17.52.4 [ 260.486295] Lustre: DEBUG MARKER: OSS: 2.17.52.4 [ 261.586899] Lustre: DEBUG MARKER: -----============= acceptance-small: sanityn ============----- Sat May 9 13:19:02 EDT 2026 [ 274.490685] Lustre: DEBUG MARKER: excepting tests: 27 40a 102 [ 275.487814] Lustre: DEBUG MARKER: skipping tests SLOW=no: 33a [ 276.580181] Lustre: DEBUG MARKER: === sanityn: start setup 13:19:17 (1778347157) === [ 279.428359] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing check_config_client /mnt/lustre [ 289.584781] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 291.533401] Lustre: 11065:0:(mgs_llog.c:1348:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 293.601236] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 295.720605] Lustre: DEBUG MARKER: === sanityn: finish setup 13:19:36 (1778347176) === [ 297.093237] Lustre: DEBUG MARKER: == sanityn test 0: do_node_vp() and do_facet_vp() do the right thing ========================================================== 13:19:38 (1778347178) [ 302.031551] Lustre: DEBUG MARKER: == sanityn test 1: Check attribute updates on 2 mount points ========================================================== 13:19:43 (1778347183) [ 306.329769] Lustre: DEBUG MARKER: == sanityn test 2a: check cached attribute updates on 2 mtpt's ================================================================== 13:19:47 (1778347187) [ 310.818446] Lustre: DEBUG MARKER: == sanityn test 2b: check cached attribute updates on 2 mtpt's ================================================================== 13:19:51 (1778347191) [ 315.504554] Lustre: DEBUG MARKER: == sanityn test 2c: check cached attribute updates on 2 mtpt's root ============================================================= 13:19:56 (1778347196) [ 320.082861] Lustre: DEBUG MARKER: == sanityn test 2d: check cached attribute updates on 2 mtpt's root ============================================================= 13:20:01 (1778347201) [ 324.773397] Lustre: DEBUG MARKER: == sanityn test 2e: check chmod on root is propagated to others ========================================================== 13:20:05 (1778347205) [ 330.613387] Lustre: DEBUG MARKER: == sanityn test 2f: check attr/owner updates on DNE with 2 mtpt's ========================================================== 13:20:11 (1778347211) [ 332.049994] Lustre: DEBUG MARKER: SKIP: sanityn test_2f needs >= 2 MDTs [ 333.455796] Lustre: DEBUG MARKER: == sanityn test 2g: check blocks update on sync write ==== 13:20:14 (1778347214) [ 339.002303] Lustre: DEBUG MARKER: == sanityn test 3: symlink on one mtpt, readlink on another ===================================================================== 13:20:20 (1778347220) [ 344.188274] Lustre: DEBUG MARKER: == sanityn test 4: fstat validation on multiple mount points ==================================================================== 13:20:25 (1778347225) [ 350.178765] Lustre: DEBUG MARKER: == sanityn test 5: create a file on one mount, truncate it on the other ========================================================== 13:20:31 (1778347231) [ 354.957120] Lustre: DEBUG MARKER: == sanityn test 6: remove of open file on other node ============================================================================ 13:20:35 (1778347235) [ 359.375759] Lustre: DEBUG MARKER: == sanityn test 7: remove of open directory on other node ======================================================================= 13:20:40 (1778347240) [ 363.548677] Lustre: DEBUG MARKER: == sanityn test 8: remove of open special file on other node ==================================================================== 13:20:44 (1778347244) [ 367.769224] Lustre: DEBUG MARKER: == sanityn test 9a: append of file with sub-page size on multiple mounts ========================================================== 13:20:48 (1778347248) [ 373.128920] Lustre: DEBUG MARKER: == sanityn test 9b: append to striped sparse file ======== 13:20:54 (1778347254) [ 377.434887] Lustre: DEBUG MARKER: == sanityn test 10a: write of file with sub-page size on multiple mounts ========================================================== 13:20:58 (1778347258) [ 382.836474] Lustre: DEBUG MARKER: == sanityn test 10b: write of file with sub-page size on multiple mounts ========================================================== 13:21:03 (1778347263) [ 387.610650] Lustre: DEBUG MARKER: == sanityn test 11: execution of file opened for write should return error ============================================================== 13:21:08 (1778347268) [ 392.484788] Lustre: DEBUG MARKER: == sanityn test 12: test lock ordering (link, stat, unlink) ========================================================== 13:21:13 (1778347273) [ 520.002263] Lustre: DEBUG MARKER: == sanityn test 13: test directory page revocation ======= 13:23:21 (1778347401) [ 523.100544] Lustre: DEBUG MARKER: == sanityn test 14aa: execution of file open for write returns -ETXTBSY ========================================================== 13:23:24 (1778347404) [ 525.548812] Lustre: DEBUG MARKER: == sanityn test 14ab: open(RDWR) of executing file returns -ETXTBSY ========================================================== 13:23:27 (1778347407) [ 527.940283] Lustre: DEBUG MARKER: == sanityn test 14b: truncate of executing file returns -ETXTBSY ================================================================ 13:23:29 (1778347409) [ 530.406957] Lustre: DEBUG MARKER: == sanityn test 14c: open(O_TRUNC) of executing file return -ETXTBSY ============================================================ 13:23:31 (1778347411) [ 533.071508] Lustre: DEBUG MARKER: == sanityn test 14d: chmod of executing file is still possible ================================================================== 13:23:34 (1778347414) [ 533.737651] Lustre: DEBUG MARKER: chmod [ 536.169123] Lustre: DEBUG MARKER: == sanityn test 15: test out-of-space with multiple writers ===================================================================== 13:23:37 (1778347417) [ 558.274591] Lustre: DEBUG MARKER: SKIP: oos2 test_15 oos2.sh: 7527424KB free > 800000KB, increase MAXFREE (or reduce fs size) [ 565.928689] Lustre: DEBUG MARKER: == sanityn test 16a: 500 iterations of dual-mount fsx ==== 13:24:07 (1778347447) [ 575.246658] Lustre: DEBUG MARKER: == sanityn test 16b: 500 iterations of dual-mount fsx at small size ========================================================== 13:24:16 (1778347456) [ 581.233669] Lustre: DEBUG MARKER: == sanityn test 16c: verify data consistency on ldiskfs with cache disabled (b=17397) ========================================================== 13:24:22 (1778347462) [ 581.970984] Lustre: DEBUG MARKER: SKIP: sanityn test_16c dio on ldiskfs only [ 582.486916] Lustre: DEBUG MARKER: == sanityn test 16d: Verify DIO and buffer IO with two clients ========================================================== 13:24:24 (1778347464) [ 593.788524] Lustre: DEBUG MARKER: == sanityn test 16e: Verify size consistency for O_DIRECT write ========================================================== 13:24:35 (1778347475) [ 595.975392] Lustre: DEBUG MARKER: == sanityn test 16f: rw sequential consistency vs drop_caches ========================================================== 13:24:37 (1778347477) [ 618.295448] Lustre: DEBUG MARKER: == sanityn test 16g: mmap rw sequential consistency vs drop_caches ========================================================== 13:24:59 (1778347499) [ 640.681423] Lustre: DEBUG MARKER: == sanityn test 16h: mmap read after truncate file ======= 13:25:22 (1778347522) [ 642.848052] Lustre: DEBUG MARKER: == sanityn test 16i: read after truncate file ============ 13:25:24 (1778347524) [ 644.881404] Lustre: DEBUG MARKER: == sanityn test 16j: race dio with buffered i/o ========== 13:25:26 (1778347526) [ 653.671466] Lustre: DEBUG MARKER: == sanityn test 16k: Parallel FSX and drop caches should not panic ========================================================== 13:25:35 (1778347535) [ 663.614434] Lustre: DEBUG MARKER: == sanityn test 17: resource creation/LVB creation race ========================================================================= 13:25:45 (1778347545) [ 664.100457] LustreError: 5786:0:(ldlm_resource.c:1597:ldlm_resource_get()) cfs_fail_timeout id 30a sleeping for 2000ms [ 666.184074] LustreError: 5786:0:(ldlm_resource.c:1597:ldlm_resource_get()) cfs_fail_timeout id 30a awake [ 668.060387] Lustre: DEBUG MARKER: == sanityn test 18: mmap sanity check =========================================================================================== 13:25:49 (1778347549) [ 679.448380] Lustre: DEBUG MARKER: == sanityn test 19: test concurrent uncached read races ========================================================================= 13:26:01 (1778347561) [ 680.292362] Lustre: DEBUG MARKER: SKIP: sanityn test_19 not cache-capable obdfilter [ 680.803345] Lustre: DEBUG MARKER: == sanityn test 20: test extra readahead page left in cache ============================================================== 13:26:02 (1778347562) [ 682.921544] Lustre: DEBUG MARKER: == sanityn test 21: Try to remove mountpoint on another dir ============================================================== 13:26:04 (1778347564) [ 684.915121] Lustre: DEBUG MARKER: == sanityn test 23: others should see updated atime while another read============================================================== 13:26:06 (1778347566) [ 748.377337] Lustre: DEBUG MARKER: == sanityn test 24a: lfs df [-ih] [path] test =================================================================================== 13:27:10 (1778347630) [ 750.432778] Lustre: DEBUG MARKER: == sanityn test 24b: lfs df should show both filesystems ========================================================================= 13:27:12 (1778347632) [ 752.421190] Lustre: DEBUG MARKER: == sanityn test 25a: change ACL on one mountpoint be seen on another ============================================================= 13:27:14 (1778347634) [ 754.635504] Lustre: DEBUG MARKER: == sanityn test 25b: change ACL under remote dir on one mountpoint be seen on another ========================================================== 13:27:16 (1778347636) [ 755.120156] Lustre: DEBUG MARKER: SKIP: sanityn test_25b needs >= 2 MDTs [ 755.641625] Lustre: DEBUG MARKER: == sanityn test 26a: allow mtime to get older ============ 13:27:17 (1778347637) [ 758.649791] Lustre: DEBUG MARKER: == sanityn test 26b: sync mtime between ost and mds ====== 13:27:20 (1778347640) [ 762.591706] Lustre: DEBUG MARKER: == sanityn test 26c: set-in-past on open file is not lost on close ========================================================== 13:27:24 (1778347644) [ 765.611679] Lustre: DEBUG MARKER: SKIP: sanityn test_27 skipping excluded test 27 [ 766.140110] Lustre: DEBUG MARKER: == sanityn test 30: recreate file race =================== 13:27:27 (1778347647) [ 770.126369] Lustre: DEBUG MARKER: == sanityn test 31a: voluntary cancel / blocking ast race======================================================================== 13:27:31 (1778347651) [ 773.067953] Lustre: DEBUG MARKER: == sanityn test 31b: voluntary OST cancel / blocking ast race======================================================================== 13:27:34 (1778347654) [ 789.121644] Lustre: *** cfs_fail_loc=316, val=0*** [ 791.442904] Lustre: DEBUG MARKER: == sanityn test 31r: open-rename(replace) race =========== 13:27:53 (1778347673) [ 796.541737] Lustre: DEBUG MARKER: == sanityn test 31s: open should not revalidate invalid dentry ========================================================== 13:27:58 (1778347678) [ 799.104131] Lustre: DEBUG MARKER: == sanityn test 31t: getattr should not revalidate invalid dentry ========================================================== 13:28:00 (1778347680) [ 802.271102] Lustre: DEBUG MARKER: SKIP: sanityn test_33a skipping SLOW test 33a [ 802.863618] Lustre: DEBUG MARKER: == sanityn test 33b: COS: cross create/delete, 2 clients, benchmark under remote dir ========================================================== 13:28:04 (1778347684) [ 803.411671] Lustre: DEBUG MARKER: SKIP: sanityn test_33b Need two or more clients, have 1 [ 804.019247] Lustre: DEBUG MARKER: == sanityn test 33c: Cancel cross-MDT lock should trigger Sync-on-Lock-Cancel ========================================================== 13:28:05 (1778347685) [ 804.493829] Lustre: DEBUG MARKER: SKIP: sanityn test_33c needs >= 2 MDTs [ 805.012654] Lustre: DEBUG MARKER: == sanityn test 33d: dependent transactions should trigger COS ========================================================== 13:28:06 (1778347686) [ 805.466473] Lustre: DEBUG MARKER: SKIP: sanityn test_33d needs >= 2 MDTs [ 805.976334] Lustre: DEBUG MARKER: == sanityn test 33e: independent transactions shouldn't trigger COS ========================================================== 13:28:07 (1778347687) [ 806.504340] Lustre: DEBUG MARKER: SKIP: sanityn test_33e needs >= 2 MDTs [ 807.078879] Lustre: DEBUG MARKER: == sanityn test 34: no lock timeout under IO ============= 13:28:08 (1778347688) [ 808.215028] Lustre: *** cfs_fail_loc=512, val=0*** [ 808.216502] LustreError: 15397:0:(service.c:2476:ptlrpc_server_handle_request()) cfs_fail_timeout id 512 sleeping for 4000ms [ 809.547873] Lustre: *** cfs_fail_loc=512, val=0*** [ 809.547978] LustreError: 6561:0:(service.c:2476:ptlrpc_server_handle_request()) cfs_fail_timeout id 512 sleeping for 4000ms [ 809.549466] Lustre: Skipped 6 previous similar messages [ 809.552288] LustreError: 6561:0:(service.c:2476:ptlrpc_server_handle_request()) Skipped 4 previous similar messages [ 812.272189] LustreError: 15397:0:(service.c:2476:ptlrpc_server_handle_request()) cfs_fail_timeout id 512 awake [ 812.277474] Lustre: *** cfs_fail_loc=512, val=0*** [ 812.280713] Lustre: *** cfs_fail_loc=512, val=0*** [ 812.282014] LustreError: 7443:0:(service.c:2476:ptlrpc_server_handle_request()) cfs_fail_timeout id 512 sleeping for 4000ms [ 813.280136] Lustre: *** cfs_fail_loc=512, val=0*** [ 813.600141] LustreError: 12179:0:(service.c:2476:ptlrpc_server_handle_request()) cfs_fail_timeout id 512 awake [ 814.304151] Lustre: *** cfs_fail_loc=512, val=0*** [ 814.667938] Lustre: *** cfs_fail_loc=512, val=0*** [ 814.669560] Lustre: Skipped 14 previous similar messages [ 816.344097] LustreError: 7443:0:(service.c:2476:ptlrpc_server_handle_request()) cfs_fail_timeout id 512 awake [ 816.346565] LustreError: 7443:0:(service.c:2476:ptlrpc_server_handle_request()) Skipped 5 previous similar messages [ 816.362352] LustreError: 18669:0:(service.c:2476:ptlrpc_server_handle_request()) cfs_fail_timeout id 512 sleeping for 4000ms [ 816.365196] LustreError: 18669:0:(service.c:2476:ptlrpc_server_handle_request()) Skipped 12 previous similar messages [ 819.787884] Lustre: *** cfs_fail_loc=512, val=0*** [ 819.789517] Lustre: Skipped 18 previous similar messages [ 820.416157] LustreError: 7389:0:(service.c:2476:ptlrpc_server_handle_request()) cfs_fail_timeout id 512 awake [ 820.420258] LustreError: 7389:0:(service.c:2476:ptlrpc_server_handle_request()) Skipped 11 previous similar messages [ 824.483871] Lustre: *** cfs_fail_loc=512, val=0*** [ 824.485532] Lustre: Skipped 1 previous similar message [ 824.489178] LustreError: 15379:0:(service.c:2476:ptlrpc_server_handle_request()) cfs_fail_timeout id 512 sleeping for 4000ms [ 824.491892] LustreError: 15379:0:(service.c:2476:ptlrpc_server_handle_request()) Skipped 17 previous similar messages [ 828.384393] Lustre: *** cfs_fail_loc=512, val=0*** [ 828.385878] Lustre: Skipped 25 previous similar messages [ 828.552135] LustreError: 15379:0:(service.c:2476:ptlrpc_server_handle_request()) cfs_fail_timeout id 512 awake [ 828.556874] LustreError: 15379:0:(service.c:2476:ptlrpc_server_handle_request()) Skipped 17 previous similar messages [ 841.277313] LustreError: 15407:0:(service.c:2476:ptlrpc_server_handle_request()) cfs_fail_timeout id 512 sleeping for 4000ms [ 841.280084] LustreError: 15407:0:(service.c:2476:ptlrpc_server_handle_request()) Skipped 37 previous similar messages [ 845.336072] LustreError: 15407:0:(service.c:2476:ptlrpc_server_handle_request()) cfs_fail_timeout id 512 awake [ 845.339308] LustreError: 15407:0:(service.c:2476:ptlrpc_server_handle_request()) Skipped 37 previous similar messages [ 845.345483] Lustre: *** cfs_fail_loc=512, val=0*** [ 845.346517] Lustre: Skipped 46 previous similar messages [ 845.349196] Lustre: *** cfs_fail_loc=512, val=0*** [ 845.350819] Lustre: Skipped 3 previous similar messages [ 853.480176] Lustre: *** cfs_fail_loc=512, val=0*** [ 853.481416] Lustre: Skipped 7 previous similar messages [ 854.496342] LustreError: 5774:0:(ldlm_lockd.c:255:expired_lock_main()) ### lock callback timer expired after 1s: evicting client at 192.168.204.35@tcp ns: filter-lustre-OST0001_UUID lock: 000000001537a7c5/0x4a80cdb26b97135c lrc: 3/0,0 mode: PR/PR res: [0x280000400:0x36:0x0].0x0 rrc: 4 type: EXT [0->18446744073709551615] (req 0->4095) gid 0 flags: 0x60000400030020 nid: 192.168.204.35@tcp remote: 0x42773975145fcf58 expref: 9 pid: 12179 timeout: 854 lvb_type: 0 lru_score: 0 lru_type: 0 [ 870.780518] Lustre: *** cfs_fail_loc=511, val=0*** [ 870.781718] Lustre: Skipped 3 previous similar messages [ 871.840139] LustreError: 5774:0:(ldlm_lockd.c:255:expired_lock_main()) ### lock callback timer expired after 1s: evicting client at 192.168.204.35@tcp ns: filter-lustre-OST0000_UUID lock: 00000000a12d274d/0x4a80cdb26b9713da lrc: 3/0,0 mode: PW/PW res: [0x240000400:0x39:0x0].0x0 rrc: 3 type: EXT [0->18446744073709551615] (req 0->4095) gid 0 flags: 0x60000400000020 nid: 192.168.204.35@tcp remote: 0x42773975145fcf7b expref: 10 pid: 6560 timeout: 871 lvb_type: 0 lru_score: 0 lru_type: 0 [ 871.854784] LustreError: 5774:0:(ldlm_lockd.c:255:expired_lock_main()) Skipped 1 previous similar message [ 874.464367] LustreError: 15407:0:(service.c:2476:ptlrpc_server_handle_request()) cfs_fail_timeout id 511 sleeping for 4000ms [ 874.467085] LustreError: 15407:0:(service.c:2476:ptlrpc_server_handle_request()) Skipped 69 previous similar messages [ 878.520077] LustreError: 15397:0:(service.c:2476:ptlrpc_server_handle_request()) cfs_fail_timeout id 511 awake [ 878.522560] LustreError: 15397:0:(service.c:2476:ptlrpc_server_handle_request()) Skipped 65 previous similar messages [ 879.584318] Lustre: *** cfs_fail_loc=511, val=0*** [ 879.585586] Lustre: Skipped 112 previous similar messages [ 884.968043] LustreError: 5784:0:(service.c:2476:ptlrpc_server_handle_request()) cfs_fail_timeout interrupted [ 884.970811] LustreError: 5784:0:(service.c:2476:ptlrpc_server_handle_request()) Skipped 3 previous similar messages [ 886.182202] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0000-osc-ffff9e53829a2000.ost_server_uuid 50 [ 886.709653] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9e53829a2000.ost_server_uuid in FULL state after 0 sec [ 887.932308] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0001-osc-ffff9e53829a2000.ost_server_uuid 50 [ 888.450919] Lustre: DEBUG MARKER: osc.lustre-OST0001-osc-ffff9e53829a2000.ost_server_uuid in IDLE state after 0 sec [ 890.034841] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0000-osc-ffff9e53829a2000.ost_server_uuid 50 [ 890.510503] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9e53829a2000.ost_server_uuid in FULL state after 0 sec [ 891.727258] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0001-osc-ffff9e53829a2000.ost_server_uuid 50 [ 892.219862] Lustre: DEBUG MARKER: osc.lustre-OST0001-osc-ffff9e53829a2000.ost_server_uuid in IDLE state after 0 sec [ 895.312154] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0000-osc-ffff9e53829a2000.ost_server_uuid 50 [ 895.786964] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9e53829a2000.ost_server_uuid in FULL state after 0 sec [ 896.913020] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0001-osc-ffff9e53829a2000.ost_server_uuid 50 [ 897.378694] Lustre: DEBUG MARKER: osc.lustre-OST0001-osc-ffff9e53829a2000.ost_server_uuid in IDLE state after 0 sec [ 897.924522] Lustre: DEBUG MARKER: == sanityn test 35: -EINTR cp_ast vs. bl_ast race does not evict client ========================================================== 13:29:39 (1778347779) [ 898.775336] Lustre: DEBUG MARKER: Race attempt 0 [ 900.399894] Lustre: DEBUG MARKER: Wait for 49034 49169 for 60 sec... [ 962.515752] Lustre: DEBUG MARKER: == sanityn test 36: handle ESTALE/open-unlink correctly == 13:30:44 (1778347844) [ 1200.723482] Lustre: DEBUG MARKER: == sanityn test 37: check i_size is not updated for directory on close (bug 18695) ======================================================================== 13:34:42 (1778348082) [ 1215.310513] Lustre: 7389:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff8b00c68d4a80 x1864732007906432/t4295005055(0) o101->1fa0241a-0aff-4edb-83ea-c8af009315a3@192.168.204.35@tcp:7/0 lens 656/3488 e 0 to 0 dl 1778348147 ref 1 fl Interpret:H/602/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:0 [ 1217.500768] Lustre: DEBUG MARKER: == sanityn test 39a: file mtime does not change after rename ========================================================== 13:34:58 (1778348098) [ 1219.725825] Lustre: DEBUG MARKER: == sanityn test 39b: file mtime the same on clients with/out lock ========================================================== 13:35:01 (1778348101) [ 1222.831969] Lustre: DEBUG MARKER: == sanityn test 39c: check truncate mtime update ================================================================================ 13:35:04 (1778348104) [ 1226.108606] Lustre: DEBUG MARKER: == sanityn test 39d: sync write should update mtime ====== 13:35:07 (1778348107) [ 1228.112864] Lustre: DEBUG MARKER: SKIP: sanityn test_40a skipping ALWAYS excluded test 40a [ 1228.643843] Lustre: DEBUG MARKER: == sanityn test 40b: pdirops: open|create and others ======================================================================== 13:35:10 (1778348110) [ 1230.231563] LustreError: 25239:0:(mdt_handler.c:4161:mdt_object_pdo_lock()) cfs_fail_timeout id 145 sleeping for 15000ms [ 1230.234968] LustreError: 25239:0:(mdt_handler.c:4161:mdt_object_pdo_lock()) Skipped 17 previous similar messages [ 1235.024094] LustreError: 25239:0:(mdt_handler.c:4161:mdt_object_pdo_lock()) cfs_fail_timeout interrupted [ 1235.026900] LustreError: 25239:0:(mdt_handler.c:4161:mdt_object_pdo_lock()) Skipped 5 previous similar messages [ 1236.963551] Lustre: DEBUG MARKER: == sanityn test 40c: pdirops: link and others ======================================================================== 13:35:18 (1778348118) [ 1242.912083] LustreError: 15407:0:(mdt_handler.c:4161:mdt_object_pdo_lock()) cfs_fail_timeout interrupted [ 1244.939285] Lustre: DEBUG MARKER: == sanityn test 40d: pdirops: unlink and others ======================================================================== 13:35:26 (1778348126) [ 1251.017039] LustreError: 7389:0:(mdt_handler.c:4161:mdt_object_pdo_lock()) cfs_fail_timeout interrupted [ 1253.001165] Lustre: DEBUG MARKER: == sanityn test 40e: pdirops: rename and others ======================================================================== 13:35:34 (1778348134) [ 1258.440061] LustreError: 5798:0:(mdt_handler.c:4161:mdt_object_pdo_lock()) cfs_fail_timeout interrupted [ 1260.470245] Lustre: DEBUG MARKER: == sanityn test 41a: pdirops: create vs mkdir ======================================================================== 13:35:42 (1778348142) [ 1265.907794] Lustre: DEBUG MARKER: == sanityn test 41b: pdirops: create vs create ======================================================================== 13:35:47 (1778348147) [ 1268.504045] LustreError: 5786:0:(mdt_handler.c:4161:mdt_object_pdo_lock()) cfs_fail_timeout interrupted [ 1268.506866] LustreError: 5786:0:(mdt_handler.c:4161:mdt_object_pdo_lock()) Skipped 1 previous similar message [ 1271.049433] Lustre: DEBUG MARKER: == sanityn test 41c: pdirops: create vs link ======================================================================== 13:35:52 (1778348152) [ 1276.630841] Lustre: DEBUG MARKER: == sanityn test 41d: pdirops: create vs unlink ======================================================================== 13:35:58 (1778348158) [ 1282.651960] Lustre: DEBUG MARKER: == sanityn test 41e: pdirops: create and rename (tgt) ======================================================================== 13:36:04 (1778348164) [ 1285.504115] LustreError: 5786:0:(mdt_handler.c:4161:mdt_object_pdo_lock()) cfs_fail_timeout interrupted [ 1285.512637] LustreError: 5786:0:(mdt_handler.c:4161:mdt_object_pdo_lock()) Skipped 2 previous similar messages [ 1288.468620] Lustre: DEBUG MARKER: == sanityn test 41f: pdirops: create and rename (src) ======================================================================== 13:36:10 (1778348170) [ 1293.907236] Lustre: DEBUG MARKER: == sanityn test 41g: pdirops: create vs getattr ======================================================================== 13:36:15 (1778348175) [ 1299.431505] Lustre: DEBUG MARKER: == sanityn test 41h: pdirops: create vs readdir ======================================================================== 13:36:21 (1778348181) [ 1304.991460] Lustre: DEBUG MARKER: == sanityn test 41i: reint_open: create vs create ======== 13:36:26 (1778348186) [ 1305.461543] LustreError: 25228:0:(mdt_open.c:1567:mdt_reint_open()) cfs_race id 169 sleeping [ 1305.667315] LustreError: 15397:0:(mdt_open.c:1567:mdt_reint_open()) cfs_fail_race id 169 waking [ 1305.671945] LustreError: 25228:0:(mdt_open.c:1567:mdt_reint_open()) cfs_fail_race id 169 awake: rc=4793 [ 1306.760583] LustreError: 25228:0:(mdt_open.c:1567:mdt_reint_open()) cfs_race id 169 sleeping [ 1306.968102] LustreError: 5786:0:(mdt_open.c:1567:mdt_reint_open()) cfs_fail_race id 169 waking [ 1306.970804] LustreError: 25228:0:(mdt_open.c:1567:mdt_reint_open()) cfs_fail_race id 169 awake: rc=4793 [ 1307.807005] LustreError: 25228:0:(mdt_open.c:1567:mdt_reint_open()) cfs_race id 169 sleeping [ 1308.012922] LustreError: 5784:0:(mdt_open.c:1567:mdt_reint_open()) cfs_fail_race id 169 waking [ 1308.015179] LustreError: 25228:0:(mdt_open.c:1567:mdt_reint_open()) cfs_fail_race id 169 awake: rc=4794 [ 1310.754799] LustreError: 15397:0:(mdt_open.c:1567:mdt_reint_open()) cfs_race id 169 sleeping [ 1310.758812] LustreError: 15397:0:(mdt_open.c:1567:mdt_reint_open()) Skipped 2 previous similar messages [ 1310.960101] LustreError: 25239:0:(mdt_open.c:1567:mdt_reint_open()) cfs_fail_race id 169 waking [ 1310.962353] LustreError: 25239:0:(mdt_open.c:1567:mdt_reint_open()) Skipped 2 previous similar messages [ 1310.964814] LustreError: 15397:0:(mdt_open.c:1567:mdt_reint_open()) cfs_fail_race id 169 awake: rc=4798 [ 1310.969492] LustreError: 15397:0:(mdt_open.c:1567:mdt_reint_open()) Skipped 2 previous similar messages [ 1315.122959] LustreError: 25239:0:(mdt_open.c:1567:mdt_reint_open()) cfs_race id 169 sleeping [ 1315.126319] LustreError: 25239:0:(mdt_open.c:1567:mdt_reint_open()) Skipped 3 previous similar messages [ 1315.326836] LustreError: 5786:0:(mdt_open.c:1567:mdt_reint_open()) cfs_fail_race id 169 waking [ 1315.329380] LustreError: 5786:0:(mdt_open.c:1567:mdt_reint_open()) Skipped 3 previous similar messages [ 1315.332066] LustreError: 25239:0:(mdt_open.c:1567:mdt_reint_open()) cfs_fail_race id 169 awake: rc=4796 [ 1315.334737] LustreError: 25239:0:(mdt_open.c:1567:mdt_reint_open()) Skipped 3 previous similar messages [ 1323.332335] LustreError: 7389:0:(mdt_open.c:1567:mdt_reint_open()) cfs_race id 169 sleeping [ 1323.334633] LustreError: 7389:0:(mdt_open.c:1567:mdt_reint_open()) Skipped 6 previous similar messages [ 1323.536360] LustreError: 15397:0:(mdt_open.c:1567:mdt_reint_open()) cfs_fail_race id 169 waking [ 1323.538537] LustreError: 15397:0:(mdt_open.c:1567:mdt_reint_open()) Skipped 6 previous similar messages [ 1323.541046] LustreError: 7389:0:(mdt_open.c:1567:mdt_reint_open()) cfs_fail_race id 169 awake: rc=4796 [ 1323.544873] LustreError: 7389:0:(mdt_open.c:1567:mdt_reint_open()) Skipped 6 previous similar messages [ 1340.118873] LustreError: 5785:0:(mdt_open.c:1567:mdt_reint_open()) cfs_race id 169 sleeping [ 1340.120917] LustreError: 5785:0:(mdt_open.c:1567:mdt_reint_open()) Skipped 15 previous similar messages [ 1340.324390] LustreError: 15397:0:(mdt_open.c:1567:mdt_reint_open()) cfs_fail_race id 169 waking [ 1340.326428] LustreError: 15397:0:(mdt_open.c:1567:mdt_reint_open()) Skipped 15 previous similar messages [ 1340.328455] LustreError: 5785:0:(mdt_open.c:1567:mdt_reint_open()) cfs_fail_race id 169 awake: rc=4794 [ 1340.333439] LustreError: 5785:0:(mdt_open.c:1567:mdt_reint_open()) Skipped 15 previous similar messages [ 1372.930985] LustreError: 7389:0:(mdt_open.c:1567:mdt_reint_open()) cfs_race id 169 sleeping [ 1372.933276] LustreError: 7389:0:(mdt_open.c:1567:mdt_reint_open()) Skipped 31 previous similar messages [ 1373.137319] LustreError: 11358:0:(mdt_open.c:1567:mdt_reint_open()) cfs_fail_race id 169 waking [ 1373.140090] LustreError: 11358:0:(mdt_open.c:1567:mdt_reint_open()) Skipped 31 previous similar messages [ 1373.142888] LustreError: 7389:0:(mdt_open.c:1567:mdt_reint_open()) cfs_fail_race id 169 awake: rc=4793 [ 1373.147383] LustreError: 7389:0:(mdt_open.c:1567:mdt_reint_open()) Skipped 31 previous similar messages [ 1438.176121] LustreError: 25228:0:(mdt_open.c:1594:mdt_reint_open()) cfs_fail_race id 16a awake: rc=0 [ 1438.179236] LustreError: 25228:0:(mdt_open.c:1594:mdt_reint_open()) Skipped 39 previous similar messages [ 1438.185915] LustreError: 15407:0:(mdt_open.c:1594:mdt_reint_open()) cfs_fail_race id 16a waking [ 1438.188289] LustreError: 15407:0:(mdt_open.c:1594:mdt_reint_open()) Skipped 39 previous similar messages [ 1439.136262] LustreError: 5785:0:(mdt_open.c:1594:mdt_reint_open()) cfs_race id 16a sleeping [ 1439.139579] LustreError: 5785:0:(mdt_open.c:1594:mdt_reint_open()) Skipped 40 previous similar messages [ 1568.224137] LustreError: 5785:0:(mdt_open.c:1594:mdt_reint_open()) cfs_fail_race id 16a awake: rc=0 [ 1568.229460] LustreError: 5785:0:(mdt_open.c:1594:mdt_reint_open()) Skipped 20 previous similar messages [ 1568.252147] LustreError: 15407:0:(mdt_open.c:1594:mdt_reint_open()) cfs_fail_race id 16a waking [ 1568.256637] LustreError: 15407:0:(mdt_open.c:1594:mdt_reint_open()) Skipped 20 previous similar messages [ 1569.020442] LustreError: 11358:0:(mdt_open.c:1594:mdt_reint_open()) cfs_race id 16a sleeping [ 1569.022573] LustreError: 11358:0:(mdt_open.c:1594:mdt_reint_open()) Skipped 20 previous similar messages [ 1826.784237] LustreError: 11358:0:(mdt_open.c:1594:mdt_reint_open()) cfs_fail_race id 16a awake: rc=0 [ 1826.788434] LustreError: 11358:0:(mdt_open.c:1594:mdt_reint_open()) Skipped 41 previous similar messages [ 1826.799305] LustreError: 5784:0:(mdt_open.c:1594:mdt_reint_open()) cfs_fail_race id 16a waking [ 1826.805876] LustreError: 5784:0:(mdt_open.c:1594:mdt_reint_open()) Skipped 41 previous similar messages [ 1827.874090] LustreError: 15407:0:(mdt_open.c:1594:mdt_reint_open()) cfs_race id 16a sleeping [ 1827.876190] LustreError: 15407:0:(mdt_open.c:1594:mdt_reint_open()) Skipped 41 previous similar messages [ 2029.147888] Lustre: DEBUG MARKER: == sanityn test 42a: pdirops: mkdir vs mkdir ======================================================================== 13:48:30 (1778348910) [ 2030.614634] LustreError: 7389:0:(mdt_handler.c:4161:mdt_object_pdo_lock()) cfs_fail_timeout id 145 sleeping for 15000ms [ 2030.618464] LustreError: 7389:0:(mdt_handler.c:4161:mdt_object_pdo_lock()) Skipped 11 previous similar messages [ 2032.081100] LustreError: 7389:0:(mdt_handler.c:4161:mdt_object_pdo_lock()) cfs_fail_timeout interrupted [ 2032.086358] LustreError: 7389:0:(mdt_handler.c:4161:mdt_object_pdo_lock()) Skipped 3 previous similar messages [ 2034.971258] Lustre: DEBUG MARKER: == sanityn test 42b: pdirops: mkdir vs create ======================================================================== 13:48:36 (1778348916) [ 2037.832071] LustreError: 5784:0:(mdt_handler.c:4161:mdt_object_pdo_lock()) cfs_fail_timeout interrupted [ 2040.621091] Lustre: DEBUG MARKER: == sanityn test 42c: pdirops: mkdir vs link ======================================================================== 13:48:42 (1778348922) [ 2046.122346] Lustre: DEBUG MARKER: == sanityn test 42d: pdirops: mkdir vs unlink ======================================================================== 13:48:47 (1778348927) [ 2047.196353] LustreError: 15407:0:(mdt_handler.c:4161:mdt_object_pdo_lock()) cfs_fail_timeout id 145 sleeping for 15000ms [ 2047.198942] LustreError: 15407:0:(mdt_handler.c:4161:mdt_object_pdo_lock()) Skipped 2 previous similar messages [ 2048.657080] LustreError: 15407:0:(mdt_handler.c:4161:mdt_object_pdo_lock()) cfs_fail_timeout interrupted [ 2048.661658] LustreError: 15407:0:(mdt_handler.c:4161:mdt_object_pdo_lock()) Skipped 1 previous similar message [ 2051.366703] Lustre: DEBUG MARKER: == sanityn test 42e: pdirops: mkdir and rename (tgt) ======================================================================== 13:48:52 (1778348932) [ 2056.833124] Lustre: DEBUG MARKER: == sanityn test 42f: pdirops: mkdir and rename (src) ======================================================================== 13:48:58 (1778348938) [ 2062.368348] Lustre: DEBUG MARKER: == sanityn test 42g: pdirops: mkdir vs getattr ======================================================================== 13:49:03 (1778348943) [ 2065.201056] LustreError: 25228:0:(mdt_handler.c:4161:mdt_object_pdo_lock()) cfs_fail_timeout interrupted [ 2065.204346] LustreError: 25228:0:(mdt_handler.c:4161:mdt_object_pdo_lock()) Skipped 2 previous similar messages [ 2067.958634] Lustre: DEBUG MARKER: == sanityn test 42h: pdirops: mkdir vs readdir ======================================================================== 13:49:09 (1778348949) [ 2073.672372] Lustre: DEBUG MARKER: == sanityn test 43a: rmdir,mkdir doesn't return -EEXIST ======================================================================== 13:49:15 (1778348955) [ 2091.128031] Lustre: DEBUG MARKER: == sanityn test 43b: pdirops: unlink vs create ======================================================================== 13:49:32 (1778348972) [ 2092.339957] LustreError: 15397:0:(mdt_handler.c:4161:mdt_object_pdo_lock()) cfs_fail_timeout id 145 sleeping for 15000ms [ 2092.342526] LustreError: 15397:0:(mdt_handler.c:4161:mdt_object_pdo_lock()) Skipped 4 previous similar messages [ 2096.096957] Lustre: DEBUG MARKER: == sanityn test 43c: pdirops: unlink vs link ======================================================================== 13:49:37 (1778348977) [ 2098.616062] LustreError: 5785:0:(mdt_handler.c:4161:mdt_object_pdo_lock()) cfs_fail_timeout interrupted [ 2098.618412] LustreError: 5785:0:(mdt_handler.c:4161:mdt_object_pdo_lock()) Skipped 2 previous similar messages [ 2101.016985] Lustre: DEBUG MARKER: == sanityn test 43d: pdirops: unlink vs unlink ======================================================================== 13:49:42 (1778348982) [ 2105.875269] Lustre: DEBUG MARKER: == sanityn test 43e: pdirops: unlink and rename (tgt) ======================================================================== 13:49:47 (1778348987) [ 2110.917178] Lustre: DEBUG MARKER: == sanityn test 43f: pdirops: unlink and rename (src) ======================================================================== 13:49:52 (1778348992) [ 2115.826340] Lustre: DEBUG MARKER: == sanityn test 43g: pdirops: unlink vs getattr ======================================================================== 13:49:57 (1778348997) [ 2120.611986] Lustre: DEBUG MARKER: == sanityn test 43h: pdirops: unlink vs readdir ======================================================================== 13:50:02 (1778349002) [ 2125.406193] Lustre: DEBUG MARKER: == sanityn test 43i: pdirops: unlink vs remote mkdir ===== 13:50:07 (1778349007) [ 2125.849821] Lustre: DEBUG MARKER: SKIP: sanityn test_43i needs >= 2 MDTs [ 2126.366314] Lustre: DEBUG MARKER: == sanityn test 43j: racy mkdir return EEXIST ======================================================================== 13:50:07 (1778349007) [ 2126.795259] LustreError: 5786:0:(mdt_reint.c:687:mdt_create()) cfs_race id 167 sleeping [ 2126.795670] LustreError: 11358:0:(mdt_reint.c:687:mdt_create()) cfs_fail_race id 167 waking [ 2126.800923] LustreError: 5786:0:(mdt_reint.c:687:mdt_create()) cfs_fail_race id 167 awake: rc=4997 [ 2127.473140] LustreError: 25228:0:(mdt_reint.c:687:mdt_create()) cfs_race id 167 sleeping [ 2127.473200] LustreError: 11358:0:(mdt_reint.c:687:mdt_create()) cfs_fail_race id 167 waking [ 2127.476989] LustreError: 25228:0:(mdt_reint.c:687:mdt_create()) Skipped 1 previous similar message [ 2127.478988] LustreError: 11358:0:(mdt_reint.c:687:mdt_create()) Skipped 1 previous similar message [ 2127.482986] LustreError: 25228:0:(mdt_reint.c:687:mdt_create()) cfs_fail_race id 167 awake: rc=4999 [ 2127.485294] LustreError: 25228:0:(mdt_reint.c:687:mdt_create()) Skipped 1 previous similar message [ 2128.508542] LustreError: 5784:0:(mdt_reint.c:687:mdt_create()) cfs_race id 167 sleeping [ 2128.508543] LustreError: 7389:0:(mdt_reint.c:687:mdt_create()) cfs_fail_race id 167 waking [ 2128.508561] LustreError: 7389:0:(mdt_reint.c:687:mdt_create()) Skipped 2 previous similar messages [ 2128.511271] LustreError: 5784:0:(mdt_reint.c:687:mdt_create()) Skipped 2 previous similar messages [ 2128.518538] LustreError: 5784:0:(mdt_reint.c:687:mdt_create()) cfs_fail_race id 167 awake: rc=5000 [ 2128.520847] LustreError: 5784:0:(mdt_reint.c:687:mdt_create()) Skipped 2 previous similar messages [ 2130.561964] LustreError: 11358:0:(mdt_reint.c:687:mdt_create()) cfs_race id 167 sleeping [ 2130.562208] LustreError: 25228:0:(mdt_reint.c:687:mdt_create()) cfs_fail_race id 167 waking [ 2130.564239] LustreError: 11358:0:(mdt_reint.c:687:mdt_create()) Skipped 5 previous similar messages [ 2130.568169] LustreError: 25228:0:(mdt_reint.c:687:mdt_create()) Skipped 5 previous similar messages [ 2130.570147] LustreError: 11358:0:(mdt_reint.c:687:mdt_create()) cfs_fail_race id 167 awake: rc=4994 [ 2130.572529] LustreError: 11358:0:(mdt_reint.c:687:mdt_create()) Skipped 5 previous similar messages [ 2134.674674] LustreError: 5784:0:(mdt_reint.c:687:mdt_create()) cfs_race id 167 sleeping [ 2134.675072] LustreError: 7389:0:(mdt_reint.c:687:mdt_create()) cfs_fail_race id 167 waking [ 2134.677611] LustreError: 5784:0:(mdt_reint.c:687:mdt_create()) Skipped 10 previous similar messages [ 2134.682561] LustreError: 7389:0:(mdt_reint.c:687:mdt_create()) Skipped 10 previous similar messages [ 2134.689775] LustreError: 5784:0:(mdt_reint.c:687:mdt_create()) cfs_fail_race id 167 awake: rc=4996 [ 2134.693377] LustreError: 5784:0:(mdt_reint.c:687:mdt_create()) Skipped 10 previous similar messages [ 2143.066054] LustreError: 11358:0:(mdt_reint.c:687:mdt_create()) cfs_race id 167 sleeping [ 2143.067470] LustreError: 5784:0:(mdt_reint.c:687:mdt_create()) cfs_fail_race id 167 waking [ 2143.070116] LustreError: 11358:0:(mdt_reint.c:687:mdt_create()) Skipped 19 previous similar messages [ 2143.073159] LustreError: 5784:0:(mdt_reint.c:687:mdt_create()) Skipped 19 previous similar messages [ 2143.081428] LustreError: 11358:0:(mdt_reint.c:687:mdt_create()) cfs_fail_race id 167 awake: rc=5000 [ 2143.085606] LustreError: 11358:0:(mdt_reint.c:687:mdt_create()) Skipped 19 previous similar messages [ 2159.459873] LustreError: 5785:0:(mdt_reint.c:687:mdt_create()) cfs_race id 167 sleeping [ 2159.460962] LustreError: 25228:0:(mdt_reint.c:687:mdt_create()) cfs_fail_race id 167 waking [ 2159.466388] LustreError: 25228:0:(mdt_reint.c:687:mdt_create()) Skipped 37 previous similar messages [ 2159.471082] LustreError: 5785:0:(mdt_reint.c:687:mdt_create()) Skipped 37 previous similar messages [ 2159.481364] LustreError: 5785:0:(mdt_reint.c:687:mdt_create()) cfs_fail_race id 167 awake: rc=5000 [ 2159.486232] LustreError: 5785:0:(mdt_reint.c:687:mdt_create()) Skipped 37 previous similar messages [ 2170.327070] Lustre: DEBUG MARKER: == sanityn test 43k: unlink vs create ==================== 13:50:51 (1778349051) [ 2192.442498] LustreError: 5786:0:(mdt_reint.c:1275:mdt_reint_unlink()) cfs_fail_race id 169 waking [ 2192.444559] LustreError: 5786:0:(mdt_reint.c:1275:mdt_reint_unlink()) Skipped 28 previous similar messages [ 2258.247804] LustreError: 5785:0:(mdt_reint.c:1275:mdt_reint_unlink()) cfs_fail_race id 169 waking [ 2258.251161] LustreError: 5785:0:(mdt_reint.c:1275:mdt_reint_unlink()) Skipped 28 previous similar messages [ 2340.133148] LustreError: 5786:0:(mdt_open.c:1567:mdt_reint_open()) cfs_race id 169 sleeping [ 2340.138356] LustreError: 5786:0:(mdt_open.c:1567:mdt_reint_open()) Skipped 104 previous similar messages [ 2340.651301] LustreError: 5786:0:(mdt_open.c:1567:mdt_reint_open()) cfs_fail_race id 169 awake: rc=4492 [ 2340.656843] LustreError: 5786:0:(mdt_open.c:1567:mdt_reint_open()) Skipped 105 previous similar messages [ 2388.210773] LustreError: 7389:0:(mdt_reint.c:1275:mdt_reint_unlink()) cfs_fail_race id 169 waking [ 2388.217973] LustreError: 7389:0:(mdt_reint.c:1275:mdt_reint_unlink()) Skipped 55 previous similar messages [ 2632.766109] Lustre: DEBUG MARKER: == sanityn test 44a: pdirops: rename tgt vs mkdir ======================================================================== 13:58:34 (1778349514) [ 2633.969107] LustreError: 5798:0:(mdt_reint.c:2751:mdt_lock_two_dirs()) cfs_fail_timeout id 146 sleeping for 10000ms [ 2633.971901] LustreError: 5798:0:(mdt_reint.c:2751:mdt_lock_two_dirs()) Skipped 6 previous similar messages [ 2635.432065] LustreError: 5798:0:(mdt_reint.c:2751:mdt_lock_two_dirs()) cfs_fail_timeout interrupted [ 2635.435623] LustreError: 5798:0:(mdt_reint.c:2751:mdt_lock_two_dirs()) Skipped 5 previous similar messages [ 2637.804309] Lustre: DEBUG MARKER: == sanityn test 44b: pdirops: rename tgt vs create ======================================================================== 13:58:39 (1778349519) [ 2643.557108] Lustre: DEBUG MARKER: == sanityn test 44c: pdirops: rename tgt vs link ======================================================================== 13:58:45 (1778349525) [ 2649.852759] Lustre: DEBUG MARKER: == sanityn test 44d: pdirops: rename tgt vs unlink ======================================================================== 13:58:51 (1778349531) [ 2655.977575] Lustre: DEBUG MARKER: == sanityn test 44e: pdirops: rename tgt and rename (tgt) ======================================================================== 13:58:57 (1778349537) [ 2661.976474] Lustre: DEBUG MARKER: == sanityn test 44f: pdirops: rename tgt and rename (src) ======================================================================== 13:59:03 (1778349543) [ 2667.617744] Lustre: DEBUG MARKER: == sanityn test 44g: pdirops: rename tgt vs getattr ======================================================================== 13:59:09 (1778349549) [ 2673.450278] Lustre: DEBUG MARKER: == sanityn test 44h: pdirops: rename tgt vs readdir ======================================================================== 13:59:15 (1778349555) [ 2680.216637] Lustre: DEBUG MARKER: == sanityn test 44i: pdirops: rename tgt vs remote mkdir ========================================================== 13:59:21 (1778349561) [ 2680.935254] Lustre: DEBUG MARKER: SKIP: sanityn test_44i needs >= 2 MDTs [ 2681.782957] Lustre: DEBUG MARKER: == sanityn test 45a: rename,mkdir doesn't return -EEXIST ======================================================================== 13:59:23 (1778349563) [ 2715.599648] Lustre: DEBUG MARKER: == sanityn test 45b: pdirops: rename src vs create ======================================================================== 13:59:57 (1778349597) [ 2721.078840] Lustre: DEBUG MARKER: == sanityn test 45c: pdirops: rename src vs link ======================================================================== 14:00:02 (1778349602) [ 2726.609591] Lustre: DEBUG MARKER: == sanityn test 45d: pdirops: rename src vs unlink ======================================================================== 14:00:08 (1778349608) [ 2732.239823] Lustre: DEBUG MARKER: == sanityn test 45e: pdirops: rename src and rename (tgt) ======================================================================== 14:00:13 (1778349613) [ 2738.581992] Lustre: DEBUG MARKER: == sanityn test 45f: pdirops: rename src and rename (src) ======================================================================== 14:00:19 (1778349619) [ 2744.220691] Lustre: DEBUG MARKER: == sanityn test 45g: pdirops: rename src vs getattr ======================================================================== 14:00:25 (1778349625) [ 2749.291286] Lustre: DEBUG MARKER: == sanityn test 45h: pdirops: unlink vs readdir ======================================================================== 14:00:30 (1778349630) [ 2754.113333] Lustre: DEBUG MARKER: == sanityn test 45i: pdirops: rename src vs remote mkdir ========================================================== 14:00:35 (1778349635) [ 2754.704296] Lustre: DEBUG MARKER: SKIP: sanityn test_45i needs >= 2 MDTs [ 2755.372807] Lustre: DEBUG MARKER: == sanityn test 45j: read vs rename ====================== 14:00:36 (1778349636) [ 2757.174971] LustreError: 5799:0:(mdt_reint.c:2910:mdt_reint_rename()) cfs_fail_race id 169 waking [ 2757.176973] LustreError: 5799:0:(mdt_reint.c:2910:mdt_reint_rename()) Skipped 105 previous similar messages [ 2940.526478] LustreError: 25239:0:(mdt_open.c:1567:mdt_reint_open()) cfs_race id 169 sleeping [ 2940.529674] LustreError: 25239:0:(mdt_open.c:1567:mdt_reint_open()) Skipped 203 previous similar messages [ 2941.038293] LustreError: 25239:0:(mdt_open.c:1567:mdt_reint_open()) cfs_fail_race id 169 awake: rc=4493 [ 2941.040858] LustreError: 25239:0:(mdt_open.c:1567:mdt_reint_open()) Skipped 203 previous similar messages [ 3245.719983] Lustre: DEBUG MARKER: == sanityn test 46a: pdirops: link vs mkdir ======================================================================== 14:08:47 (1778350127) [ 3247.316746] LustreError: 5785:0:(mdt_handler.c:4161:mdt_object_pdo_lock()) cfs_fail_timeout id 145 sleeping for 15000ms [ 3247.322056] LustreError: 5785:0:(mdt_handler.c:4161:mdt_object_pdo_lock()) Skipped 14 previous similar messages [ 3248.888090] LustreError: 5785:0:(mdt_handler.c:4161:mdt_object_pdo_lock()) cfs_fail_timeout interrupted [ 3248.894388] LustreError: 5785:0:(mdt_handler.c:4161:mdt_object_pdo_lock()) Skipped 14 previous similar messages [ 3252.092801] Lustre: DEBUG MARKER: == sanityn test 46b: pdirops: link vs create ======================================================================== 14:08:53 (1778350133) [ 3257.982180] Lustre: DEBUG MARKER: == sanityn test 46c: pdirops: link vs link ======================================================================== 14:08:59 (1778350139) [ 3263.697801] Lustre: DEBUG MARKER: == sanityn test 46d: pdirops: link vs unlink ======================================================================== 14:09:05 (1778350145) [ 3270.186864] Lustre: DEBUG MARKER: == sanityn test 46e: pdirops: link and rename (tgt) ======================================================================== 14:09:11 (1778350151) [ 3276.295011] Lustre: DEBUG MARKER: == sanityn test 46f: pdirops: link and rename (src) ======================================================================== 14:09:17 (1778350157) [ 3282.422338] Lustre: DEBUG MARKER: == sanityn test 46g: pdirops: link vs getattr ======================================================================== 14:09:23 (1778350163) [ 3288.490559] Lustre: DEBUG MARKER: == sanityn test 46h: pdirops: link vs readdir ======================================================================== 14:09:30 (1778350170) [ 3295.087451] Lustre: DEBUG MARKER: == sanityn test 46i: pdirops: link vs remote mkdir ======= 14:09:36 (1778350176) [ 3295.887815] Lustre: DEBUG MARKER: SKIP: sanityn test_46i needs >= 2 MDTs [ 3296.662005] Lustre: DEBUG MARKER: == sanityn test 47a: pdirops: remote mkdir vs mkdir ====== 14:09:38 (1778350178) [ 3297.311077] Lustre: DEBUG MARKER: SKIP: sanityn test_47a needs >= 2 MDTs [ 3298.153564] Lustre: DEBUG MARKER: == sanityn test 47b: pdirops: remote mkdir vs create ===== 14:09:39 (1778350179) [ 3298.864265] Lustre: DEBUG MARKER: SKIP: sanityn test_47b needs >= 2 MDTs [ 3299.784627] Lustre: DEBUG MARKER: == sanityn test 47c: pdirops: remote mkdir vs link ======= 14:09:41 (1778350181) [ 3300.434764] Lustre: DEBUG MARKER: SKIP: sanityn test_47c needs >= 2 MDTs [ 3301.195429] Lustre: DEBUG MARKER: == sanityn test 47d: pdirops: remote mkdir vs unlink ===== 14:09:42 (1778350182) [ 3302.000365] Lustre: DEBUG MARKER: SKIP: sanityn test_47d needs >= 2 MDTs [ 3302.937940] Lustre: DEBUG MARKER: == sanityn test 47e: pdirops: remote mkdir and rename (tgt) ========================================================== 14:09:44 (1778350184) [ 3303.674895] Lustre: DEBUG MARKER: SKIP: sanityn test_47e needs >= 2 MDTs [ 3304.456501] Lustre: DEBUG MARKER: == sanityn test 47f: pdirops: remote mkdir and rename (src) ========================================================== 14:09:45 (1778350185) [ 3305.180481] Lustre: DEBUG MARKER: SKIP: sanityn test_47f needs >= 2 MDTs [ 3305.782801] Lustre: DEBUG MARKER: == sanityn test 47g: pdirops: remote mkdir vs getattr ==== 14:09:47 (1778350187) [ 3306.341950] Lustre: DEBUG MARKER: SKIP: sanityn test_47g needs >= 2 MDTs [ 3307.057323] Lustre: DEBUG MARKER: == sanityn test 50: osc lvb attrs: enqueue vs. CP AST ======================================================================== 14:09:48 (1778350188) [ 3314.812544] Lustre: DEBUG MARKER: == sanityn test 51a: layout lock: refresh layout should work ========================================================== 14:09:56 (1778350196) [ 3319.823959] Lustre: DEBUG MARKER: == sanityn test 51b: layout lock: glimpse should be able to restart if layout changed ========================================================== 14:10:01 (1778350201) [ 3334.858577] Lustre: DEBUG MARKER: == sanityn test 51c: layout lock: IT_LAYOUT blocked and correct layout can be returned ========================================================== 14:10:16 (1778350216) [ 3337.312107] LustreError: 5785:0:(mdt_open.c:973:mdt_object_open_lock()) cfs_fail_timeout id 172 awake [ 3337.315479] LustreError: 5785:0:(mdt_open.c:973:mdt_object_open_lock()) Skipped 9 previous similar messages [ 3341.685860] Lustre: DEBUG MARKER: == sanityn test 51d: layout lock: losing layout lock should clean up memory map region ========================================================== 14:10:23 (1778350223) [ 3345.123412] Lustre: DEBUG MARKER: == sanityn test 51e: lfs getstripe does not break leases, part 2 ========================================================== 14:10:26 (1778350226) [ 3349.605300] Lustre: DEBUG MARKER: == sanityn test 54: rename locking ======================= 14:10:31 (1778350231) [ 3355.112065] LustreError: 5799:0:(mdt_reint.c:2740:mdt_lock_two_dirs()) cfs_fail_timeout id 153 awake [ 3355.114174] LustreError: 5799:0:(mdt_reint.c:2740:mdt_lock_two_dirs()) Skipped 1 previous similar message [ 3371.888143] LustreError: 5798:0:(mdt_reint.c:2943:mdt_reint_rename()) cfs_fail_timeout id 154 awake [ 3371.892989] LustreError: 5798:0:(mdt_reint.c:2943:mdt_reint_rename()) Skipped 2 previous similar messages [ 3374.644765] Lustre: DEBUG MARKER: == sanityn test 55a: rename vs unlink target dir ========= 14:10:56 (1778350256) [ 3383.033227] Lustre: DEBUG MARKER: == sanityn test 55b: rename vs unlink source dir ========= 14:11:04 (1778350264) [ 3391.660884] Lustre: DEBUG MARKER: == sanityn test 55c: rename vs unlink orphan target dir == 14:11:13 (1778350273) [ 3405.034697] Lustre: DEBUG MARKER: == sanityn test 55d: rename file vs link ================= 14:11:26 (1778350286) [ 3410.472114] LustreError: 5797:0:(mdt_reint.c:2829:mdt_reint_rename()) cfs_fail_timeout id 155 awake [ 3410.475525] LustreError: 5797:0:(mdt_reint.c:2829:mdt_reint_rename()) Skipped 4 previous similar messages [ 3415.269273] Lustre: DEBUG MARKER: == sanityn test 55e: rename race AB/BA under the same parent dir ========================================================== 14:11:36 (1778350296) [ 3416.033797] Lustre: DEBUG MARKER: SKIP: sanityn test_55e needs >= 2 MDTs [ 3416.651282] Lustre: DEBUG MARKER: == sanityn test 55f: rename: (P1/A -> P2/B) race with (P2/B -> P1/A) ========================================================== 14:11:38 (1778350298) [ 3430.167965] Lustre: DEBUG MARKER: == sanityn test 55g: rename: race with trylock =========== 14:11:51 (1778350311) [ 3445.027540] Lustre: DEBUG MARKER: == sanityn test 56a: test llverdev with single large stripe ========================================================== 14:12:06 (1778350326) [ 3486.847175] Lustre: DEBUG MARKER: == sanityn test 56b: test llverdev and partial verify of wide stripe file ========================================================== 14:12:48 (1778350368) [ 3530.778789] Lustre: DEBUG MARKER: == sanityn test 60: Verify data_version behaviour ======== 14:13:32 (1778350412) [ 3534.365944] Lustre: DEBUG MARKER: == sanityn test 70a: cd directory [ 3537.060684] Lustre: DEBUG MARKER: == sanityn test 70b: remove files after calling rm_entry ========================================================== 14:13:38 (1778350418) [ 3540.337773] Lustre: DEBUG MARKER: == sanityn test 71a: correct file map just after write operation is finished ========================================================== 14:13:41 (1778350421) [ 3540.984686] Lustre: DEBUG MARKER: SKIP: sanityn test_71a ORI-366/LU-1941: FIEMAP unimplemented on ZFS [ 3541.624510] Lustre: DEBUG MARKER: == sanityn test 71b: check fiemap support for stripecount > 1 ========================================================== 14:13:43 (1778350423) [ 3542.460729] Lustre: DEBUG MARKER: SKIP: sanityn test_71b ORI-366/LU-1941: FIEMAP unimplemented on ZFS [ 3543.399873] Lustre: DEBUG MARKER: == sanityn test 71c: check FIEMAP_EXTENT_LAST flag with different extents number ========================================================== 14:13:44 (1778350424) [ 3544.128675] Lustre: DEBUG MARKER: SKIP: sanityn test_71c support only ldiskfs ost [ 3544.901061] Lustre: DEBUG MARKER: == sanityn test 71d: fiemap corruption test with fm_extent_count=0 ========================================================== 14:13:46 (1778350426) [ 3545.444682] Lustre: DEBUG MARKER: SKIP: sanityn test_71d ORI-366/LU-1941: FIEMAP unimplemented on ZFS [ 3546.083130] Lustre: DEBUG MARKER: == sanityn test 72: getxattr/setxattr cache should be consistent between nodes ========================================================== 14:13:47 (1778350427) [ 3549.356069] Lustre: DEBUG MARKER: == sanityn test 73: getxattr should not cause xattr lock cancellation ========================================================== 14:13:50 (1778350430) [ 3552.713232] Lustre: DEBUG MARKER: == sanityn test 74: flock deadlock: different mounts ======================================================================== 14:13:54 (1778350434) [ 3559.673955] Lustre: DEBUG MARKER: == sanityn test 75: osc: upcall after unuse lock============================================================================= 14:14:01 (1778350441) [ 3567.125891] Lustre: DEBUG MARKER: == sanityn test 76: Verify MDT open_files listing ======== 14:14:08 (1778350448) [ 3591.078722] Lustre: DEBUG MARKER: == sanityn test 77a: check FIFO NRS policy =============== 14:14:32 (1778350472) [ 3593.866664] Lustre: DEBUG MARKER: == sanityn test 77b: check CRR-N NRS policy ============== 14:14:35 (1778350475) [ 3598.420944] Lustre: DEBUG MARKER: == sanityn test 77c: check ORR NRS policy ================ 14:14:39 (1778350479) [ 3604.050692] Lustre: DEBUG MARKER: == sanityn test 77d: check TRR nrs policy ================ 14:14:45 (1778350485) [ 3610.231737] Lustre: DEBUG MARKER: == sanityn test 77e: check TBF NID nrs policy ============ 14:14:51 (1778350491) [ 3619.951527] Lustre: DEBUG MARKER: == sanityn test 77f: check TBF JobID nrs policy ========== 14:15:01 (1778350501) [ 3629.122557] Lustre: DEBUG MARKER: == sanityn test 77g: Change TBF type directly ============ 14:15:10 (1778350510) [ 3633.259901] Lustre: DEBUG MARKER: == sanityn test 77h: Wrong policy name should report error, not LBUG ========================================================== 14:15:14 (1778350514) [ 3637.811788] Lustre: DEBUG MARKER: == sanityn test 77i: Change rank of TBF rule ============= 14:15:19 (1778350519) [ 3647.323340] Lustre: DEBUG MARKER: == sanityn test 77j: check TBF-OPCode NRS policy ========= 14:15:28 (1778350528) [ 3702.057076] Lustre: DEBUG MARKER: == sanityn test 77ja: check TBF-UID/GID NRS policy ======= 14:16:23 (1778350583) [ 3835.713919] Lustre: DEBUG MARKER: == sanityn test 77jb: check TBF-UID/GID NRS policy on files that don't belong to us ========================================================== 14:18:37 (1778350717) [ 3975.153688] Lustre: DEBUG MARKER: == sanityn test 77k: check TBF policy with UID/GID/JobID/OPCode expression ========================================================== 14:20:56 (1778350856) [ 4343.793504] Lustre: DEBUG MARKER: == sanityn test 77kb: Check different granular TBF type combination: jobid+opcode ========================================================== 14:27:05 (1778351225) [ 4386.185784] Lustre: DEBUG MARKER: == sanityn test 77kc: Check different granular TBF type combination: nid+opcode ========================================================== 14:27:47 (1778351267) [ 4426.970091] Lustre: DEBUG MARKER: == sanityn test 77kd: Check different granular TBF type combination: nid+jobid ========================================================== 14:28:28 (1778351308) [ 4463.246851] Lustre: DEBUG MARKER: == sanityn test 77ke: Check different granular TBF type combination: jobid+opcode ========================================================== 14:29:04 (1778351344) [ 4544.354298] Lustre: DEBUG MARKER: == sanityn test 77kf: Check different granular TBF type combination: uid+gid ========================================================== 14:30:25 (1778351425) [ 4611.111190] Lustre: DEBUG MARKER: == sanityn test 77kg: check different granular TBF type combination: uid+opcode ========================================================== 14:31:32 (1778351492) [ 4733.144701] Lustre: DEBUG MARKER: == sanityn test 77kh: Verify that Project ID support for NRS TBF rule ========================================================== 14:33:34 (1778351614) [ 4738.133335] Lustre: server umount lustre-MDT0000 complete [ 4739.386976] LustreError: 5769:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1778351620 with bad export cookie 5368516922017400643 [ 4739.394753] LustreError: MGC192.168.204.135@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4748.793330] Lustre: server umount lustre-OST0000 complete [ 4759.932209] Lustre: server umount lustre-OST0001 complete [ 4766.040484] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing load_modules_local [ 4769.468946] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4771.235457] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4772.680310] Lustre: 189019:0:(mgs_llog.c:1348:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 4774.654211] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 4776.716898] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4778.733927] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3684 to 0x240000400:3713) [ 4779.874073] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 4781.696249] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3660 to 0x280000400:3681) [ 4782.505275] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4786.646407] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4788.246498] Lustre: 190569:0:(mgs_llog.c:1348:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 4874.449864] Lustre: DEBUG MARKER: == sanityn test 77ki: Add rule with unsupported TBF type should fail for generic TBF ========================================================== 14:35:56 (1778351756) [ 4883.100154] Lustre: DEBUG MARKER: == sanityn test 77l: check the output of NRS policies for generic TBF ========================================================== 14:36:04 (1778351764) [ 4887.260829] Lustre: DEBUG MARKER: == sanityn test 77m: check NRS Delay slows write RPC processing ========================================================== 14:36:08 (1778351768) [ 4938.638275] Lustre: DEBUG MARKER: == sanityn test 77n: check wildcard support for TBF JobID NRS policy ========================================================== 14:37:00 (1778351820) [ 5007.187222] Lustre: DEBUG MARKER: == sanityn test 77o: Changing rank should not panic ====== 14:38:08 (1778351888) [ 5012.452282] Lustre: DEBUG MARKER: == sanityn test 77q: Parallel TBF rule definitions should not panic ========================================================== 14:38:13 (1778351893) [ 5059.808023] Lustre: DEBUG MARKER: == sanityn test 77p: Check validity of rule names for TBF policies ========================================================== 14:39:01 (1778351941) [ 5074.248070] Lustre: DEBUG MARKER: == sanityn test 77r: Change type of tbf policy at run time ========================================================== 14:39:15 (1778351955) [ 5113.814304] Lustre: DEBUG MARKER: == sanityn test 77s: Check TBF LRU shrinker ============== 14:39:55 (1778351995) [ 5131.296586] Lustre: DEBUG MARKER: == sanityn test 77t: check TBF minrate parsing and output ========================================================== 14:40:12 (1778352012) [ 5143.931943] Lustre: DEBUG MARKER: == sanityn test 77u: check TBF minrate on NID and generic rules ========================================================== 14:40:25 (1778352025) [ 5154.807805] Lustre: DEBUG MARKER: == sanityn test 77v: verify minimum RPC rate under congestion ========================================================== 14:40:36 (1778352036) [ 5155.395898] Lustre: DEBUG MARKER: SKIP: sanityn test_77v need OSTs and MDTs on separate nodes [ 5156.152749] Lustre: DEBUG MARKER: == sanityn test 78: Enable policy and specify tunings right away ========================================================== 14:40:37 (1778352037) [ 5160.518632] Lustre: DEBUG MARKER: == sanityn test 79: xattr: intent error ================== 14:40:41 (1778352041) [ 5161.325739] LustreError: 188609:0:(mdt_handler.c:5448:mdt_intent_opc()) cfs_fail_timeout id 160 sleeping for 10000ms [ 5161.332769] LustreError: 188609:0:(mdt_handler.c:5448:mdt_intent_opc()) Skipped 23 previous similar messages [ 5171.328062] LustreError: 188609:0:(mdt_handler.c:5448:mdt_intent_opc()) cfs_fail_timeout id 160 awake [ 5171.330756] LustreError: 188609:0:(mdt_handler.c:5448:mdt_intent_opc()) Skipped 5 previous similar messages [ 5171.333347] Lustre: *** cfs_fail_loc=131, val=0*** [ 5174.061621] Lustre: DEBUG MARKER: == sanityn test 80a: migrate directory when some children is being opened ========================================================== 14:40:55 (1778352055) [ 5174.633952] Lustre: DEBUG MARKER: SKIP: sanityn test_80a needs >= 2 MDTs [ 5175.482727] Lustre: DEBUG MARKER: == sanityn test 80b: Accessing directory during migration ========================================================== 14:40:56 (1778352056) [ 5176.160662] Lustre: DEBUG MARKER: SKIP: sanityn test_80b needs >= 2 MDTs [ 5176.900109] Lustre: DEBUG MARKER: == sanityn test 81a: rename and stat under striped directory ========================================================== 14:40:58 (1778352058) [ 5177.429930] Lustre: DEBUG MARKER: SKIP: sanityn test_81a needs >= 2 MDTs [ 5178.099726] Lustre: DEBUG MARKER: == sanityn test 81b: rename under striped directory doesn't deadlock ========================================================== 14:40:59 (1778352059) [ 5178.656195] Lustre: DEBUG MARKER: SKIP: sanityn test_81b We need at least 2 MDTs for this test [ 5179.367682] Lustre: DEBUG MARKER: == sanityn test 81c: rename revoke LOOKUP lock for remote object ========================================================== 14:41:00 (1778352060) [ 5180.016609] Lustre: DEBUG MARKER: SKIP: sanityn test_81c needs >= 4 MDTs [ 5180.616387] Lustre: DEBUG MARKER: == sanityn test 81d: parallel rename file cross-dir on same MDT ========================================================== 14:41:02 (1778352062) [ 5217.876337] Lustre: DEBUG MARKER: == sanityn test 82: fsetxattr and fgetxattr on orphan files ========================================================== 14:41:39 (1778352099) [ 5220.967025] Lustre: DEBUG MARKER: == sanityn test 83: access striped directory while it is being created/unlinked ========================================================== 14:41:42 (1778352102) [ 5221.765667] Lustre: DEBUG MARKER: SKIP: sanityn test_83 needs >= 2 MDTs [ 5222.680331] Lustre: DEBUG MARKER: == sanityn test 84: 0-nlink race in lu_object_find() ===== 14:41:43 (1778352103) [ 5223.206257] LustreError: 188609:0:(lu_object.c:911:lu_object_find_at()) cfs_race id 60b sleeping [ 5228.221579] LustreError: 188640:0:(mdt_reint.c:1470:mdt_reint_unlink()) cfs_fail_race id 60b waking [ 5228.224629] LustreError: 188609:0:(lu_object.c:911:lu_object_find_at()) cfs_fail_race id 60b awake: rc=0 [ 5231.005961] Lustre: DEBUG MARKER: == sanityn test 85: Lustre API root cache race =========== 14:41:52 (1778352112) [ 5234.180575] Lustre: DEBUG MARKER: == sanityn test 90: open/create and unlink striped directory ========================================================== 14:41:55 (1778352115) [ 5234.855670] Lustre: DEBUG MARKER: SKIP: sanityn test_90 needs >= 2 MDTs [ 5235.533212] Lustre: DEBUG MARKER: == sanityn test 91: chmod and unlink striped directory === 14:41:57 (1778352117) [ 5236.112395] Lustre: DEBUG MARKER: SKIP: sanityn test_91 needs >= 2 MDTs [ 5236.723350] Lustre: DEBUG MARKER: == sanityn test 92: create remote directory under orphan directory ========================================================== 14:41:58 (1778352118) [ 5237.452392] Lustre: DEBUG MARKER: SKIP: sanityn test_92 needs >= 2 MDTs [ 5238.194148] Lustre: DEBUG MARKER: == sanityn test 93: alloc_rr should not allocate on same ost ========================================================== 14:41:59 (1778352119) [ 5239.353595] LustreError: 207067:0:(lod_qos.c:658:lod_check_and_reserve_ost()) cfs_fail_timeout id 163 sleeping for 2000ms [ 5241.440076] LustreError: 207067:0:(lod_qos.c:658:lod_check_and_reserve_ost()) cfs_fail_timeout id 163 awake [ 5248.077707] Lustre: DEBUG MARKER: == sanityn test 94: signal vs CP callback race =========== 14:42:09 (1778352129) [ 5259.251502] Lustre: DEBUG MARKER: == sanityn test 95a: Check readpage() on a page that was removed from page cache ========================================================== 14:42:20 (1778352140) [ 5274.866785] Lustre: DEBUG MARKER: == sanityn test 95b: Check readpage() on a page that is no longer uptodate ========================================================== 14:42:36 (1778352156) [ 5283.887803] Lustre: DEBUG MARKER: == sanityn test 100a: DoM: glimpse RPCs for stat without IO lock (DoM only file) ========================================================== 14:42:45 (1778352165) [ 5284.563573] Lustre: DEBUG MARKER: SKIP: sanityn test_100a Reserved for glimpse-ahead [ 5285.421103] Lustre: DEBUG MARKER: == sanityn test 100b: DoM: no glimpse RPC for stat with IO lock (DoM only file) ========================================================== 14:42:46 (1778352166) [ 5288.679119] Lustre: DEBUG MARKER: == sanityn test 100c: DoM: write vs stat without IO lock (combined file) ========================================================== 14:42:50 (1778352170) [ 5291.850081] Lustre: DEBUG MARKER: == sanityn test 100d: DoM: write+truncate vs stat without IO lock (combined file) ========================================================== 14:42:53 (1778352173) [ 5295.065549] Lustre: DEBUG MARKER: == sanityn test 100e: DoM: read on open and file size ==== 14:42:56 (1778352176) [ 5298.303384] Lustre: DEBUG MARKER: == sanityn test 101a: Discard DoM data on unlink ========= 14:42:59 (1778352179) [ 5300.986440] Lustre: DEBUG MARKER: == sanityn test 101b: Discard DoM data on rename ========= 14:43:02 (1778352182) [ 5303.982964] Lustre: DEBUG MARKER: == sanityn test 101c: Discard DoM data on close-unlink === 14:43:05 (1778352185) [ 5308.217621] Lustre: DEBUG MARKER: SKIP: sanityn test_102 skipping ALWAYS excluded test 102 [ 5309.007974] Lustre: DEBUG MARKER: == sanityn test 103: Test size correctness with lockahead ========================================================== 14:43:10 (1778352190) [ 5309.692125] LustreError: 189228:0:(tgt_handler.c:2738:tgt_brw_write()) cfs_fail_timeout id 415 sleeping for 2000ms [ 5309.697964] LustreError: 189228:0:(tgt_handler.c:2738:tgt_brw_write()) Skipped 3 previous similar messages [ 5311.784122] LustreError: 189228:0:(tgt_handler.c:2738:tgt_brw_write()) cfs_fail_timeout id 415 awake [ 5311.789331] LustreError: 189228:0:(tgt_handler.c:2738:tgt_brw_write()) Skipped 3 previous similar messages [ 5317.490651] Lustre: DEBUG MARKER: == sanityn test 104: Verify that MDS stores atime/mtime/ctime during close ========================================================== 14:43:18 (1778352198) [ 5318.200245] Lustre: DEBUG MARKER: SKIP: sanityn test_104 ldiskfs only test [ 5319.043514] Lustre: DEBUG MARKER: == sanityn test 105: Glimpse and lock cancel race ======== 14:43:20 (1778352200) [ 5342.925845] Lustre: DEBUG MARKER: == sanityn test 106a: Verify the btime via statx() ======= 14:43:44 (1778352224) [ 5343.696368] Lustre: DEBUG MARKER: SKIP: sanityn test_106a Test only for ldiskfs and statx() supported [ 5344.503460] Lustre: DEBUG MARKER: == sanityn test 106b: Glimpse RPCs test for statx ======== 14:43:45 (1778352225) [ 5348.061541] Lustre: DEBUG MARKER: == sanityn test 106c: Verify statx attributes mask ======= 14:43:49 (1778352229) [ 5351.237553] Lustre: DEBUG MARKER: == sanityn test 107a: Basic grouplock conflict =========== 14:43:52 (1778352232) [ 5356.659697] Lustre: DEBUG MARKER: == sanityn test 107b: Grouplock is added to the head of waiting list ========================================================== 14:43:58 (1778352238) [ 5366.136445] Lustre: DEBUG MARKER: == sanityn test 108a: lseek: parallel updates ============ 14:44:07 (1778352247) [ 5373.619655] Lustre: DEBUG MARKER: == sanityn test 109: Race with several mount instances on 1 node ========================================================== 14:44:14 (1778352254) [ 5375.843739] Lustre: DEBUG MARKER: Iteration 0 [ 5386.463344] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing load_modules_local [ 5388.615184] Lustre: DEBUG MARKER: Iteration 1 [ 5398.156564] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing load_modules_local [ 5399.941328] Lustre: DEBUG MARKER: Iteration 2 [ 5410.328966] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing load_modules_local [ 5416.142428] Lustre: DEBUG MARKER: == sanityn test 110: do not grant another lock on resend ========================================================== 14:44:57 (1778352297) [ 5472.256137] LustreError: 207996:0:(mdt_handler.c:2522:mdt_getattr_name_lock()) cfs_fail_timeout id 534 awake [ 5472.261736] LustreError: 207996:0:(mdt_handler.c:2522:mdt_getattr_name_lock()) Skipped 1 previous similar message [ 5472.267700] Lustre: 207996:0:(service.c:2561:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (51/3s); client may timeout req@ffff8b01e8f63100 x1864737527703296/t0(0) o101->7058672e-e46f-4908-954a-3fa42e1650d7@192.168.204.35@tcp:435/0 lens 584/640 e 0 to 0 dl 1778352350 ref 1 fl Complete:/600/0 rc 0/0 job:'stat.0' uid:0 gid:0 projid:0 [ 5472.271740] LustreError: 190337:0:(mdt_handler.c:2522:mdt_getattr_name_lock()) cfs_fail_timeout id 534 sleeping for 75000ms [ 5472.291648] LustreError: 190337:0:(mdt_handler.c:2522:mdt_getattr_name_lock()) Skipped 2 previous similar messages [ 5472.875308] Lustre: lustre-MDT0000: Client 7058672e-e46f-4908-954a-3fa42e1650d7 (at 192.168.204.35@tcp) reconnecting [ 5528.165598] Lustre: lustre-MDT0000: Client 7058672e-e46f-4908-954a-3fa42e1650d7 (at 192.168.204.35@tcp) reconnecting [ 5547.280068] LustreError: 190337:0:(mdt_handler.c:2522:mdt_getattr_name_lock()) cfs_fail_timeout id 534 awake [ 5547.283920] LustreError: 190337:0:(mdt_handler.c:2522:mdt_getattr_name_lock()) Skipped 2 previous similar messages [ 5584.470095] Lustre: lustre-MDT0000: Client 7058672e-e46f-4908-954a-3fa42e1650d7 (at 192.168.204.35@tcp) reconnecting [ 5585.107785] Lustre: DEBUG MARKER: == sanityn test 111: A racy rename/link an open file should not cause fs corruption ========================================================== 14:47:46 (1778352466) [ 5585.837286] Lustre: DEBUG MARKER: SKIP: sanityn test_111 needs >= 2 MDTs [ 5586.665080] Lustre: DEBUG MARKER: == sanityn test 112: update max-inherit in default LMV === 14:47:48 (1778352468) [ 5587.391544] Lustre: DEBUG MARKER: SKIP: sanityn test_112 We need at least 2 MDTs for this test [ 5588.111295] Lustre: DEBUG MARKER: == sanityn test 113: check servers of specified fs ======= 14:47:49 (1778352469) [ 5591.158995] Lustre: DEBUG MARKER: == sanityn test 114: implicit default LMV inherit ======== 14:47:52 (1778352472) [ 5591.903568] Lustre: DEBUG MARKER: SKIP: sanityn test_114 We need at least 2 MDTs for this test [ 5592.801742] Lustre: DEBUG MARKER: == sanityn test 115: ldiskfs doesn't check direntry for uniqueness ========================================================== 14:47:54 (1778352474) [ 5593.628177] Lustre: DEBUG MARKER: SKIP: sanityn test_115 ldiskfs only test [ 5594.547594] Lustre: DEBUG MARKER: == sanityn test 116: DNE: Set default LMV layout from a remote client ========================================================== 14:47:55 (1778352475) [ 5595.261592] Lustre: DEBUG MARKER: SKIP: sanityn test_116 needs >= 2 MDTs [ 5596.213490] Lustre: DEBUG MARKER: == sanityn test 121: trunc append race =================== 14:47:57 (1778352477) [ 5601.513141] Lustre: DEBUG MARKER: == sanityn test 200: service remains healthy while able to process request ========================================================== 14:48:02 (1778352482) [ 5610.464268] Lustre: 189226:0:(service.c:1608:ptlrpc_at_send_early_reply()) @@@ Could not add any time (4/3), not sending early reply req@ffff8b01f48e6d80 x1864737527746432/t0(0) o4->7058672e-e46f-4908-954a-3fa42e1650d7@192.168.204.35@tcp:581/0 lens 4584/0 e 0 to 0 dl 1778352496 ref 2 fl New:/600/ffffffff rc 0/-1 job:'dd.0' uid:0 gid:0 projid:0 [ 5619.885648] Lustre: 220779:0:(service.c:3935:ptlrpc_svcpt_health_check()) lustre-OST0000: notice - request waiting 16s, service 16s [ 5620.258100] Lustre: lustre-OST0000: Client 7058672e-e46f-4908-954a-3fa42e1650d7 (at 192.168.204.35@tcp) reconnecting [ 5623.313666] Lustre: 220829:0:(service.c:3935:ptlrpc_svcpt_health_check()) lustre-OST0000: notice - request waiting 19s, service 19s [ 5636.576193] Lustre: 189227:0:(service.c:1608:ptlrpc_at_send_early_reply()) @@@ Could not add any time (4/-3), not sending early reply req@ffff8b00ee033800 x1864737527755904/t0(0) o4->7058672e-e46f-4908-954a-3fa42e1650d7@192.168.204.35@tcp:607/0 lens 4584/448 e 0 to 0 dl 1778352522 ref 2 fl Interpret:/600/0 rc 0/0 job:'dd.0' uid:0 gid:0 projid:0 [ 5636.585026] Lustre: 189227:0:(service.c:1608:ptlrpc_at_send_early_reply()) Skipped 8 previous similar messages [ 5636.711442] Lustre: lustre-OST0000: Client 7058672e-e46f-4908-954a-3fa42e1650d7 (at 192.168.204.35@tcp) reconnecting [ 5642.720194] Lustre: 189227:0:(service.c:1608:ptlrpc_at_send_early_reply()) @@@ Could not add any time (5/4), not sending early reply req@ffff8b01f6a2ea00 x1864737527746432/t0(0) o4->7058672e-e46f-4908-954a-3fa42e1650d7@192.168.204.35@tcp:614/0 lens 4584/0 e 0 to 0 dl 1778352529 ref 2 fl New:/602/ffffffff rc 0/-1 job:'dd.0' uid:0 gid:0 projid:0 [ 5642.736237] Lustre: 189227:0:(service.c:1608:ptlrpc_at_send_early_reply()) Skipped 6 previous similar messages [ 5652.072475] Lustre: lustre-OST0000: Client 7058672e-e46f-4908-954a-3fa42e1650d7 (at 192.168.204.35@tcp) reconnecting [ 5663.712313] Lustre: 189227:0:(service.c:1608:ptlrpc_at_send_early_reply()) @@@ Could not add any time (5/-10), not sending early reply req@ffff8b00c927f100 x1864737527761024/t0(0) o4->7058672e-e46f-4908-954a-3fa42e1650d7@192.168.204.35@tcp:635/0 lens 4584/448 e 0 to 0 dl 1778352550 ref 2 fl Interpret:/600/0 rc 0/0 job:'dd.0' uid:0 gid:0 projid:0 [ 5663.735355] Lustre: 189227:0:(service.c:1608:ptlrpc_at_send_early_reply()) Skipped 1 previous similar message [ 5664.434764] Lustre: 217382:0:(service.c:2561:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (26/2s); client may timeout req@ffff8b01f6a2e300 x1864737527746304/t8589939368(0) o4->7058672e-e46f-4908-954a-3fa42e1650d7@192.168.204.35@tcp:614/0 lens 4584/448 e 0 to 0 dl 1778352544 ref 1 fl Complete:/602/0 rc 0/0 job:'dd.0' uid:0 gid:0 projid:0 [ 5664.458665] Lustre: 217382:0:(service.c:2561:ptlrpc_server_handle_request()) Skipped 1 previous similar message [ 5669.174973] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0000-osc-ffff9e5386056000.ost_server_uuid 50 [ 5669.942424] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9e5386056000.ost_server_uuid in IDLE state after 0 sec [ 5670.579918] Lustre: DEBUG MARKER: cleanup: ====================================================== [ 5671.369919] Lustre: DEBUG MARKER: == sanityn test complete, duration 5409 sec ============== 14:49:12 (1778352552) [ 5672.230135] Lustre: DEBUG MARKER: === sanityn: start cleanup 14:49:13 (1778352553) === [ 5747.625093] Lustre: DEBUG MARKER: === sanityn: finish cleanup 14:50:28 (1778352628) === [ 5752.801673] Lustre: lustre-MDT0000-lwp-OST0001: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 5752.802336] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5752.811816] Lustre: Skipped 1 previous similar message [ 5755.208503] Lustre: server umount lustre-MDT0000 complete [ 5757.120282] LustreError: 189249:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1778352638 with bad export cookie 5368516922019550084 [ 5757.121705] LustreError: MGC192.168.204.135@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5757.123885] LustreError: 189249:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 5757.177930] Lustre: server umount lustre-OST0000 complete [ 5759.137976] Lustre: server umount lustre-OST0001 complete [ 5764.910602] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing unload_modules_local [ 5766.469901] Key type lgssc unregistered [ 5766.634776] LNet: 222666:0:(lib-ptl.c:967:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 5766.639940] LNetError: 222666:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 5766.651722] LNet: Removed LNI 192.168.204.135@tcp [ 5767.075153] Key type .llcrypt unregistered [ 5767.077561] Key type ._llcrypt unregistered