[ 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.16.2-1.fc38 04/01/2014 [ 0.000000] Hypervisor detected: KVM [ 0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00 [ 0.000000] kvm-clock: using sched offset of 407839665 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2399.998 MHz processor [ 0.000000] last_pfn = 0x146e00 max_arch_pfn = 0x400000000 [ 0.000000] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT [ 0.000000] last_pfn = 0xbffce max_arch_pfn = 0x400000000 [ 0.000000] found SMP MP-table at [mem 0x000f5b30-0x000f5b3f] [ 0.000000] RAMDISK: [mem 0xbcc54000-0xbffbffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F5950 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE1BB7 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE1A53 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 001A13 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE1AC7 000090 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE1B57 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE1B8F 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe1a53-0xbffe1ac6] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe1a52] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe1ac7-0xbffe1b56] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe1b57-0xbffe1b8e] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe1b8f-0xbffe1bb6] [ 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, 524588K 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.001010] APIC: Switch to symmetric I/O mode setup [ 0.003138] x2apic enabled [ 0.004006] Switched APIC routing to physical x2apic. [ 0.005017] kvm-guest: setup PV IPIs [ 0.008563] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.009000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.009019] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.010009] pid_max: default: 32768 minimum: 301 [ 0.012036] LSM: Security Framework initializing [ 0.013039] Yama: becoming mindful. [ 0.014063] SELinux: Initializing. [ 0.015076] *** VALIDATE selinux *** [ 0.023671] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.027689] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.028172] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.029093] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.030113] *** VALIDATE tmpfs *** [ 0.031000] *** VALIDATE proc *** [ 0.032080] *** VALIDATE cgroup *** [ 0.033017] *** VALIDATE cgroup2 *** [ 0.034310] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.035146] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.036003] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.037033] Spectre V2 : User space: Vulnerable [ 0.038008] Speculative Store Bypass: Vulnerable [ 0.041717] debug: unmapping init [mem 0xffffffffab059000-0xffffffffab060fff] [ 0.044165] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.045718] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.046019] ... version: 2 [ 0.047009] ... bit width: 48 [ 0.048007] ... generic registers: 4 [ 0.049008] ... value mask: 0000ffffffffffff [ 0.050008] ... max period: 00007fffffffffff [ 0.051009] ... fixed-purpose events: 3 [ 0.052007] ... event mask: 000000070000000f [ 0.054196] rcu: Hierarchical SRCU implementation. [ 0.056337] smp: Bringing up secondary CPUs ... [ 0.057524] x86: Booting SMP configuration: [ 0.058014] .... node #0, CPUs: #1 #2 #3 [ 0.061713] smp: Brought up 1 node, 4 CPUs [ 0.063008] smpboot: Max logical packages: 1 [ 0.064013] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.275216] node 0 deferred pages initialised in 210ms [ 0.279138] devtmpfs: initialized [ 0.280204] x86/mm: Memory block size: 128MB [ 0.282754] gcov: version magic: 0x41383552 [ 0.285419] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.288114] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.290323] pinctrl core: initialized pinctrl subsystem [ 0.292137] [ 0.292531] ************************************************************* [ 0.294015] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.296008] ** ** [ 0.298008] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.299007] ** ** [ 0.301017] ** This means that this kernel is built to expose internal ** [ 0.303007] ** IOMMU data structures, which may compromise security on ** [ 0.305006] ** your system. ** [ 0.307007] ** ** [ 0.309008] ** If you see this message and you are not debugging the ** [ 0.310006] ** kernel, report this immediately to your vendor! ** [ 0.312007] ** ** [ 0.314008] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.316007] ************************************************************* [ 0.317796] NET: Registered protocol family 16 [ 0.320662] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.322035] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.324040] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.327134] cpuidle: using governor menu [ 0.328604] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.330361] PCI: Using configuration type 1 for base access [ 0.332149] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.340115] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.342013] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.345108] cryptd: max_cpu_qlen set to 1000 [ 0.348386] ACPI: Added _OSI(Module Device) [ 0.349010] ACPI: Added _OSI(Processor Device) [ 0.350011] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.352007] ACPI: Added _OSI(Processor Aggregator Device) [ 0.355327] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.361359] ACPI: Interpreter enabled [ 0.363051] ACPI: PM: (supports S0 S3 S4 S5) [ 0.364013] ACPI: Using IOAPIC for interrupt routing [ 0.366084] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.369363] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.378978] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.381037] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.383021] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.386079] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.390240] acpiphp: Slot [2] registered [ 0.392172] acpiphp: Slot [3] registered [ 0.393095] acpiphp: Slot [4] registered [ 0.394047] acpiphp: Slot [5] registered [ 0.395121] acpiphp: Slot [6] registered [ 0.397129] acpiphp: Slot [7] registered [ 0.398081] acpiphp: Slot [8] registered [ 0.399100] acpiphp: Slot [9] registered [ 0.401105] acpiphp: Slot [10] registered [ 0.402065] acpiphp: Slot [11] registered [ 0.403105] acpiphp: Slot [12] registered [ 0.404064] acpiphp: Slot [13] registered [ 0.405095] acpiphp: Slot [14] registered [ 0.407078] acpiphp: Slot [15] registered [ 0.408058] acpiphp: Slot [16] registered [ 0.409060] acpiphp: Slot [17] registered [ 0.410058] acpiphp: Slot [18] registered [ 0.411058] acpiphp: Slot [19] registered [ 0.412080] acpiphp: Slot [20] registered [ 0.413073] acpiphp: Slot [21] registered [ 0.414000] acpiphp: Slot [22] registered [ 0.414000] acpiphp: Slot [23] registered [ 0.416135] acpiphp: Slot [24] registered [ 0.418085] acpiphp: Slot [25] registered [ 0.419069] acpiphp: Slot [26] registered [ 0.420051] acpiphp: Slot [27] registered [ 0.421051] acpiphp: Slot [28] registered [ 0.421839] acpiphp: Slot [29] registered [ 0.423076] acpiphp: Slot [30] registered [ 0.423919] acpiphp: Slot [31] registered [ 0.425048] PCI host bridge to bus 0000:00 [ 0.425883] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.427022] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.429013] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.432016] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.434015] pci_bus 0000:00: root bus resource [mem 0x180000000-0x1ffffffff window] [ 0.437015] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.438137] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.442181] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.446201] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.454012] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.458048] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.460010] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.462009] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.464010] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.467000] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.468784] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.472031] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.474402] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.478013] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.488923] pci 0000:00:02.0: reg 0x20: [mem 0xfebe4000-0xfebe7fff 64bit pref] [ 0.493009] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.496531] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.509018] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.513013] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.527017] pci 0000:00:05.0: reg 0x20: [mem 0xfebe8000-0xfebebfff 64bit pref] [ 0.541915] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.551019] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.557016] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.573018] pci 0000:00:06.0: reg 0x20: [mem 0xfebec000-0xfebeffff 64bit pref] [ 0.582385] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.589026] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.593019] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.606016] pci 0000:00:07.0: reg 0x20: [mem 0xfebf0000-0xfebf3fff 64bit pref] [ 0.615876] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.621023] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.625014] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.639022] pci 0000:00:08.0: reg 0x20: [mem 0xfebf4000-0xfebf7fff 64bit pref] [ 0.653057] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.659019] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.664012] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.686017] pci 0000:00:09.0: reg 0x20: [mem 0xfebf8000-0xfebfbfff 64bit pref] [ 0.702590] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.710017] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.717017] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.741022] pci 0000:00:0a.0: reg 0x20: [mem 0xfebfc000-0xfebfffff 64bit pref] [ 0.753000] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.754358] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.757319] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.759289] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.761196] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.766133] iommu: Default domain type: Passthrough [ 0.767264] SCSI subsystem initialized [ 0.768078] ACPI: bus type USB registered [ 0.769075] usbcore: registered new interface driver usbfs [ 0.771051] usbcore: registered new interface driver hub [ 0.772042] usbcore: registered new device driver usb [ 0.774139] pps_core: LinuxPPS API ver. 1 registered [ 0.775006] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.777063] PTP clock support registered [ 0.779114] EDAC MC: Ver: 3.0.0 [ 0.781121] PCI: Using ACPI for IRQ routing [ 0.782769] NetLabel: Initializing [ 0.784006] NetLabel: domain hash size = 128 [ 0.785007] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.786053] NetLabel: unlabeled traffic allowed by default [ 0.788141] vgaarb: loaded [ 0.790199] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.791011] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.797004] clocksource: Switched to clocksource kvm-clock [ 0.904706] VFS: Disk quotas dquot_6.6.0 [ 0.906039] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.908329] *** VALIDATE ramfs *** [ 0.909633] *** VALIDATE hugetlbfs *** [ 0.910925] pnp: PnP ACPI init [ 0.912971] pnp: PnP ACPI: found 6 devices [ 0.929575] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.932242] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.933997] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.935846] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.938261] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.940420] pci_bus 0000:00: resource 8 [mem 0x180000000-0x1ffffffff window] [ 0.943148] NET: Registered protocol family 2 [ 0.945644] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.950674] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.954180] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.958438] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.961553] TCP: Hash tables configured (established 65536 bind 65536) [ 0.963812] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.965485] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.967127] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.968851] NET: Registered protocol family 1 [ 0.970699] RPC: Registered named UNIX socket transport module. [ 0.972803] RPC: Registered udp transport module. [ 0.974697] RPC: Registered tcp transport module. [ 0.976141] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.978216] NET: Registered protocol family 44 [ 0.979531] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.981099] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.982777] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.984697] PCI: CLS 0 bytes, default 64 [ 0.985988] Unpacking initramfs... [ 2.268415] debug: unmapping init [mem 0xffff9104bcc54000-0xffff9104bffbffff] [ 2.272540] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.274631] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.277397] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 2.742347] Initialise system trusted keyrings [ 2.744095] Key type blacklist registered [ 2.746169] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.752606] zbud: loaded [ 2.754858] *** VALIDATE nfs *** [ 2.756109] *** VALIDATE nfs4 *** [ 2.757428] pstore: using deflate compression [ 2.760360] Platform Keyring initialized [ 2.865377] NET: Registered protocol family 38 [ 2.867533] Key type asymmetric registered [ 2.869285] Asymmetric key parser 'x509' registered [ 2.870754] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 2.873925] io scheduler mq-deadline registered [ 2.875632] io scheduler kyber registered [ 2.877412] io scheduler bfq registered [ 2.879043] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 2.880921] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 2.883601] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 2.887755] ACPI: Power Button [PWRF] [ 2.976162] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 3.064093] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 3.240760] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 3.328167] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 3.510210] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 3.539681] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.569438] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.577647] Non-volatile memory driver v1.3 [ 3.579331] Linux agpgart interface v0.103 [ 3.617630] virtio_blk virtio1: [vda] 132416 512-byte logical blocks (67.8 MB/64.7 MiB) [ 3.620164] vda: detected capacity change from 0 to 67796992 [ 3.637159] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.639799] vdb: detected capacity change from 0 to 1073741824 [ 3.653091] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.655557] vdc: detected capacity change from 0 to 2621440000 [ 3.671920] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.674565] vdd: detected capacity change from 0 to 2621440000 [ 3.693566] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.697715] vde: detected capacity change from 0 to 4294967296 [ 3.714322] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.717520] vdf: detected capacity change from 0 to 4294967296 [ 3.725104] libphy: Fixed MDIO Bus: probed [ 3.731840] usbcore: registered new interface driver usbserial_generic [ 3.733987] usbserial: USB Serial support registered for generic [ 3.735796] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.739159] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.740519] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.743423] mousedev: PS/2 mouse device common for all mice [ 3.747130] rtc_cmos 00:05: RTC can wake from S4 [ 3.750285] rtc_cmos 00:05: registered as rtc0 [ 3.751663] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.753978] intel_pstate: CPU model not supported [ 3.755297] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.764046] hid: raw HID events driver (C) Jiri Kosina [ 3.766550] usbcore: registered new interface driver usbhid [ 3.769106] usbhid: USB HID core driver [ 3.771379] drop_monitor: Initializing network drop monitor service [ 3.775563] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.779343] Initializing XFRM netlink socket [ 3.779717] NET: Registered protocol family 10 [ 3.780783] Segment Routing with IPv6 [ 3.780825] NET: Registered protocol family 17 [ 3.781098] mpls_gso: MPLS GSO support [ 3.795287] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.796854] RAS: Correctable Errors collector initialized. [ 3.804410] AVX version of gcm_enc/dec engaged. [ 3.806445] AES CTR mode by8 optimization enabled [ 3.888917] sched_clock: Marking stable (3888848918, 0)->(4651272464, -762423546) [ 3.892769] registered taskstats version 1 [ 3.897238] Loading compiled-in X.509 certificates [ 3.899175] zswap: loaded using pool lzo/zbud [ 3.926959] Key type big_key registered [ 3.938454] Key type encrypted registered [ 3.942482] ima: No TPM chip found, activating TPM-bypass! [ 3.944533] ima: Allocated hash algorithm: sha1 [ 3.946294] ima: No architecture policies found [ 3.948099] evm: Initialising EVM extended attributes: [ 3.949629] evm: security.selinux [ 3.950492] evm: security.ima [ 3.951583] evm: security.capability [ 3.952864] evm: HMAC attrs: 0x1 [ 3.955130] rtc_cmos 00:05: setting system clock to 2025-07-25 06:54:03 UTC (1753426443) [ 3.961080] debug: unmapping init [mem 0xffffffffac003000-0xffffffffac1fffff] [ 3.971905] debug: unmapping init [mem 0xffffffffaad82000-0xffffffffab058fff] [ 3.983033] Write protecting the kernel read-only data: 28672k [ 3.987278] debug: unmapping init [mem 0xffffffffa9403000-0xffffffffa95fffff] [ 3.993536] debug: unmapping init [mem 0xffffffffa9d14000-0xffffffffa9dfffff] [ 4.030481] 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) [ 4.037291] systemd[1]: Detected virtualization kvm. [ 4.038638] systemd[1]: Detected architecture x86-64. [ 4.040317] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 4.066704] systemd[1]: No hostname configured. [ 4.068448] systemd[1]: Set hostname to . [ 4.070617] random: systemd: uninitialized urandom read (16 bytes read) [ 4.073059] systemd[1]: Initializing machine ID from random generator. [ 4.128321] random: ln: uninitialized urandom read (6 bytes read) [ 4.257102] random: systemd: uninitialized urandom read (16 bytes read) [ 4.259979] systemd[1]: Started Dispatch Password Requests to Console Directory Watch. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ 4.266722] systemd[1]: Listening on Journal Socket (/dev/log). [ OK ] Listening on Journal Socket (/dev/log). [ 4.271125] systemd[1]: Reached target Initrd Root Device. [ OK ] Reached target Initrd Root Device. [ OK ] Reached target Timers. [ OK ] Reached target Slices. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. [ OK ] Listening on udev Kernel Socket. [ OK ] Reached target Swap. [ OK ] Reached target Local File Systems. [ OK ] Listening on Journal Socket. Starting Create list of required st…ce nodes for the current kernel... Starting Create Volatile Files and Directories... [ OK ] Started Memstrack Anylazing Service. [ OK ] Listening on udev Control Socket. [ OK ] Reached target Sockets. Starting Journal Service... Starting Apply Kernel Variables... Starting Setup Virtual Console... [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Apply Kernel Variables. [ OK ] Started Setup Virtual Console. Starting dracut cmdline hook... Starting Create Static Device Nodes in /dev... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started Journal Service. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 4.984696] device-mapper: uevent: version 1.0.3 [ 4.986924] device-mapper: ioctl: 4.46.0-ioctl (2022-02-22) initialised: dm-devel@redhat.com [ OK ] Started dracut pre-udev hook. Starting udev Kernel Device Manager... [ OK ] Started udev Kernel Device Manager. Starting dracut pre-trigger hook... [ OK ] Started dracut pre-trigger hook. Starting udev Coldplug all Devices... Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. Starting dracut initqueue hook... [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ 5.784781] random: fast init done [ 5.816864] virtio_net virtio0 ens2: renamed from eth0 [ 5.981404] scsi host0: ata_piix [ 6.005563] scsi host1: ata_piix [ 6.007545] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 6.012609] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 10.467698] random: crng init done [ 10.469124] random: 7 urandom warning(s) missed due to ratelimiting [ 10.927356] dracut-initqueue[591]: RTNETLINK answers: File exists Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Mounting /sysroot... [ 12.168825] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped target Timers. [ OK ] Stopped dracut initqueue hook. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped target Basic System. [ OK ] Stopped target Paths. [ OK ] Stopped target Slices. [ OK ] Stopped target Sockets. [ OK ] Stopped target System Initialization. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. Stopping udev Kernel Device Manager... [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped target Swap. [ 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 Kernel Socket. [ OK ] Closed udev Control Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 13.482556] printk: systemd: 26 output lines suppressed due to ratelimiting [ 13.898198] SELinux: Disabled at runtime. [ 13.963066] 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.976123] systemd[1]: Detected virtualization kvm. [ 13.978057] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 14.684485] systemd[1]: initrd-switch-root.service: Succeeded. [ 14.687569] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 14.692281] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 14.696382] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 14.701743] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 14.716507] systemd[1]: Starting Journal Service... Starting Journal Service... [ 14.723704] systemd[1]: Listening on udev Kernel Socket. [ OK ] Listening on udev Kernel Socket. [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Created slice User and Session Slice. [ OK ] Listening on RPCbind Server Activation Socket. Starting Create list of required st…ce nodes for the current kernel... Mounting Kernel Debug File System... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Created slice system-getty.slice. [ OK ] Reached target Slices. [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Reached target RPC Port Mapper. [ OK ] Reached target rpc_pipefs.target. Mounting Huge Pages File System... [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. Starting Remount Root and Kernel File Systems... Activating swap /dev/disk/by-label/SWAP... [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Listening on udev Control Socket. Starting udev Coldplug all Devices... Mounting POSIX Message Queue File System... [ OK ] Stopped target Switch Root. [ OK [0[ 14.921122] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS m] Stopped target Initrd File Systems. [ OK ] Stopped target Initrd Root File System. Starting Apply Kernel Variables... [ OK ] Listening on Process Core Dump Socket. [ OK ] Started Journal Service. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Mounted Kernel Debug File System. [ 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 ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Started Apply Kernel Variables. [ OK ] Reached target Swap. Starting Configure read-only root support... Starting Create Static Device Nodes in /dev... Starting Flush Journal to Persistent Storage... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started udev Coldplug all Devices. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Reached target Local File Systems (Pre). Mounting /mnt... Mounting /home/green/git/lustre-release... Starting udev Kernel Device Manager... [ OK ] Mounted /mnt. [ 15.352463] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 15.768188] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 15.805082] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 15.994854] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 16.018543] EDAC sbridge: Ver: 1.1.2 [ 18.553339] Key type dns_resolver registered [ 18.895336] NFS: Registering the id_resolver key type [ 18.897498] Key type id_resolver registered [ 18.899106] Key type id_legacy registered [ OK ] Started Configure read-only root support. Starting Load/Save Random Seed... [ OK ] Reached target Local File Systems. Starting Mark the need to relabel after reboot... Starting Rebuild Dynamic Linker Cache... Starting Create Volatile Files and Directories... [ OK ] Started Load/Save Random Seed. [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Create Volatile Files and Directories. Starting RPC Bind... Starting Update UTMP about System Boot/Shutdown... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting Restore /run/initramfs on shutdown... Starting Login Service... [ OK ] Reached target sshd-keygen.target. [ OK ] Started D-Bus System Message Bus. Starting Network Manager... [ OK ] Started irqbalance daemon. [ OK ] Started dnf makecache --timer. [ OK ] Reached target Timers. [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Login Service. [ OK ] Started Network Manager. Starting Network Manager Wait Online... [ OK ] Reached target Network. Starting Dynamic System Tuning Daemon... Starting OpenSSH server daemon... Starting GSSAPI Proxy Daemon... Starting Hostname Service... [ OK ] Started OpenSSH server daemon. [ 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 Permit User Sessions. [ OK ] Started Serial Getty on ttyS1. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Command Scheduler. [ 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. [ OK ] Started System Logging Service. Starting Authorization Manager... [ OK ] Started Dynamic System Tuning Daemon. [ OK ] Reached target Multi-User System. [ OK ] Reached target Graphical Interface. Starting Update UTMP about System Runlevel Changes... [ OK ] Started Update UTMP about System Runlevel Changes. [ OK ] Started Authorization Manager. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg244-server login: [ 38.976262] spl: loading out-of-tree module taints kernel. [ 43.040032] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 50.612320] Key type ._llcrypt registered [ 50.613906] Key type .llcrypt registered [ 50.689457] Lustre: DEBUG MARKER: oleg244-server.virtnet: executing set_hostid [ 63.751970] Lustre: DEBUG MARKER: oleg244-server.virtnet: executing load_modules_local [ 64.998591] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 65.011816] alg: No test for adler32 (adler32-zlib) [ 66.227655] Lustre: Lustre: Build Version: 2.16.56_57_g82204de [ 66.898954] LNet: Added LNI 192.168.202.144@tcp [8/256/0/180] [ 66.902153] LNet: Accept secure, port 988 [ 68.575193] Key type lgssc registered [ 69.843693] Lustre: Echo OBD driver; http://www.lustre.org/ [ 77.306260] vdc: vdc1 vdc9 [ 84.518754] vde: vde1 vde9 [ 91.915572] vdf: vdf1 vdf9 [ 103.295461] Lustre: DEBUG MARKER: oleg244-server.virtnet: executing load_modules_local [ 107.761476] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 108.917537] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 109.068215] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 109.135530] Lustre: lustre-MDT0000: new disk, initializing [ 109.347509] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 109.388153] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 111.454494] Lustre: DEBUG MARKER: oleg244-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 114.617746] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 117.587761] Lustre: lustre-OST0000: new disk, initializing [ 117.590514] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 117.593205] Lustre: Skipped 1 previous similar message [ 117.638307] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 120.532862] Lustre: DEBUG MARKER: oleg244-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 126.040670] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:0:ost [ 126.044181] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:0:ost] [ 126.124438] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x240000400 [ 126.342264] Lustre: lustre-OST0001: new disk, initializing [ 126.344643] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 126.392198] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 129.378195] Lustre: DEBUG MARKER: oleg244-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 135.228850] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:1:ost [ 135.232927] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:1:ost] [ 135.274522] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x280000400 [ 136.689139] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 141.113172] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 148.811924] Lustre: DEBUG MARKER: oleg244-server.virtnet: executing check_logdir /tmp/testlogs/ [ 150.796476] Lustre: DEBUG MARKER: oleg244-server.virtnet: executing yml_node [ 153.333549] Lustre: DEBUG MARKER: Client: 2.16.56.57 [ 154.651435] Lustre: DEBUG MARKER: MDS: 2.16.56.57 [ 155.864043] Lustre: DEBUG MARKER: OSS: 2.16.56.57 [ 156.651520] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity ============----- Fri Jul 25 02:56:35 EDT 2025 [ 165.362969] Lustre: DEBUG MARKER: - need mds1 <= 2.14.55-100-g8a84c7f9c7 for LU-14927, skip 0f [ 166.169930] Lustre: DEBUG MARKER: - need mds1 < v2_14_55-100-g8a84c7f9c7 for LU-14927, skip 0f [ 166.965694] Lustre: DEBUG MARKER: excepting tests: 42a 42c 42b 118c 118d 407 119i 817 411a 130b 130c 130d 130e 130f 130g 312 [ 167.698239] Lustre: DEBUG MARKER: skipping tests SLOW=no: 27m 60i 64b 68 71 135 136 230d 300o 842 51b [ 168.447651] Lustre: DEBUG MARKER: === sanity: start setup 02:56:46 (1753426606) === [ 170.082759] Lustre: DEBUG MARKER: oleg244-client.virtnet: executing check_config_client /mnt/lustre [ 178.917924] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 180.718862] Lustre: 11088:0:(mgs_llog.c:1345:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 182.497622] Lustre: DEBUG MARKER: oleg244-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 184.255474] Lustre: DEBUG MARKER: === sanity: finish setup 02:57:02 (1753426622) === [ 187.509497] Lustre: DEBUG MARKER: == sanity test 60a: llog_test run from kernel module and test llog_reader ========================================================== 02:57:05 (1753426625) [ 189.055947] Lustre: DEBUG MARKER: SKIP: sanity test_60a missing subtest run-llog.sh [ 189.979523] Lustre: DEBUG MARKER: == sanity test 60b: limit repeated messages from CERROR/CWARN ========================================================== 02:57:08 (1753426628) [ 193.197353] Lustre: DEBUG MARKER: == sanity test 60c: unlink file when mds full ============ 02:57:11 (1753426631) [ 309.151166] Lustre: DEBUG MARKER: == sanity test 60d: test printk console message masking == 02:59:07 (1753426747) [ 312.041706] Lustre: DEBUG MARKER: == sanity test 60e: no space while new llog is being created ========================================================== 02:59:10 (1753426750) [ 312.651710] Lustre: *** cfs_fail_loc=15b, val=0*** [ 312.654245] Lustre: *** cfs_fail_loc=15b, val=0*** [ 312.656119] LustreError: 7403:0:(llog_cat.c:583:llog_cat_add_rec()) lustre-OST0001-osc-MDT0000: initialization error: rc = -28 [ 315.743404] Lustre: DEBUG MARKER: == sanity test 60f: change debug_path works ============== 02:59:14 (1753426754) [ 319.089104] Lustre: DEBUG MARKER: == sanity test 60g: transaction abort won't cause MDT hung ========================================================== 02:59:17 (1753426757) [ 319.547268] Lustre: *** cfs_fail_loc=19a, val=0*** [ 320.455542] Lustre: *** cfs_fail_loc=19a, val=0*** [ 320.457181] Lustre: Skipped 1 previous similar message [ 321.726452] Lustre: *** cfs_fail_loc=19a, val=0*** [ 321.728072] Lustre: Skipped 2 previous similar messages [ 324.065129] Lustre: *** cfs_fail_loc=19a, val=0*** [ 324.066850] Lustre: Skipped 4 previous similar messages [ 328.127646] Lustre: *** cfs_fail_loc=19a, val=0*** [ 328.128828] Lustre: Skipped 9 previous similar messages [ 336.470171] Lustre: *** cfs_fail_loc=19a, val=0*** [ 336.471714] Lustre: Skipped 22 previous similar messages [ 352.695882] Lustre: *** cfs_fail_loc=19a, val=0*** [ 352.698103] Lustre: Skipped 41 previous similar messages [ 362.156832] Lustre: DEBUG MARKER: == sanity test 60h: striped directory with missing stripes can be accessed ========================================================== 03:00:00 (1753426800) [ 362.634096] Lustre: DEBUG MARKER: SKIP: sanity test_60h Need at least 2 MDTs [ 363.192838] Lustre: DEBUG MARKER: SKIP: sanity test_60i skipping SLOW test 60i [ 363.767742] Lustre: DEBUG MARKER: == sanity test 60j: llog_reader reports corruptions ====== 03:00:02 (1753426802) [ 364.339484] Lustre: DEBUG MARKER: SKIP: sanity test_60j ldiskfs only test [ 364.964107] Lustre: DEBUG MARKER: == sanity test 61a: mmap() writes don't make sync hang ========================================================================== 03:00:03 (1753426803) [ 367.393390] Lustre: DEBUG MARKER: == sanity test 61b: mmap() of unstriped file is successful ========================================================== 03:00:05 (1753426805) [ 369.784323] Lustre: DEBUG MARKER: == sanity test 63a: Verify oig_wait interruption does not crash ================================================================= 03:00:08 (1753426808) [ 433.329491] Lustre: DEBUG MARKER: == sanity test 63b: async write errors should be returned to fsync ============================================================= 03:01:11 (1753426871) [ 438.847399] Lustre: DEBUG MARKER: == sanity test 64a: verify filter grant calculations (in kernel) =============================================================== 03:01:17 (1753426877) [ 441.648535] Lustre: DEBUG MARKER: SKIP: sanity test_64b skipping SLOW test 64b [ 442.242851] Lustre: DEBUG MARKER: == sanity test 64c: verify grant shrink ================== 03:01:20 (1753426880) [ 444.831611] Lustre: DEBUG MARKER: == sanity test 64d: check grant limit exceed ============= 03:01:23 (1753426883) [ 470.047319] Lustre: DEBUG MARKER: == sanity test 64e: check grant consumption (no grant allocation) ========================================================== 03:01:48 (1753426908) [ 471.121227] Lustre: *** cfs_fail_loc=725, val=0*** [ 472.429335] Lustre: *** cfs_fail_loc=725, val=0*** [ 475.013343] Lustre: DEBUG MARKER: == sanity test 64f: check grant consumption (with grant allocation) ========================================================== 03:01:53 (1753426913) [ 478.450378] Lustre: DEBUG MARKER: == sanity test 64g: grant shrink on MDT ================== 03:01:57 (1753426917) [ 492.266516] Lustre: DEBUG MARKER: == sanity test 64h: grant shrink on read ================= 03:02:10 (1753426930) [ 503.590517] Lustre: DEBUG MARKER: == sanity test 64i: shrink on reconnect ================== 03:02:22 (1753426942) [ 507.596981] Lustre: *** cfs_fail_loc=513, val=17*** [ 507.598721] LustreError: 6514:0:(service.c:2284:ptlrpc_server_handle_req_in()) drop incoming rpc opc 17, x1838600944003968 [ 508.232735] Lustre: Failing over lustre-OST0000 [ 508.301064] LustreError: 22432:0:(obd_class.h:479:obd_check_dev()) Device 12 not setup [ 508.307770] Lustre: server umount lustre-OST0000 complete [ 508.896028] Lustre: lustre-OST0000-osc-MDT0000: Connection to lustre-OST0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 514.015955] LustreError: 12207:0:(ldlm_lib.c:1113:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 514.020819] LustreError: 12207:0:(ldlm_lib.c:1113:target_handle_connect()) Skipped 3 previous similar messages [ 517.454344] LustreError: 12207:0:(ldlm_lib.c:1113:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.202.44@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 519.135730] LustreError: 7380:0:(ldlm_lib.c:1113:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 520.914625] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [ 522.329172] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 522.889128] Lustre: DEBUG MARKER: oleg244-server.virtnet: executing set_default_debug all all [ 523.328810] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 192.168.202.144@tcp (at 0@lo) [ 523.329676] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 526.165143] Lustre: DEBUG MARKER: oleg244-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 526.721891] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 531.074377] Lustre: DEBUG MARKER: == sanity test 64j: check grants on re-done rpc ========== 03:02:49 (1753426969) [ 531.494924] Lustre: *** cfs_fail_loc=256, val=0*** [ 535.249958] Lustre: DEBUG MARKER: == sanity test 65a: directory with no stripe info ======== 03:02:53 (1753426973) [ 537.532893] Lustre: DEBUG MARKER: == sanity test 65b: directory setstripe -S stripe_size*2 -i 0 -c 1 ========================================================== 03:02:56 (1753426976) [ 539.990096] Lustre: DEBUG MARKER: == sanity test 65c: directory setstripe -S stripe_size*4 -i 1 -c 1 ========================================================== 03:02:58 (1753426978) [ 542.581417] Lustre: DEBUG MARKER: == sanity test 65d: directory setstripe -S stripe_size -c stripe_count ========================================================== 03:03:01 (1753426981) [ 545.063571] Lustre: DEBUG MARKER: == sanity test 65e: directory setstripe defaults ========= 03:03:03 (1753426983) [ 547.571080] Lustre: DEBUG MARKER: == sanity test 65f: dir setstripe permission (should return error) ============================================================= 03:03:06 (1753426986) [ 550.018902] Lustre: DEBUG MARKER: == sanity test 65g: directory setstripe -d =============== 03:03:08 (1753426988) [ 552.553871] Lustre: DEBUG MARKER: == sanity test 65h: directory stripe info inherit ============================================================================== 03:03:11 (1753426991) [ 555.014418] Lustre: DEBUG MARKER: == sanity test 65i: various tests to set root directory striping ========================================================== 03:03:13 (1753426993) [ 557.826466] Lustre: DEBUG MARKER: == sanity test 65j: set default striping on root directory (bug 6367)=========================================================== 03:03:16 (1753426996) [ 561.240758] Lustre: DEBUG MARKER: == sanity test 65k: validate manual striping works properly with deactivated OSCs ========================================================== 03:03:19 (1753426999) [ 562.005839] Lustre: lustre-OST0000-osc-MDT0000: Connection to lustre-OST0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 562.009995] Lustre: lustre-OST0000: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnecting [ 562.013121] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 192.168.202.144@tcp (at 0@lo) [ 567.153301] Lustre: setting import lustre-OST0000_UUID INACTIVE by administrator request [ 571.451724] Lustre: lustre-OST0000-osc-MDT0000: Connection to lustre-OST0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 571.456178] Lustre: Skipped 1 previous similar message [ 571.458850] Lustre: lustre-OST0000: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnecting [ 571.461799] Lustre: Skipped 1 previous similar message [ 571.464483] LustreError: lustre-OST0000-osc-MDT0000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 571.469823] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 192.168.202.144@tcp (at 0@lo) [ 571.473787] Lustre: Skipped 1 previous similar message [ 573.599429] Lustre: DEBUG MARKER: oleg244-server.virtnet: executing wait_import_state FULL os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid 50 [ 573.684618] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid in FULL state after 0 sec [ 578.452112] Lustre: setting import lustre-OST0001_UUID INACTIVE by administrator request [ 583.512794] Lustre: lustre-OST0001-osc-MDT0000: Connection to lustre-OST0001 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 583.517664] Lustre: lustre-OST0001: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnecting [ 583.520556] LustreError: lustre-OST0001-osc-MDT0000: This client was evicted by lustre-OST0001; in progress operations using this service will fail. [ 583.524629] Lustre: lustre-OST0001-osc-MDT0000: Connection restored to 192.168.202.144@tcp (at 0@lo) [ 585.093644] Lustre: DEBUG MARKER: oleg244-server.virtnet: executing wait_import_state FULL os[cp].lustre-OST0001-osc-MDT0000.ost_server_uuid 50 [ 585.170980] Lustre: DEBUG MARKER: os[cp].lustre-OST0001-osc-MDT0000.ost_server_uuid in FULL state after 0 sec [ 587.462721] Lustre: DEBUG MARKER: == sanity test 65l: lfs find on -1 stripe dir ================================================================================== 03:03:46 (1753427026) [ 589.947527] Lustre: DEBUG MARKER: == sanity test 65m: normal user can't set filesystem default stripe ========================================================== 03:03:48 (1753427028) [ 592.248333] Lustre: DEBUG MARKER: == sanity test 65n: don't inherit default layout from root for new subdirectories ========================================================== 03:03:50 (1753427030) [ 597.285778] Lustre: DEBUG MARKER: SKIP: sanity test_65n needs >= 2 MDTs [ 604.874272] Lustre: DEBUG MARKER: == sanity test 65o: pool inheritance for mdt component === 03:04:03 (1753427043) [ 620.063529] Lustre: DEBUG MARKER: == sanity test 65p: setstripe with yaml file and huge number ========================================================== 03:04:18 (1753427058) [ 622.486127] Lustre: DEBUG MARKER: == sanity test 65q: setstripe with >=8E offset should fail ========================================================== 03:04:21 (1753427061) [ 624.797238] Lustre: DEBUG MARKER: == sanity test 65r: prevent all-zero offsets ============= 03:04:23 (1753427063) [ 627.302651] Lustre: DEBUG MARKER: == sanity test 66: update inode blocks count on client ========================================================================= 03:04:25 (1753427065) [ 631.505360] Lustre: DEBUG MARKER: == sanity test 69: verify oa2dentry return -ENOENT doesn't LBUG ================================================================ 03:04:30 (1753427070) [ 632.240505] Lustre: *** cfs_fail_loc=217, val=0*** [ 632.242767] Lustre: Skipped 3 previous similar messages [ 633.274971] Lustre: *** cfs_fail_loc=217, val=0*** [ 633.276827] Lustre: Skipped 3 previous similar messages [ 635.793810] Lustre: DEBUG MARKER: == sanity test 70a: verify health_check, health_write don't explode (on OST) ========================================================== 03:04:34 (1753427074) [ 640.284703] Lustre: DEBUG MARKER: SKIP: sanity test_71 skipping SLOW test 71 [ 640.907368] Lustre: DEBUG MARKER: == sanity test 72a: Test that remove suid works properly (bug5695) ============================================================== 03:04:39 (1753427079) [ 643.479234] Lustre: DEBUG MARKER: == sanity test 72b: Test that we keep mode setting if without file data changed (bug 24226) ========================================================== 03:04:42 (1753427082) [ 646.151598] Lustre: DEBUG MARKER: == sanity test 73: multiple MDC requests (should not deadlock) ========================================================== 03:04:44 (1753427084) [ 674.988301] Lustre: DEBUG MARKER: == sanity test 74a: ldlm_enqueue freed-export error path, ls (shouldn't LBUG) ========================================================== 03:05:13 (1753427113) [ 677.302608] Lustre: DEBUG MARKER: == sanity test 74b: ldlm_enqueue freed-export error path, touch (shouldn't LBUG) ========================================================== 03:05:15 (1753427115) [ 679.608653] Lustre: DEBUG MARKER: == sanity test 74c: ldlm_lock_create error path, (shouldn't LBUG) ========================================================== 03:05:18 (1753427118) [ 681.814970] Lustre: DEBUG MARKER: == sanity test 76a: confirm clients recycle inodes properly ============================================================== 03:05:20 (1753427120) [ 709.356819] Lustre: DEBUG MARKER: == sanity test 76b: confirm clients recycle directory inodes properly ============================================================== 03:05:47 (1753427147) [ 725.406271] Lustre: DEBUG MARKER: == sanity test 77a: normal checksum read/write operation ========================================================== 03:06:03 (1753427163) [ 728.344240] Lustre: DEBUG MARKER: == sanity test 77b: checksum error on client write, read ========================================================== 03:06:06 (1753427166) [ 728.478112] LustreError: lustre-OST0000: BAD WRITE CHECKSUM: from 12345-192.168.202.44@tcp inode [0x200000406:0xc34:0x0] object 0x240000400:3786 extent [0-1048575]: client csum 5667fa4d, server csum 5667fa4c [ 730.297674] Lustre: DEBUG MARKER: set checksum type to crc32, rc = 0 [ 731.472196] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.202.44@tcp inode [0x200000406:0xc34:0x0] object 0x240000400:3786 extent [0-1048575], client returned csum 284e125 (type 1), server csum faf67146 (type 1) [ 732.475233] Lustre: DEBUG MARKER: set checksum type to adler, rc = 0 [ 733.648078] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.202.44@tcp inode [0x200000406:0xc34:0x0] object 0x240000400:3786 extent [0-1048575], client returned csum 1d6062eb (type 2), server csum 90166365 (type 2) [ 734.685776] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 735.887073] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.202.44@tcp inode [0x200000406:0xc34:0x0] object 0x240000400:3786 extent [0-1048575], client returned csum fb817edc (type 4), server csum 6ed1d4d (type 4) [ 736.951396] Lustre: DEBUG MARKER: set checksum type to t10ip512, rc = 0 [ 738.128135] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.202.44@tcp inode [0x200000406:0xc34:0x0] object 0x240000400:3786 extent [0-1048575], client returned csum beedf82b (type 10), server csum 1eb8f7b1 (type 10) [ 739.138383] Lustre: DEBUG MARKER: set checksum type to t10ip4K, rc = 0 [ 741.279769] Lustre: DEBUG MARKER: set checksum type to t10crc512, rc = 0 [ 742.480448] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.202.44@tcp inode [0x200000406:0xc34:0x0] object 0x240000400:3786 extent [0-1048575], client returned csum dd7df38a (type 40), server csum ee33f3db (type 40) [ 742.487686] LustreError: Skipped 1 previous similar message [ 743.479413] Lustre: DEBUG MARKER: set checksum type to t10crc4K, rc = 0 [ 745.512922] Lustre: DEBUG MARKER: set checksum type to t10ip4K, rc = 0 [ 747.785584] Lustre: DEBUG MARKER: == sanity test 77c: checksum error on client read with debug ========================================================== 03:06:26 (1753427186) [ 750.672014] Lustre: 6522:0:(tgt_handler.c:1935:dump_all_bulk_pages()) dumping checksum data to /tmp/lustre-log-checksum_dump-ost-[0x200000406:0xc35:0x0]:[0-1048575]-4a42fac6-5667fa4c [ 750.680549] LustreError: dumping log to /tmp/lustre-log.1753427190.6522 [ 750.743228] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.202.44@tcp inode [0x200000406:0xc35:0x0] object 0x240000400:3787 extent [0-1048575], client returned csum 4a42fac6 (type 20), server csum 5667fa4c (type 20) [ 750.751176] LustreError: Skipped 1 previous similar message [ 761.376620] Lustre: DEBUG MARKER: == sanity test 77d: checksum error on OST direct write, read ========================================================== 03:06:39 (1753427199) [ 761.505434] LustreError: 30695:0:(tgt_grant.c:745:tgt_grant_check()) lustre-OST0001: cli e01c9fac-5577-4a0d-9dfe-22c9da0dc66e claims 1703936 GRANT, real grant 0 [ 761.514553] LustreError: lustre-OST0001: BAD WRITE CHECKSUM: from 12345-192.168.202.44@tcp inode [0x200000406:0xc37:0x0] object 0x280000400:3777 extent [0-1048575]: client csum 30ec5402, server csum 30ec5401 [ 766.223892] Lustre: DEBUG MARKER: == sanity test 77f: repeat checksum error on write (expect error) ========================================================== 03:06:44 (1753427204) [ 766.862161] Lustre: DEBUG MARKER: set checksum type to crc32, rc = 0 [ 766.991832] LustreError: lustre-OST0000: BAD WRITE CHECKSUM: from 12345-192.168.202.44@tcp inode [0x200000406:0xc38:0x0] object 0x240000400:3788 extent [0-1048575]: client csum b2f1b12, server csum b2f1b11 [ 767.003871] LustreError: Skipped 4 previous similar messages [ 770.389474] LustreError: lustre-OST0000: BAD WRITE CHECKSUM: from 12345-192.168.202.44@tcp inode [0x200000406:0xc38:0x0] object 0x240000400:3788 extent [6291456-7340031]: client csum b2f1b12, server csum b2f1b11 [ 770.403441] LustreError: Skipped 13 previous similar messages [ 777.621497] LustreError: lustre-OST0000: BAD WRITE CHECKSUM: from 12345-192.168.202.44@tcp inode [0x200000406:0xc38:0x0] object 0x240000400:3788 extent [2097152-3145727]: client csum b2f1b12, server csum b2f1b11 [ 777.635177] LustreError: Skipped 17 previous similar messages [ 788.821594] LustreError: lustre-OST0000: BAD WRITE CHECKSUM: from 12345-192.168.202.44@tcp inode [0x200000406:0xc38:0x0] object 0x240000400:3788 extent [6291456-7340031]: client csum b2f1b12, server csum b2f1b11 [ 788.837432] LustreError: Skipped 15 previous similar messages [ 812.376340] LustreError: lustre-OST0000: BAD WRITE CHECKSUM: from 12345-192.168.202.44@tcp inode [0x200000406:0xc38:0x0] object 0x240000400:3788 extent [1048576-2097151]: client csum b2f1b12, server csum b2f1b11 [ 812.390399] LustreError: Skipped 22 previous similar messages [ 823.365750] Lustre: DEBUG MARKER: set checksum type to adler, rc = 0 [ 845.142816] LustreError: lustre-OST0000: BAD WRITE CHECKSUM: from 12345-192.168.202.44@tcp inode [0x200000406:0xc38:0x0] object 0x240000400:3788 extent [5242880-6291455]: client csum 19eeae62, server csum 19eeae61 [ 845.157506] LustreError: Skipped 63 previous similar messages [ 880.642068] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 909.588633] LustreError: lustre-OST0000: BAD WRITE CHECKSUM: from 12345-192.168.202.44@tcp inode [0x200000406:0xc38:0x0] object 0x240000400:3788 extent [5242880-6291455]: client csum b5ea7f3c, server csum b5ea7f3b [ 909.602055] LustreError: Skipped 92 previous similar messages [ 936.940362] Lustre: DEBUG MARKER: set checksum type to t10ip512, rc = 0 [ 994.324359] Lustre: DEBUG MARKER: set checksum type to t10ip4K, rc = 0 [ 1040.726719] LustreError: lustre-OST0000: BAD WRITE CHECKSUM: from 12345-192.168.202.44@tcp inode [0x200000406:0xc38:0x0] object 0x240000400:3788 extent [5242880-6291455]: client csum 30ec5402, server csum 30ec5401 [ 1040.741312] LustreError: Skipped 189 previous similar messages [ 1051.677751] Lustre: DEBUG MARKER: set checksum type to t10crc512, rc = 0 [ 1108.114110] Lustre: DEBUG MARKER: set checksum type to t10crc4K, rc = 0 [ 1165.405479] Lustre: DEBUG MARKER: set checksum type to t10ip4K, rc = 0 [ 1167.497785] Lustre: DEBUG MARKER: == sanity test 77g: checksum error on OST write, read ==== 03:13:26 (1753427606) [ 1168.000410] Lustre: *** cfs_fail_loc=21a, val=0*** [ 1170.260397] Lustre: *** cfs_fail_loc=21b, val=0*** [ 1174.282979] Lustre: DEBUG MARKER: == sanity test 77k: enable/disable checksum correctly ==== 03:13:32 (1753427612) [ 1174.625482] Lustre: Setting parameter lustre.osc.lustre*.checksums=0 in log params [ 1175.465488] Lustre: Modifying parameter lustre.osc.lustre*.checksums=1 in log params [ 1178.416946] Lustre: Disabling parameter lustre.osc.lustre*.checksums= in log params [ 1182.053399] Lustre: Setting parameter lustre.osc.lustre*.checksums=0 in log params [ 1184.675717] Lustre: DEBUG MARKER: == sanity test 77l: preferred checksum type is remembered after reconnected ========================================================== 03:13:43 (1753427623) [ 1185.303125] Lustre: DEBUG MARKER: set checksum type to invalid, rc = 22 [ 1185.901377] Lustre: DEBUG MARKER: set checksum type to crc32, rc = 0 [ 1187.247942] Lustre: DEBUG MARKER: oleg244-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff9c1ee01ae000.ost_server_uuid 50 [ 1190.861732] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9c1ee01ae000.ost_server_uuid in IDLE state after 3 sec [ 1192.166805] Lustre: DEBUG MARKER: oleg244-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9c1ee01ae000.ost_server_uuid 50 [ 1192.723411] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9c1ee01ae000.ost_server_uuid in FULL state after 0 sec [ 1193.303792] Lustre: DEBUG MARKER: set checksum type to adler, rc = 0 [ 1194.623716] Lustre: DEBUG MARKER: oleg244-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff9c1ee01ae000.ost_server_uuid 50 [ 1206.559175] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9c1ee01ae000.ost_server_uuid in IDLE state after 11 sec [ 1207.761769] Lustre: DEBUG MARKER: oleg244-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9c1ee01ae000.ost_server_uuid 50 [ 1208.240976] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9c1ee01ae000.ost_server_uuid in FULL state after 0 sec [ 1208.785897] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 1210.010619] Lustre: DEBUG MARKER: oleg244-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff9c1ee01ae000.ost_server_uuid 50 [ 1221.974474] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9c1ee01ae000.ost_server_uuid in IDLE state after 11 sec [ 1223.240355] Lustre: DEBUG MARKER: oleg244-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9c1ee01ae000.ost_server_uuid 50 [ 1223.732391] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9c1ee01ae000.ost_server_uuid in FULL state after 0 sec [ 1224.317802] Lustre: DEBUG MARKER: set checksum type to t10ip512, rc = 0 [ 1225.612933] Lustre: DEBUG MARKER: oleg244-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff9c1ee01ae000.ost_server_uuid 50 [ 1237.595228] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9c1ee01ae000.ost_server_uuid in IDLE state after 11 sec [ 1238.824844] Lustre: DEBUG MARKER: oleg244-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9c1ee01ae000.ost_server_uuid 50 [ 1239.341819] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9c1ee01ae000.ost_server_uuid in FULL state after 0 sec [ 1239.925122] Lustre: DEBUG MARKER: set checksum type to t10ip4K, rc = 0 [ 1241.279948] Lustre: DEBUG MARKER: oleg244-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff9c1ee01ae000.ost_server_uuid 50 [ 1253.242736] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9c1ee01ae000.ost_server_uuid in IDLE state after 11 sec [ 1254.540428] Lustre: DEBUG MARKER: oleg244-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9c1ee01ae000.ost_server_uuid 50 [ 1255.071917] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9c1ee01ae000.ost_server_uuid in FULL state after 0 sec [ 1255.694286] Lustre: DEBUG MARKER: set checksum type to t10crc512, rc = 0 [ 1257.134680] Lustre: DEBUG MARKER: oleg244-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff9c1ee01ae000.ost_server_uuid 50 [ 1268.100292] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9c1ee01ae000.ost_server_uuid in IDLE state after 10 sec [ 1269.323723] Lustre: DEBUG MARKER: oleg244-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9c1ee01ae000.ost_server_uuid 50 [ 1269.874900] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9c1ee01ae000.ost_server_uuid in FULL state after 0 sec [ 1270.450628] Lustre: DEBUG MARKER: set checksum type to t10crc4K, rc = 0 [ 1271.676206] Lustre: DEBUG MARKER: oleg244-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff9c1ee01ae000.ost_server_uuid 50 [ 1283.668310] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9c1ee01ae000.ost_server_uuid in IDLE state after 11 sec [ 1285.051796] Lustre: DEBUG MARKER: oleg244-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9c1ee01ae000.ost_server_uuid 50 [ 1285.620488] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9c1ee01ae000.ost_server_uuid in FULL state after 0 sec [ 1288.171402] Lustre: DEBUG MARKER: set checksum type to t10ip4K, rc = 0 [ 1288.795940] Lustre: DEBUG MARKER: == sanity test 77m: Verify checksum_speed is correctly read ========================================================== 03:15:27 (1753427727) [ 1291.008621] Lustre: DEBUG MARKER: == sanity test 77n: Verify read from a hole inside contiguous blocks with T10PI ========================================================== 03:15:29 (1753427729) [ 1291.646842] Lustre: DEBUG MARKER: SKIP: sanity test_77n f77n.sanity blocks not contiguous around hole [ 1292.275184] Lustre: DEBUG MARKER: == sanity test 77o: Verify checksum_type for server (mdt and ofd(obdfilter)) ========================================================== 03:15:30 (1753427730) [ 1296.609978] Lustre: DEBUG MARKER: == sanity test 78: handle large O_DIRECT writes correctly ====================================================================== 03:15:35 (1753427735) [ 1300.487281] Lustre: DEBUG MARKER: == sanity test 79: df report consistency check =========== 03:15:39 (1753427739) [ 1319.464663] Lustre: DEBUG MARKER: == sanity test 80: Page eviction is equally fast at high offsets too ========================================================== 03:15:58 (1753427758) [ 1322.964181] Lustre: DEBUG MARKER: == sanity test 81a: OST should retry write when get -ENOSPC ========================================================================= 03:16:01 (1753427761) [ 1323.362748] Lustre: *** cfs_fail_loc=228, val=0*** [ 1325.530074] Lustre: DEBUG MARKER: == sanity test 81b: OST should return -ENOSPC when retry still fails ================================================================= 03:16:04 (1753427764) [ 1326.005923] Lustre: *** cfs_fail_loc=228, val=0*** [ 1328.289268] Lustre: DEBUG MARKER: == sanity test 99: cvs strange file/directory operations ========================================================== 03:16:06 (1753427766) [ 1336.327145] Lustre: DEBUG MARKER: == sanity test 100: check local port using privileged port ========================================================== 03:16:14 (1753427774) [ 1338.842273] Lustre: DEBUG MARKER: == sanity test 101a: check read-ahead for random reads === 03:16:17 (1753427777) [ 1398.140700] Lustre: DEBUG MARKER: == sanity test 101b: check stride-io mode read-ahead =========================================================================== 03:17:16 (1753427836) [ 1409.255484] Lustre: DEBUG MARKER: == sanity test 101c: check stripe_size aligned read-ahead ========================================================== 03:17:27 (1753427847) [ 1437.506797] Lustre: DEBUG MARKER: == sanity test 101d: file read with and without read-ahead enabled ========================================================== 03:17:56 (1753427876) [ 1550.217514] Lustre: DEBUG MARKER: == sanity test 101e: check read-ahead for small read(1k) for small files(500k) ========================================================== 03:19:48 (1753427988) [ 1578.694915] Lustre: DEBUG MARKER: == sanity test 101f: check mmap read performance ========= 03:20:17 (1753428017) [ 1581.871964] Lustre: DEBUG MARKER: == sanity test 101g: Big bulk(4/16 MiB) readahead ======== 03:20:20 (1753428020) [ 1651.847540] Lustre: DEBUG MARKER: == sanity test 101h: Readahead should cover current read window ========================================================== 03:21:30 (1753428090) [ 1659.477247] Lustre: DEBUG MARKER: == sanity test 101i: allow current readahead to exceed reservation ========================================================== 03:21:38 (1753428098) [ 1663.026665] Lustre: DEBUG MARKER: == sanity test 101j: A complete read block should be submitted when no RA ========================================================== 03:21:41 (1753428101) [ 1680.162688] Lustre: DEBUG MARKER: == sanity test 101m: read ahead for small file and last stripe of the file ========================================================== 03:21:58 (1753428118) [ 1680.651956] Lustre: DEBUG MARKER: SKIP: sanity test_101m need >= 2.13.57 and ldiskfs for fallocate [ 1681.194977] Lustre: DEBUG MARKER: == sanity test 102a: user xattr test ============================================================================================ 03:21:59 (1753428119) [ 1683.590244] Lustre: DEBUG MARKER: == sanity test 102b: getfattr/setfattr for trusted.lov EAs ========================================================== 03:22:02 (1753428122) [ 1687.234544] Lustre: DEBUG MARKER: == sanity test 102c: non-root getfattr/setfattr for lustre.lov EAs ===================================================================== 03:22:05 (1753428125) [ 1689.617651] Lustre: DEBUG MARKER: == sanity test 102d: tar restore stripe info from tarfile,not keep osts ========================================================== 03:22:08 (1753428128) [ 1694.876482] Lustre: DEBUG MARKER: == sanity test 102f: tar copy files, not keep osts ======= 03:22:13 (1753428133) [ 1700.088230] Lustre: DEBUG MARKER: == sanity test 102h: grow xattr from inside inode to external block ========================================================== 03:22:18 (1753428138) [ 1700.744871] Lustre: DEBUG MARKER: save trusted.big on /mnt/lustre/f102h.sanity [ 1701.252753] Lustre: DEBUG MARKER: save trusted.sml on /mnt/lustre/f102h.sanity [ 1701.750614] Lustre: DEBUG MARKER: grow trusted.sml on /mnt/lustre/f102h.sanity [ 1702.231862] Lustre: DEBUG MARKER: trusted.big still valid after growing trusted.sml [ 1704.248399] Lustre: DEBUG MARKER: == sanity test 102ha: grow xattr from inside inode to external inode ========================================================== 03:22:22 (1753428142) [ 1704.923668] Lustre: DEBUG MARKER: save trusted.big on /mnt/lustre/f102ha.sanity [ 1705.471108] Lustre: DEBUG MARKER: save trusted.sml on /mnt/lustre/f102ha.sanity [ 1706.030443] Lustre: DEBUG MARKER: grow trusted.sml on /mnt/lustre/f102ha.sanity [ 1706.601394] Lustre: DEBUG MARKER: trusted.big still valid after growing trusted.sml [ 1707.354663] Lustre: DEBUG MARKER: save trusted.big on /mnt/lustre/f102ha.sanity [ 1709.389347] Lustre: DEBUG MARKER: == sanity test 102i: lgetxattr test on symbolic link ====================================================================== 03:22:28 (1753428148) [ 1711.688192] Lustre: DEBUG MARKER: == sanity test 102j: non-root tar restore stripe info from tarfile, not keep osts ============================================================= 03:22:30 (1753428150) [ 1717.163773] Lustre: DEBUG MARKER: == sanity test 102k: setfattr without parameter of value shouldn't cause a crash ========================================================== 03:22:35 (1753428155) [ 1719.590957] Lustre: DEBUG MARKER: == sanity test 102l: listxattr size test ============================================================================================ 03:22:38 (1753428158) [ 1721.774826] Lustre: DEBUG MARKER: == sanity test 102m: Ensure listxattr fails on small bufffer ================================================================== 03:22:40 (1753428160) [ 1723.848220] Lustre: DEBUG MARKER: == sanity test 102n: silently ignore setxattr on internal trusted xattrs ========================================================== 03:22:42 (1753428162) [ 1726.517848] Lustre: DEBUG MARKER: == sanity test 102p: check setxattr(2) correctly fails without permission ========================================================== 03:22:45 (1753428165) [ 1728.848658] Lustre: DEBUG MARKER: == sanity test 102q: flistxattr should not return trusted.link EAs for orphans ========================================================== 03:22:47 (1753428167) [ 1730.977701] Lustre: DEBUG MARKER: == sanity test 102r: set EAs with empty values =========== 03:22:49 (1753428169) [ 1733.412903] Lustre: DEBUG MARKER: == sanity test 102s: getting nonexistent xattrs should fail ========================================================== 03:22:51 (1753428171) [ 1735.806486] Lustre: DEBUG MARKER: == sanity test 102t: zero length xattr values handled correctly ========================================================== 03:22:54 (1753428174) [ 1738.263869] Lustre: DEBUG MARKER: == sanity test 103a: acl test ============================ 03:22:56 (1753428176) [ 1813.063572] Lustre: DEBUG MARKER: == sanity test 103b: umask lfs setstripe ================= 03:24:11 (1753428251) [ 1869.231773] Lustre: DEBUG MARKER: == sanity test 103c: 'cp -rp' won't set empty acl ======== 03:25:07 (1753428307) [ 1871.670331] Lustre: DEBUG MARKER: == sanity test 103e: inheritance of big amount of default ACLs ========================================================== 03:25:10 (1753428310) [ 2165.805257] Lustre: DEBUG MARKER: == sanity test 103f: changelog doesn't interfere with default ACLs buffers ========================================================== 03:30:04 (1753428604) [ 2167.518195] Lustre: lustre-MDD0000: changelog on [ 2169.987342] Lustre: lustre-MDD0000: changelog off [ 2170.927416] Lustre: DEBUG MARKER: == sanity test 104a: lfs df [-ih] [path] test =================================================================================== 03:30:09 (1753428609) [ 2171.139170] Lustre: lustre-OST0000: Client ed75a0e6-d738-4fe4-a3d4-85779220cc0d (at 192.168.202.44@tcp) reconnecting [ 2172.654931] Lustre: DEBUG MARKER: oleg244-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0000-osc-ffff9c1ed0361000.ost_server_uuid 50 [ 2173.200883] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9c1ed0361000.ost_server_uuid in FULL state after 0 sec [ 2175.503647] Lustre: DEBUG MARKER: == sanity test 104b: runas -u 500 -g 500 lfs check servers test ============================================================================== 03:30:14 (1753428614) [ 2177.782228] Lustre: DEBUG MARKER: == sanity test 104c: Verify df vs lfs_df stays same after recordsize change ========================================================== 03:30:16 (1753428616) [ 2186.673707] Lustre: DEBUG MARKER: == sanity test 104d: runas -u 500 -g 500 lctl dl test ==== 03:30:25 (1753428625) [ 2189.125172] Lustre: DEBUG MARKER: == sanity test 105a: flock when mounted without -o flock test ================================================================== 03:30:27 (1753428627) [ 2191.539512] Lustre: DEBUG MARKER: == sanity test 105b: fcntl when mounted without -o flock test ================================================================== 03:30:30 (1753428630) [ 2193.986098] Lustre: DEBUG MARKER: == sanity test 105c: lockf when mounted without -o flock test ========================================================== 03:30:32 (1753428632) [ 2196.390581] Lustre: DEBUG MARKER: == sanity test 105d: flock race (should not freeze) ================================================================== 03:30:34 (1753428634) [ 2209.059276] Lustre: DEBUG MARKER: == sanity test 105e: Two conflicting flocks from same process ========================================================== 03:30:47 (1753428647) [ 2211.579298] Lustre: DEBUG MARKER: == sanity test 105f: Enqueue same range flocks =========== 03:30:50 (1753428650) [ 2215.218536] Lustre: DEBUG MARKER: == sanity test 105g: ldlm_lock_debug stack test ========== 03:30:53 (1753428653) [ 2219.669353] Lustre: DEBUG MARKER: == sanity test 105h: Flock functional verify ============= 03:30:58 (1753428658) [ 2222.315772] Lustre: DEBUG MARKER: == sanity test 105i: Flock deadlock verify =============== 03:31:00 (1753428660) [ 2229.818929] Lustre: DEBUG MARKER: == sanity test 106: attempt exec of dir followed by chown of that dir ========================================================== 03:31:08 (1753428668) [ 2232.212550] Lustre: DEBUG MARKER: == sanity test 107: Coredump on SIG ====================== 03:31:10 (1753428670) [ 2236.015553] Lustre: DEBUG MARKER: == sanity test 110: filename length checking ============= 03:31:14 (1753428674) [ 2238.567751] Lustre: DEBUG MARKER: == sanity test 116a: stripe QOS: free space balance ============================================================================= 03:31:17 (1753428677) [ 2382.929867] Lustre: DEBUG MARKER: == sanity test 116b: QoS shouldn't LBUG if not enough OSTs found on the 2nd pass ========================================================== 03:33:41 (1753428821) [ 2384.037027] Lustre: *** cfs_fail_loc=147, val=0*** [ 2387.397771] Lustre: DEBUG MARKER: == sanity test 117: verify osd extend ==================== 03:33:45 (1753428825) [ 2389.795702] Lustre: DEBUG MARKER: == sanity test 118a: verify O_SYNC works ================= 03:33:48 (1753428828) [ 2392.329557] Lustre: DEBUG MARKER: == sanity test 118b: Reclaim dirty pages on fatal error ==================================================================== 03:33:50 (1753428830) [ 2393.004438] Lustre: *** cfs_fail_loc=217, val=0*** [ 2395.694694] Lustre: DEBUG MARKER: SKIP: sanity test_118c skipping ALWAYS excluded test 118c [ 2396.295542] Lustre: DEBUG MARKER: SKIP: sanity test_118d skipping ALWAYS excluded test 118d [ 2396.932648] Lustre: DEBUG MARKER: == sanity test 118f: Simulate unrecoverable OSC side error ==================================================================== 03:33:55 (1753428835) [ 2399.514701] Lustre: DEBUG MARKER: == sanity test 118g: Don't stay in wait if we got local -ENOMEM ==================================================================== 03:33:58 (1753428838) [ 2402.125505] Lustre: DEBUG MARKER: == sanity test 118h: Verify timeout in handling recoverables errors ==================================================================== 03:34:00 (1753428840) [ 2402.814255] Lustre: *** cfs_fail_loc=20e, val=0*** [ 2403.854348] Lustre: *** cfs_fail_loc=20e, val=0*** [ 2405.902545] Lustre: *** cfs_fail_loc=20e, val=0*** [ 2408.910305] Lustre: *** cfs_fail_loc=20e, val=0*** [ 2412.942324] Lustre: *** cfs_fail_loc=20e, val=0*** [ 2415.809390] Lustre: DEBUG MARKER: == sanity test 118i: Fix error before timeout in recoverable error ==================================================================== 03:34:14 (1753428854) [ 2424.479872] Lustre: DEBUG MARKER: == sanity test 118j: Simulate unrecoverable OST side error ==================================================================== 03:34:23 (1753428863) [ 2425.135264] Lustre: *** cfs_fail_loc=220, val=0*** [ 2425.136929] Lustre: Skipped 3 previous similar messages [ 2427.937275] Lustre: DEBUG MARKER: == sanity test 118k: bio alloc -ENOMEM and IO TERM handling =================================================================== 03:34:26 (1753428866) [ 2441.116834] Lustre: DEBUG MARKER: == sanity test 118l: fsync dir =========================== 03:34:39 (1753428879) [ 2443.446872] Lustre: DEBUG MARKER: == sanity test 118m: fdatasync dir ======================= 03:34:42 (1753428882) [ 2445.656584] Lustre: DEBUG MARKER: == sanity test 118n: statfs() sends OST_STATFS requests in parallel ========================================================== 03:34:44 (1753428884) [ 2450.753745] Lustre: DEBUG MARKER: == sanity test 119a: Short directIO read must return actual read amount ========================================================== 03:34:49 (1753428889) [ 2453.046597] Lustre: DEBUG MARKER: == sanity test 119b: Sparse directIO read must return actual read amount ========================================================== 03:34:51 (1753428891) [ 2455.351549] Lustre: DEBUG MARKER: == sanity test 119c: Testing for direct read hitting hole ========================================================== 03:34:53 (1753428893) [ 2457.652271] Lustre: DEBUG MARKER: == sanity test 119e: Basic tests of dio read and write at various sizes ========================================================== 03:34:56 (1753428896) [ 2474.055486] Lustre: DEBUG MARKER: == sanity test 119f: dio vs dio race ===================== 03:35:12 (1753428912) [ 2492.481072] Lustre: DEBUG MARKER: == sanity test 119g: dio vs buffered I/O race ============ 03:35:30 (1753428930) [ 2515.762117] Lustre: DEBUG MARKER: == sanity test 119h: basic tests of memory unaligned dio ========================================================== 03:35:54 (1753428954) [ 2527.972556] Lustre: DEBUG MARKER: SKIP: sanity test_119i skipping ALWAYS excluded test 119i [ 2528.642078] Lustre: DEBUG MARKER: == sanity test 119j: basic tests of hybrid IO switching == 03:36:07 (1753428967) [ 2531.166050] Lustre: DEBUG MARKER: == sanity test 119m: Test DIO readv/writev: exercise iter duplication ========================================================== 03:36:09 (1753428969) [ 2533.512724] Lustre: DEBUG MARKER: == sanity test 119n: Test Unaligned DIO readv() and writev() with unpatched ZFS ========================================================== 03:36:12 (1753428972) [ 2534.066627] Lustre: DEBUG MARKER: SKIP: sanity test_119n zfs server without 'unaligned_dio' support [ 2534.644531] Lustre: DEBUG MARKER: == sanity test 119o: Test Unaligned DIO readv() and writev() with unpatched servers ========================================================== 03:36:13 (1753428973) [ 2535.229832] Lustre: DEBUG MARKER: SKIP: sanity test_119o need ldiskfs without 'unaligned_dio' support [ 2535.830357] Lustre: DEBUG MARKER: == sanity test 119p: Test Unaligned DIO readv() and writev() with patched servers ========================================================== 03:36:14 (1753428974) [ 2538.334346] Lustre: DEBUG MARKER: == sanity test 119q: Test patchded Unaligned DIO readv() and writev() ========================================================== 03:36:16 (1753428976) [ 2543.274913] Lustre: DEBUG MARKER: == sanity test 120a: Early Lock Cancel: mkdir test ======= 03:36:21 (1753428981) [ 2546.647797] Lustre: DEBUG MARKER: == sanity test 120b: Early Lock Cancel: create test ====== 03:36:25 (1753428985) [ 2549.704413] Lustre: DEBUG MARKER: == sanity test 120c: Early Lock Cancel: link test ======== 03:36:28 (1753428988) [ 2552.993667] Lustre: DEBUG MARKER: == sanity test 120d: Early Lock Cancel: setattr test ===== 03:36:31 (1753428991) [ 2556.276230] Lustre: DEBUG MARKER: == sanity test 120e: Early Lock Cancel: unlink test ====== 03:36:34 (1753428994) [ 2566.399652] Lustre: DEBUG MARKER: == sanity test 120f: Early Lock Cancel: rename test ====== 03:36:45 (1753429005) [ 2576.616597] Lustre: DEBUG MARKER: == sanity test 120g: Early Lock Cancel: performance test ========================================================== 03:36:55 (1753429015) [ 2729.451218] Lustre: DEBUG MARKER: == sanity test 121: read cancel race ===================== 03:39:27 (1753429167) [ 2736.584781] Lustre: DEBUG MARKER: == sanity test 123aa: verify statahead work ============== 03:39:34 (1753429174) [ 2743.729739] Lustre: DEBUG MARKER: ls -l 100 files without statahead: 1 sec [ 2745.263817] Lustre: DEBUG MARKER: ls -l 100 files with statahead: 0 sec [ 2763.218935] Lustre: DEBUG MARKER: ls -l 1000 files without statahead: 10 sec [ 2767.065124] Lustre: DEBUG MARKER: ls -l 1000 files with statahead: 3 sec [ 2830.983066] Lustre: DEBUG MARKER: ls -l 5000 files without statahead: 41 sec [ 2847.440357] Lustre: DEBUG MARKER: ls -l 5000 files with statahead: 13 sec [ 2848.085896] Lustre: DEBUG MARKER: ls -l done [ 2887.279451] Lustre: DEBUG MARKER: rm -r /mnt/lustre/d123aa.sanity: 38 seconds [ 2890.746444] Lustre: DEBUG MARKER: == sanity test 123ab: verify statahead work by using statx ========================================================== 03:42:09 (1753429329) [ 2893.748133] Lustre: DEBUG MARKER: statx -l 100 files without statahead: 1 sec [ 2894.851231] Lustre: DEBUG MARKER: statx -l 100 files with statahead: 1 sec [ 2906.927808] Lustre: DEBUG MARKER: statx -l 1000 files without statahead: 7 sec [ 2910.929739] Lustre: DEBUG MARKER: statx -l 1000 files with statahead: 3 sec [ 3052.251798] Lustre: DEBUG MARKER: statx -l 10000 files without statahead: 78 sec [ 3083.575402] Lustre: DEBUG MARKER: statx -l 10000 files with statahead: 26 sec [ 3084.132942] Lustre: DEBUG MARKER: statx -l done [ 3154.000507] Lustre: DEBUG MARKER: rm -r /mnt/lustre/d123ab.sanity: 69 seconds [ 3156.947918] Lustre: DEBUG MARKER: == sanity test 123ac: verify statahead work by using statx without glimpse RPCs ========================================================== 03:46:35 (1753429595) [ 3159.577753] Lustre: DEBUG MARKER: statx -c 1 [ 3160.440563] Lustre: DEBUG MARKER: statx -c 1 [ 3167.925348] Lustre: DEBUG MARKER: statx -c 1 [ 3170.836432] Lustre: DEBUG MARKER: statx -c 1 [ 3234.355184] Lustre: DEBUG MARKER: statx -c 1 [ 3256.589496] Lustre: DEBUG MARKER: statx -c 1 [ 3257.126420] Lustre: DEBUG MARKER: statx -c 1 [ 3315.787720] Lustre: DEBUG MARKER: rm -r /mnt/lustre/d123ac.sanity: 57 seconds [ 3317.734520] Lustre: DEBUG MARKER: statx --cached=always -D 100 files without statahead: 0 sec [ 3318.333764] Lustre: DEBUG MARKER: statx --cached=always -D 100 files with statahead: 0 sec [ 3322.714502] Lustre: DEBUG MARKER: statx --cached=always -D 1000 files without statahead: 0 sec [ 3323.355119] Lustre: DEBUG MARKER: statx --cached=always -D 1000 files with statahead: 0 sec [ 3347.944155] Lustre: DEBUG MARKER: statx --cached=always -D 10000 files without statahead: 0 sec [ 3348.702442] Lustre: DEBUG MARKER: statx --cached=always -D 10000 files with statahead: 0 sec [ 3581.979637] Lustre: DEBUG MARKER: statx --cached=always -D 100000 files without statahead: 2 sec [ 3584.125642] Lustre: DEBUG MARKER: statx --cached=always -D 100000 files with statahead: 1 sec [ 3584.657468] Lustre: DEBUG MARKER: statx --cached=always -D done [ 4806.540660] Lustre: DEBUG MARKER: rm -r /mnt/lustre/d123ac.sanity: 1221 seconds [ 4809.609705] Lustre: DEBUG MARKER: == sanity test 123ad: Verify batching statahead works correctly ========================================================== 04:14:08 (1753431248) [ 4813.070823] Lustre: DEBUG MARKER: ls -l 100 files without statahead: 1 sec [ 4814.132846] Lustre: DEBUG MARKER: ls -l 100 files with statahead: 0 sec [ 4826.547392] Lustre: DEBUG MARKER: ls -l 1000 files without statahead: 8 sec [ 4831.204369] Lustre: DEBUG MARKER: ls -l 1000 files with statahead: 3 sec [ 4941.312263] Lustre: DEBUG MARKER: ls -l 10000 files without statahead: 77 sec [ 4982.688438] Lustre: DEBUG MARKER: ls -l 10000 files with statahead: 37 sec [ 4983.221276] Lustre: DEBUG MARKER: ls -l done [ 5054.370441] Lustre: DEBUG MARKER: rm -r /mnt/lustre/d123ad.sanity: 70 seconds [ 5255.785121] Lustre: DEBUG MARKER: ls -l 100 files without statahead: 1 sec [ 5256.746767] Lustre: DEBUG MARKER: ls -l 100 files with statahead: 1 sec [ 5267.455203] Lustre: DEBUG MARKER: ls -l 1000 files without statahead: 6 sec [ 5271.581161] Lustre: DEBUG MARKER: ls -l 1000 files with statahead: 3 sec [ 5358.261149] Lustre: DEBUG MARKER: ls -l 10000 files without statahead: 61 sec [ 5395.103571] Lustre: DEBUG MARKER: ls -l 10000 files with statahead: 32 sec [ 5395.573617] Lustre: DEBUG MARKER: ls -l done [ 5460.004144] Lustre: DEBUG MARKER: rm -r /mnt/lustre/d123ad.sanity: 64 seconds [ 5617.487716] Lustre: DEBUG MARKER: == sanity test 123b: not panic with network error in statahead enqueue (bug 15027) ========================================================== 04:27:35 (1753432055) [ 5620.290453] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x240000400 to 0x240000401 [ 5620.321330] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x280000400 to 0x280000401 [ 5627.132957] Lustre: DEBUG MARKER: ls done [ 5635.116689] Lustre: DEBUG MARKER: == sanity test 123c: Can not initialize inode warning on DNE statahead ========================================================== 04:27:53 (1753432073) [ 5635.689833] Lustre: DEBUG MARKER: SKIP: sanity test_123c needs >= 2 MDTs [ 5636.551550] Lustre: DEBUG MARKER: == sanity test 123d: Statahead on striped directories works correctly ========================================================== 04:27:54 (1753432074) [ 5641.971275] Lustre: DEBUG MARKER: == sanity test 123e: statahead with large wide striping == 04:28:00 (1753432080) [ 5687.483566] Lustre: 75861:0:(mdt_handler.c:4689:mdt_unpack_req_pack_rep()) lustre-MDT0000: cannot pack response: rc = -75 [ 5803.143066] Lustre: DEBUG MARKER: == sanity test 123f: Retry mechanism with large wide striping files ========================================================== 04:30:40 (1753432240) [ 5908.116961] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x280000401 to 0x280000402 [ 5908.143383] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x240000401 to 0x240000402 [ 6154.221011] hrtimer: interrupt took 6470945 ns [ 6182.379856] Lustre: 75861:0:(mdt_handler.c:4689:mdt_unpack_req_pack_rep()) lustre-MDT0000: cannot pack response: rc = -75 [ 6706.558910] Lustre: DEBUG MARKER: == sanity test 123g: Test for stat-ahead advise ========== 04:45:41 (1753433141) [ 6787.578282] Lustre: DEBUG MARKER: == sanity test 123h: Verify statahead work with the fname pattern via du ========================================================== 04:47:02 (1753433222) [ 8314.929589] Lustre: DEBUG MARKER: == sanity test 123i: Verify statahead work with the fname indexing pattern ========================================================== 05:12:32 (1753434752) [ 8428.327640] Lustre: DEBUG MARKER: == sanity test 123j: -ENOENT error from batched statahead be handled correctly ========================================================== 05:14:26 (1753434866) [ 8429.463719] Lustre: DEBUG MARKER: SKIP: sanity test_123j needs >= 2 MDTs [ 8430.564391] Lustre: DEBUG MARKER: == sanity test 123k: Verify statahead work with mdtest shared stat() mode ========================================================== 05:14:28 (1753434868) [ 8431.620291] Lustre: DEBUG MARKER: SKIP: sanity test_123k mdtest not found [ 8432.877293] Lustre: DEBUG MARKER: == sanity test 123l: Avoid panic when revalidate a local cached entry ========================================================== 05:14:30 (1753434870) [ 8511.397661] Lustre: DEBUG MARKER: == sanity test 124a: lru resize ================================================================================================= 05:15:49 (1753434949) [ 8512.644808] Lustre: DEBUG MARKER: create 2000 files at /mnt/lustre/d124a.sanity [ 8540.333404] Lustre: DEBUG MARKER: NSDIR=ldlm.namespaces.lustre-MDT0000-mdc-ffff9c1ed80e8800 [ 8541.214611] Lustre: DEBUG MARKER: NS=ldlm.namespaces.lustre-MDT0000-mdc-ffff9c1ed80e8800 [ 8542.148608] Lustre: DEBUG MARKER: LRU=2003 [ 8542.993608] Lustre: DEBUG MARKER: LIMIT=61549 [ 8543.832976] Lustre: DEBUG MARKER: LVF=3687400 [ 8544.714391] Lustre: DEBUG MARKER: OLD_LVF=100 [ 8545.525432] Lustre: DEBUG MARKER: Sleep 50 sec [ 8596.944696] Lustre: DEBUG MARKER: Dropped 891 locks in 50s [ 8597.756656] Lustre: DEBUG MARKER: unlink 2000 files at /mnt/lustre/d124a.sanity [ 8620.714514] Lustre: DEBUG MARKER: == sanity test 124b: lru resize (performance test) ================================================================================= 05:17:38 (1753435058) [ 8675.925462] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x240000402 to 0x240000403 [ 8692.272021] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x280000402 to 0x280000403 [ 8707.751343] Lustre: DEBUG MARKER: doing ls -la /mnt/lustre/d124b.sanity/disable_lru_resize 3 times [ 8798.416681] Lustre: DEBUG MARKER: ls -la time: 90 seconds [ 8799.251384] Lustre: DEBUG MARKER: lru_size = 400 [ 8906.648579] Lustre: DEBUG MARKER: doing ls -la /mnt/lustre/d124b.sanity/enable_lru_resize 3 times [ 8955.041209] Lustre: DEBUG MARKER: ls -la time: 46 seconds [ 8955.843029] Lustre: DEBUG MARKER: lru_size = 8005 [ 8956.644587] Lustre: DEBUG MARKER: ls -la is 48% faster with lru resize enabled [ 8991.810339] Lustre: DEBUG MARKER: == sanity test 124c: LRUR cancel very aged locks ========= 05:23:50 (1753435430) [ 9018.010617] Lustre: DEBUG MARKER: == sanity test 124d: cancel very aged locks if lru-resize disabled ========================================================== 05:24:16 (1753435456) [ 9045.075933] Lustre: DEBUG MARKER: == sanity test 125: don't return EPROTO when a dir has a non-default striping and ACLs ========================================================== 05:24:43 (1753435483) [ 9049.508698] Lustre: DEBUG MARKER: == sanity test 126: check that the fsgid provided by the client is taken into account ========================================================== 05:24:47 (1753435487) [ 9053.716122] Lustre: DEBUG MARKER: == sanity test 127a: verify the client stats are sane ==== 05:24:51 (1753435491) [ 9058.326214] Lustre: DEBUG MARKER: == sanity test 127b: verify the llite client stats are sane ========================================================== 05:24:56 (1753435496) [ 9062.389420] Lustre: DEBUG MARKER: == sanity test 127c: test llite extent stats with regular [ 9147.236324] Lustre: DEBUG MARKER: == sanity test 128: interactive lfs for 2 consecutive find's ========================================================== 05:26:25 (1753435585) [ 9150.763902] Lustre: DEBUG MARKER: == sanity test 129: test directory size limit ================================================================================== 05:26:29 (1753435589) [ 9151.564929] Lustre: DEBUG MARKER: SKIP: sanity test_129 ldiskfs only test [ 9152.617143] Lustre: DEBUG MARKER: == sanity test 130a: FIEMAP (1-stripe file) ============== 05:26:30 (1753435590) [ 9153.576292] Lustre: DEBUG MARKER: SKIP: sanity test_130a LU-1941: FIEMAP unimplemented on ZFS [ 9154.502433] Lustre: DEBUG MARKER: SKIP: sanity test_130b skipping ALWAYS excluded test 130b [ 9155.450182] Lustre: DEBUG MARKER: SKIP: sanity test_130c skipping ALWAYS excluded test 130c [ 9156.360372] Lustre: DEBUG MARKER: SKIP: sanity test_130d skipping ALWAYS excluded test 130d [ 9157.155458] Lustre: DEBUG MARKER: SKIP: sanity test_130e skipping ALWAYS excluded test 130e [ 9157.947147] Lustre: DEBUG MARKER: SKIP: sanity test_130f skipping ALWAYS excluded test 130f [ 9158.812749] Lustre: DEBUG MARKER: SKIP: sanity test_130g skipping ALWAYS excluded test 130g [ 9159.668392] Lustre: DEBUG MARKER: == sanity test 130h: FIEMAP deadlock ===================== 05:26:38 (1753435598) [ 9169.655382] Lustre: DEBUG MARKER: == sanity test 130i: FIEMAP (DoM file) =================== 05:26:47 (1753435607) [ 9170.570035] Lustre: DEBUG MARKER: SKIP: sanity test_130i LU-1941: FIEMAP unimplemented on ZFS [ 9171.471405] Lustre: DEBUG MARKER: == sanity test 131a: test iov's crossing stripe boundary for writev/readv ========================================================== 05:26:49 (1753435609) [ 9174.763594] Lustre: DEBUG MARKER: == sanity test 131b: test append writev ================== 05:26:53 (1753435613) [ 9178.435308] Lustre: DEBUG MARKER: == sanity test 131c: test read/write on file w/o objects ========================================================== 05:26:56 (1753435616) [ 9182.023071] Lustre: DEBUG MARKER: == sanity test 131d: test short read ===================== 05:27:00 (1753435620) [ 9185.479600] Lustre: DEBUG MARKER: == sanity test 131e: test read hitting hole ============== 05:27:03 (1753435623) [ 9188.794312] Lustre: DEBUG MARKER: == sanity test 133a: Verifying MDT stats ================================================================================================== 05:27:07 (1753435627) [ 9199.117737] Lustre: DEBUG MARKER: == sanity test 133b: Verifying extra MDT stats ============================================================================================ 05:27:17 (1753435637) [ 9212.323189] Lustre: DEBUG MARKER: == sanity test 133c: Verifying OST stats ================================================================================================== 05:27:30 (1753435650) [ 9248.831692] Lustre: DEBUG MARKER: == sanity test 133d: Verifying rename_stats ================================================================================================== 05:28:07 (1753435687) [ 9267.136325] Lustre: DEBUG MARKER: == sanity test 133e: Verifying OST read_bytes write_bytes nid stats =========================================================================== 05:28:25 (1753435705) [ 9272.990781] Lustre: DEBUG MARKER: == sanity test 133f: Check reads/writes of client lustre proc files with bad area io ========================================================== 05:28:31 (1753435711) [ 9280.993372] 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 [ 9280.994838] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 9280.998883] Lustre: Skipped 1 previous similar message [ 9282.519257] LustreError: 91817:0:(obd_class.h:479:obd_check_dev()) Device 17 not setup [ 9282.522315] LustreError: 91817:0:(obd_class.h:479:obd_check_dev()) Skipped 1 previous similar message [ 9282.696747] Lustre: server umount lustre-MDT0000 complete [ 9284.793387] LustreError: 5731:0:(ldlm_lockd.c:2550:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1753435724 with bad export cookie 9940160859739912904 [ 9284.795065] LustreError: MGC192.168.202.144@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 9284.798226] LustreError: 5731:0:(ldlm_lockd.c:2550:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 9284.863199] LustreError: 92022:0:(obd_class.h:479:obd_check_dev()) Device 12 not setup [ 9284.867277] LustreError: 92022:0:(obd_class.h:479:obd_check_dev()) Skipped 5 previous similar messages [ 9284.885545] Lustre: server umount lustre-OST0000 complete [ 9286.890331] LustreError: 92223:0:(obd_class.h:479:obd_check_dev()) Device 2 not setup [ 9286.893792] LustreError: 92223:0:(obd_class.h:479:obd_check_dev()) Skipped 1 previous similar message [ 9287.015888] Lustre: server umount lustre-OST0001 complete [ 9292.029672] Lustre: DEBUG MARKER: oleg244-server.virtnet: executing unload_modules_local [ 9293.370949] Key type lgssc unregistered [ 9293.535613] LNet: 92749:0:(lib-ptl.c:966:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 9294.564801] LNet: Removed LNI 192.168.202.144@tcp [ 9294.948393] Key type .llcrypt unregistered [ 9294.950097] Key type ._llcrypt unregistered [ 9301.828155] Key type ._llcrypt registered [ 9301.829679] Key type .llcrypt registered [ 9301.876334] Lustre: DEBUG MARKER: oleg244-server.virtnet: executing load_modules_local [ 9302.241039] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 9302.282130] alg: No test for adler32 (adler32-zlib) [ 9303.157855] Lustre: Lustre: Build Version: 2.16.56_57_g82204de [ 9303.265734] LNet: Added LNI 192.168.202.144@tcp [8/256/0/180] [ 9303.268257] LNet: Accept secure, port 988 [ 9304.863406] Key type lgssc registered [ 9305.460206] Lustre: Echo OBD driver; http://www.lustre.org/ [ 9312.003861] Lustre: DEBUG MARKER: oleg244-server.virtnet: executing load_modules_local [ 9315.640694] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 9317.083890] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 9318.753572] Lustre: DEBUG MARKER: oleg244-server.virtnet: executing set_default_debug all all [ 9320.183840] Lustre: 94831:0:(mgs_llog.c:1345:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 9322.969709] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 9325.439656] Lustre: DEBUG MARKER: oleg244-server.virtnet: executing set_default_debug all all [ 9327.084510] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000403:5602 to 0x240000403:5889) [ 9328.849615] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 9331.604265] Lustre: DEBUG MARKER: oleg244-server.virtnet: executing set_default_debug all all [ 9334.259392] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000403:5180 to 0x280000403:5377) [ 9336.824991] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 9338.715524] Lustre: 96603:0:(mgs_llog.c:1345:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 9348.101793] Lustre: DEBUG MARKER: == sanity test 133g: Check reads/writes of server lustre proc files with bad area io ========================================================== 05:29:46 (1753435786) [ 9351.491941] LNet: 97136:0:(debug.c:388:cfs_str2mask()) unknown mask ''. [ 9351.491941] mask usage: [+|-] ... [ 9351.516950] Lustre: DEBUG MARKER:  [ 9351.518769] Lustre: DEBUG MARKER:  [ 9365.715532] LNet: 98203:0:(debug.c:388:cfs_str2mask()) unknown mask ''. [ 9365.715532] mask usage: [+|-] ... [ 9365.720325] LNet: 98203:0:(debug.c:388:cfs_str2mask()) Skipped 3 previous similar messages [ 9365.749402] Lustre: DEBUG MARKER:  [ 9380.321496] Lustre: lustre-MDT0000-lwp-OST0000: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 9380.322428] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 9380.327294] Lustre: Skipped 1 previous similar message [ 9381.271907] LustreError: 99133:0:(obd_class.h:479:obd_check_dev()) Device 9 not setup [ 9381.375466] Lustre: server umount lustre-MDT0000 complete [ 9383.651152] LustreError: 94409:0:(ldlm_lockd.c:2550:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1753435823 with bad export cookie 825890653637830360 [ 9383.651662] LustreError: MGC192.168.202.144@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 9383.656628] LustreError: 94409:0:(ldlm_lockd.c:2550:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 9383.689140] LustreError: 99339:0:(obd_class.h:479:obd_check_dev()) Device 14 not setup [ 9383.691023] LustreError: 99339:0:(obd_class.h:479:obd_check_dev()) Skipped 5 previous similar messages [ 9383.711807] Lustre: server umount lustre-OST0000 complete [ 9385.685357] LustreError: 99539:0:(obd_class.h:479:obd_check_dev()) Device 2 not setup [ 9385.687486] LustreError: 99539:0:(obd_class.h:479:obd_check_dev()) Skipped 1 previous similar message [ 9385.783638] Lustre: server umount lustre-OST0001 complete [ 9392.396138] Lustre: DEBUG MARKER: oleg244-server.virtnet: executing unload_modules_local [ 9393.764346] Key type lgssc unregistered [ 9393.950866] LNet: 100113:0:(lib-ptl.c:966:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 9394.981686] LNet: Removed LNI 192.168.202.144@tcp [ 9395.313727] Key type .llcrypt unregistered [ 9395.315544] Key type ._llcrypt unregistered [ 9402.156657] Key type ._llcrypt registered [ 9402.158014] Key type .llcrypt registered [ 9402.212813] Lustre: DEBUG MARKER: oleg244-server.virtnet: executing load_modules_local [ 9402.631953] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 9402.690801] alg: No test for adler32 (adler32-zlib) [ 9403.560304] Lustre: Lustre: Build Version: 2.16.56_57_g82204de [ 9403.649112] LNet: Added LNI 192.168.202.144@tcp [8/256/0/180] [ 9403.651582] LNet: Accept secure, port 988 [ 9405.247396] Key type lgssc registered [ 9405.713398] Lustre: Echo OBD driver; http://www.lustre.org/ [ 9412.030922] Lustre: DEBUG MARKER: oleg244-server.virtnet: executing load_modules_local [ 9415.601560] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 9417.018555] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 9418.728608] Lustre: DEBUG MARKER: oleg244-server.virtnet: executing set_default_debug all all [ 9420.098244] Lustre: 102185:0:(mgs_llog.c:1345:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 9422.776712] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 9425.453936] Lustre: DEBUG MARKER: oleg244-server.virtnet: executing set_default_debug all all [ 9426.861320] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000403:5602 to 0x240000403:5921) [ 9428.981878] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 9430.527198] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000403:5180 to 0x280000403:5409) [ 9431.726678] Lustre: DEBUG MARKER: oleg244-server.virtnet: executing set_default_debug all all [ 9436.787871] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 9438.552089] Lustre: 103967:0:(mgs_llog.c:1345:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 9447.133853] Lustre: DEBUG MARKER: == sanity test 133h: Proc files should end with newlines ========================================================== 05:31:25 (1753435885) [ 9821.742935] Lustre: DEBUG MARKER: == sanity test 134a: Server reclaims locks when reaching lock_reclaim_threshold ========================================================== 05:37:40 (1753436260) [ 9827.892610] Lustre: *** cfs_fail_loc=327, val=500*** [ 9828.496370] Lustre: *** cfs_fail_loc=327, val=500*** [ 9828.497738] Lustre: Skipped 512 previous similar messages [ 9846.116449] Lustre: DEBUG MARKER: == sanity test 134b: Server rejects lock request when reaching lock_limit_mb ========================================================== 05:38:04 (1753436284) [ 9848.380265] Lustre: *** cfs_fail_loc=328, val=500*** [ 9849.943065] Lustre: 104192:0:(ldlm_lockd.c:1320:ldlm_handle_enqueue()) @@@ Too many granted locks, reject current enqueue request and let the client retry later req@ffff910405c45c00 x1838610736356736/t0(0) o101->1a46cec0-a943-49a9-b108-af325e1d7caf@192.168.202.44@tcp:140/0 lens 648/0 e 0 to 0 dl 1753436300 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 9850.961609] Lustre: *** cfs_fail_loc=328, val=500*** [ 9850.963385] Lustre: Skipped 501 previous similar messages [ 9850.965257] Lustre: 104192:0:(ldlm_lockd.c:1320:ldlm_handle_enqueue()) @@@ Too many granted locks, reject current enqueue request and let the client retry later req@ffff9104436e7800 x1838610736357504/t0(0) o101->1a46cec0-a943-49a9-b108-af325e1d7caf@192.168.202.44@tcp:141/0 lens 648/0 e 0 to 0 dl 1753436301 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 9851.985627] Lustre: 101809:0:(ldlm_lockd.c:1320:ldlm_handle_enqueue()) @@@ Too many granted locks, reject current enqueue request and let the client retry later req@ffff9104436e5500 x1838610736358272/t0(0) o101->1a46cec0-a943-49a9-b108-af325e1d7caf@192.168.202.44@tcp:142/0 lens 648/0 e 0 to 0 dl 1753436302 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 9854.033580] Lustre: 101775:0:(ldlm_lockd.c:1320:ldlm_handle_enqueue()) @@@ Too many granted locks, reject current enqueue request and let the client retry later req@ffff910460d3fb80 x1838610736360192/t0(0) o101->1a46cec0-a943-49a9-b108-af325e1d7caf@192.168.202.44@tcp:144/0 lens 648/0 e 0 to 0 dl 1753436304 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 9854.045110] Lustre: 101775:0:(ldlm_lockd.c:1320:ldlm_handle_enqueue()) Skipped 1 previous similar message [ 9855.056917] Lustre: *** cfs_fail_loc=328, val=500*** [ 9855.058723] Lustre: Skipped 3 previous similar messages [ 9858.129448] Lustre: 104192:0:(ldlm_lockd.c:1320:ldlm_handle_enqueue()) @@@ Too many granted locks, reject current enqueue request and let the client retry later req@ffff910406421500 x1838610736363648/t0(0) o101->1a46cec0-a943-49a9-b108-af325e1d7caf@192.168.202.44@tcp:148/0 lens 648/0 e 0 to 0 dl 1753436308 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 9858.140632] Lustre: 104192:0:(ldlm_lockd.c:1320:ldlm_handle_enqueue()) Skipped 3 previous similar messages [ 9863.249109] Lustre: *** cfs_fail_loc=328, val=500*** [ 9863.250482] Lustre: Skipped 7 previous similar messages [ 9866.323785] Lustre: 104192:0:(ldlm_lockd.c:1320:ldlm_handle_enqueue()) @@@ Too many granted locks, reject current enqueue request and let the client retry later req@ffff910406420700 x1838610736370176/t0(0) o101->1a46cec0-a943-49a9-b108-af325e1d7caf@192.168.202.44@tcp:156/0 lens 648/0 e 0 to 0 dl 1753436316 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 9866.332826] Lustre: 104192:0:(ldlm_lockd.c:1320:ldlm_handle_enqueue()) Skipped 7 previous similar messages [ 9868.677466] LustreError: 151073:0:(ldlm_lockd.c:3259:lock_reclaim_threshold_mb_store()) Failed to set lock_reclaim_threshold_mb, rc = -22. [ 9874.741172] Lustre: DEBUG MARKER: SKIP: sanity test_135 skipping SLOW test 135 [ 9875.417237] Lustre: DEBUG MARKER: SKIP: sanity test_136 skipping SLOW test 136 [ 9876.133731] Lustre: DEBUG MARKER: == sanity test 140: Check reasonable stack depth (shouldn't LBUG) ============================================================== 05:38:34 (1753436314) [ 9892.719160] Lustre: DEBUG MARKER: == sanity test 150a: truncate/append tests =============== 05:38:51 (1753436331) [ 9930.955865] Lustre: DEBUG MARKER: == sanity test 150b: Verify fallocate (prealloc) functionality ========================================================== 05:39:29 (1753436369) [ 9931.576749] Lustre: DEBUG MARKER: SKIP: sanity test_150b need >= 2.13.57 and ldiskfs for fallocate [ 9932.236546] Lustre: DEBUG MARKER: == sanity test 150bb: Verify fallocate modes both zero space ========================================================== 05:39:30 (1753436370) [ 9932.869314] Lustre: DEBUG MARKER: SKIP: sanity test_150bb need >= 2.13.57 and ldiskfs for fallocate [ 9933.542036] Lustre: DEBUG MARKER: == sanity test 150c: Verify fallocate Size and Blocks ==== 05:39:32 (1753436372) [ 9934.170347] Lustre: DEBUG MARKER: SKIP: sanity test_150c need >= 2.13.57 and ldiskfs for fallocate [ 9934.841608] Lustre: DEBUG MARKER: == sanity test 150d: Verify fallocate Size and Blocks - Non zero start ========================================================== 05:39:33 (1753436373) [ 9935.478879] Lustre: DEBUG MARKER: SKIP: sanity test_150d need >= 2.13.57 and ldiskfs for fallocate [ 9936.223879] Lustre: DEBUG MARKER: == sanity test 150e: Verify 60% of available OST space consumed by fallocate ========================================================== 05:39:34 (1753436374) [ 9936.839631] Lustre: DEBUG MARKER: SKIP: sanity test_150e need >= 2.13.57 and ldiskfs for fallocate [ 9937.459050] Lustre: DEBUG MARKER: == sanity test 150f: Verify fallocate punch functionality ========================================================== 05:39:36 (1753436376) [ 9938.040625] Lustre: DEBUG MARKER: SKIP: sanity test_150f LU-14160: punch mode is not implemented on OSD ZFS [ 9938.735593] Lustre: DEBUG MARKER: == sanity test 150g: Verify fallocate punch on large range ========================================================== 05:39:37 (1753436377) [ 9939.314851] Lustre: DEBUG MARKER: SKIP: sanity test_150g LU-14160: punch mode is not implemented on OSD ZFS [ 9939.937546] Lustre: DEBUG MARKER: == sanity test 150h: Verify extend fallocate updates the file size ========================================================== 05:39:38 (1753436378) [ 9940.512169] Lustre: DEBUG MARKER: SKIP: sanity test_150h need >= 2.13.57 and ldiskfs for fallocate [ 9941.159938] Lustre: DEBUG MARKER: == sanity test 150ia: Verify fallocate zero-range ZERO functionality ========================================================== 05:39:39 (1753436379) [ 9941.721143] Lustre: DEBUG MARKER: SKIP: sanity test_150ia zero-range mode is not implemented on OSD ZFS [ 9942.362721] Lustre: DEBUG MARKER: == sanity test 150ib: Verify fallocate zero-range PREALLOC functionality ========================================================== 05:39:40 (1753436380) [ 9942.992722] Lustre: DEBUG MARKER: SKIP: sanity test_150ib zero-range mode is not implemented on OSD ZFS [ 9943.606638] Lustre: DEBUG MARKER: == sanity test 150ic: Verify fallocate LARGE zero PREALLOC functionality ========================================================== 05:39:42 (1753436382) [ 9944.119705] Lustre: DEBUG MARKER: SKIP: sanity test_150ic zero-range mode is not implemented on OSD ZFS [ 9944.719270] Lustre: DEBUG MARKER: == sanity test 151: test cache on oss and controls ========================================================================================= 05:39:43 (1753436383) [ 9945.874905] Lustre: DEBUG MARKER: SKIP: sanity test_151 not cache-capable obdfilter [ 9946.513663] Lustre: DEBUG MARKER: == sanity test 152: test read/write with enomem ====================================================================================== 05:39:45 (1753436385) [ 9949.191223] Lustre: DEBUG MARKER: == sanity test 153: test if fdatasync does not crash ================================================================================= 05:39:47 (1753436387) [ 9951.724237] Lustre: DEBUG MARKER: == sanity test 154A: lfs path2fid and fid2path basic checks ========================================================== 05:39:50 (1753436390) [ 9954.303134] Lustre: DEBUG MARKER: == sanity test 154B: verify the ll_decode_linkea tool ==== 05:39:52 (1753436392) [ 9957.014247] Lustre: DEBUG MARKER: == sanity test 154C: lfs fid2path on OST FID ============= 05:39:55 (1753436395) [ 9981.484911] Lustre: DEBUG MARKER: == sanity test 154a: Open-by-FID ========================= 05:40:19 (1753436419) [ 9982.195966] LustreError: 101776:0:(fld_handler.c:244:fld_server_lookup()) srv-lustre-MDT0000: Cannot find sequence 0xf00000400: rc = -2 [ 9985.730675] Lustre: DEBUG MARKER: == sanity test 154b: Open-by-FID for remote directory ==== 05:40:24 (1753436424) [ 9986.400861] Lustre: DEBUG MARKER: SKIP: sanity test_154b needs >= 2 MDTs [ 9987.122756] Lustre: DEBUG MARKER: == sanity test 154c: lfs path2fid and fid2path multiple arguments ========================================================== 05:40:25 (1753436425) [ 9989.715815] Lustre: DEBUG MARKER: == sanity test 154d: Verify open file fid ================ 05:40:28 (1753436428) [ 9992.869802] Lustre: DEBUG MARKER: == sanity test 154e: .lustre is not returned by readdir == 05:40:31 (1753436431) [ 9995.357479] Lustre: DEBUG MARKER: == sanity test 154ea: .lustre is not returned by readdir (2) ========================================================== 05:40:33 (1753436433) [10016.460620] Lustre: DEBUG MARKER: == sanity test 154f: get parent fids by reading link ea == 05:40:54 (1753436454) [10019.714640] Lustre: DEBUG MARKER: == sanity test 154g: various llapi FID tests ============= 05:40:58 (1753436458) [10419.388883] Lustre: DEBUG MARKER: == sanity test 154h: Verify interactive path2fid ========= 05:47:37 (1753436857) [10421.936057] Lustre: DEBUG MARKER: == sanity test 154i: fid2path for path longer than PATH_MAX ========================================================== 05:47:40 (1753436860) [10435.372774] Lustre: DEBUG MARKER: == sanity test 155a: Verify small file correctness: read cache:on write_cache:on ========================================================== 05:47:53 (1753436873) [10440.037784] Lustre: DEBUG MARKER: == sanity test 155b: Verify small file correctness: read cache:on write_cache:off ========================================================== 05:47:58 (1753436878) [10444.551859] Lustre: DEBUG MARKER: == sanity test 155c: Verify small file correctness: read cache:off write_cache:on ========================================================== 05:48:03 (1753436883) [10448.842099] Lustre: DEBUG MARKER: == sanity test 155d: Verify small file correctness: read cache:off write_cache:off ========================================================== 05:48:07 (1753436887) [10453.333428] Lustre: DEBUG MARKER: == sanity test 155e: Verify big file correctness: read cache:on write_cache:on ========================================================== 05:48:11 (1753436891) [10487.738723] Lustre: DEBUG MARKER: == sanity test 155f: Verify big file correctness: read cache:on write_cache:off ========================================================== 05:48:46 (1753436926) [10526.036609] Lustre: DEBUG MARKER: == sanity test 155g: Verify big file correctness: read cache:off write_cache:on ========================================================== 05:49:24 (1753436964) [10564.961641] Lustre: DEBUG MARKER: == sanity test 155h: Verify big file correctness: read cache:off write_cache:off ========================================================== 05:50:03 (1753437003) [10601.049432] Lustre: DEBUG MARKER: == sanity test 156: Verification of tunables ============= 05:50:39 (1753437039) [10601.661300] Lustre: DEBUG MARKER: SKIP: sanity test_156 LU-1956/LU-2261: stats not implemented on OSD ZFS [10602.245328] Lustre: DEBUG MARKER: == sanity test 160a: changelog sanity ==================== 05:50:40 (1753437040) [10603.198140] Lustre: lustre-MDD0000: changelog on [10608.015876] Lustre: Failing over lustre-MDT0000 [10608.209356] LustreError: 163611:0:(obd_class.h:479:obd_check_dev()) Device 9 not setup [10608.286268] Lustre: server umount lustre-MDT0000 complete [10610.588403] LustreError: MGC192.168.202.144@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [10610.721614] Lustre: lustre-MDT0000-lwp-OST0000: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [10610.726287] Lustre: Skipped 1 previous similar message [10610.782405] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [10610.808065] Lustre: lustre-MDD0000: changelog on [10610.814762] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [10612.081865] Lustre: DEBUG MARKER: oleg244-server.virtnet: executing set_default_debug all all [10613.077282] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [10613.399870] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [10613.416914] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000403:6751 to 0x240000403:6785) [10613.417133] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000403:6234 to 0x280000403:6273) [10613.694694] Lustre: lustre-MDD0000: changelog off [10615.779415] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to (at 0@lo) [10617.181827] Lustre: DEBUG MARKER: == sanity test 160b: Verify that very long rename doesn't crash in changelog ========================================================== 05:50:55 (1753437055) [10618.158261] Lustre: lustre-MDD0000: changelog on [10620.868428] Lustre: lustre-MDD0000: changelog off [10621.704799] Lustre: DEBUG MARKER: == sanity test 160c: verify that changelog log catch the truncate event ========================================================== 05:51:00 (1753437060) [10622.714977] Lustre: lustre-MDD0000: changelog on [10626.015364] Lustre: 100550:0:(client.c:2453:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1753437049/real 1753437049] req@ffff9105073e6680 x1838610743205632/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1753437065 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [10626.018094] Lustre: lustre-MDD0000: changelog off [10626.024738] Lustre: 100550:0:(client.c:2453:ptlrpc_expire_one_request()) Skipped 1 previous similar message [10626.924928] Lustre: DEBUG MARKER: == sanity test 160d: verify that changelog log catch the migrate event ========================================================== 05:51:05 (1753437065) [10627.586487] Lustre: DEBUG MARKER: SKIP: sanity test_160d needs >= 2 MDTs [10628.184196] Lustre: DEBUG MARKER: == sanity test 160e: changelog negative testing (should return errors) ========================================================== 05:51:06 (1753437066) [10629.182673] Lustre: lustre-MDD0000: changelog on [10631.881664] Lustre: lustre-MDD0000: changelog off [10632.721179] Lustre: DEBUG MARKER: == sanity test 160f: changelog garbage collect (timestamped users) ========================================================== 05:51:11 (1753437071) [10635.077560] Lustre: DEBUG MARKER: 1753437073: creating first dirs [10646.455190] Lustre: *** cfs_fail_loc=1313, val=3*** [10646.456324] Lustre: 164037:0:(mdd_dir.c:996:mdd_changelog_emrg_cleanup()) lustre-MDD0000: changelog has only 3 free catalog entries [10646.459092] Lustre: 164037:0:(mdd_dir.c:1079:mdd_changelog_store()) lustre-MDD0000: starting changelog garbage collection [10646.462859] Lustre: 167772:0:(mdd_trans.c:150:mdd_chlg_garbage_collect()) lustre-MDD0000: force deregister of changelog user cl6 idle for 12s with 4 unprocessed records [10652.407378] Lustre: lustre-MDD0000: changelog off [10653.244866] Lustre: DEBUG MARKER: == sanity test 160g: changelog garbage collect on idle records ========================================================== 05:51:31 (1753437091) [10654.251343] Lustre: lustre-MDD0000: changelog on [10654.252554] Lustre: Skipped 1 previous similar message [10659.319593] Lustre: 165199:0:(mdd_dir.c:1079:mdd_changelog_store()) lustre-MDD0000: starting changelog garbage collection [10659.322644] Lustre: 169367:0:(mdd_trans.c:150:mdd_chlg_garbage_collect()) lustre-MDD0000: force deregister of changelog user cl8 idle for 4s with 4 unprocessed records [10664.204248] Lustre: lustre-MDD0000: changelog off [10665.006596] Lustre: DEBUG MARKER: == sanity test 160h: changelog gc thread stop upon umount, orphan records delete ========================================================== 05:51:43 (1753437103) [10681.607078] Lustre: *** cfs_fail_loc=1316, val=0*** [10681.608907] Lustre: 165199:0:(mdd_dir.c:1079:mdd_changelog_store()) lustre-MDD0000: simulate starting changelog garbage collection [10681.614712] Lustre: 170962:0:(mdd_trans.c:150:mdd_chlg_garbage_collect()) lustre-MDD0000: force deregister of changelog user cl10 idle for 15s with 4 unprocessed records [10682.286149] Lustre: Failing over lustre-MDT0000 [10682.339262] Lustre: lustre-MDT0000-lwp-OST0000: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [10682.344219] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [10684.521729] LustreError: 171109:0:(obd_class.h:479:obd_check_dev()) Device 9 not setup [10684.523919] LustreError: 171109:0:(obd_class.h:479:obd_check_dev()) Skipped 5 previous similar messages [10684.603049] Lustre: server umount lustre-MDT0000 complete [10686.974183] LustreError: MGC192.168.202.144@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [10687.140937] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [10687.166044] Lustre: lustre-MDD0000: changelog on [10687.167443] Lustre: Skipped 1 previous similar message [10687.169382] Lustre: 171870:0:(mdd_device.c:622:mdd_changelog_llog_init()) lustre-MDD0000 : orphan changelog records found, starting from index 34 to index 35, being cleared now [10687.179793] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [10688.472248] Lustre: DEBUG MARKER: oleg244-server.virtnet: executing set_default_debug all all [10689.888949] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [10690.206806] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [10690.224591] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000403:6787 to 0x240000403:6817) [10690.224592] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000403:6234 to 0x280000403:6305) [10692.580151] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to (at 0@lo) [10692.581598] Lustre: Skipped 1 previous similar message [10694.021530] Lustre: lustre-MDD0000: changelog off [10694.845124] Lustre: DEBUG MARKER: == sanity test 160i: changelog user register/unregister race ========================================================== 05:52:13 (1753437133) [10697.252120] LustreError: 173319:0:(mdd_device.c:2022:mdd_changelog_user_purge()) cfs_race id 1315 sleeping [10699.550499] LustreError: 173452:0:(mdd_device.c:1747:mdd_changelog_user_register()) cfs_fail_race id 1315 waking [10699.553764] LustreError: 173319:0:(mdd_device.c:2022:mdd_changelog_user_purge()) cfs_fail_race id 1315 awake: rc=2701 [10704.636859] Lustre: DEBUG MARKER: == sanity test 160j: client can be umounted while its chanangelog is being used ========================================================== 05:52:23 (1753437143) [10710.476230] Lustre: DEBUG MARKER: == sanity test 160k: Verify that changelog records are not lost ========================================================== 05:52:29 (1753437149) [10712.068763] LustreError: 171878:0:(mdd_dir.c:1051:mdd_changelog_store()) cfs_fail_timeout id 15d sleeping for 3000ms [10715.087108] LustreError: 171878:0:(mdd_dir.c:1051:mdd_changelog_store()) cfs_fail_timeout id 15d awake [10722.080127] Lustre: DEBUG MARKER: == sanity test 160l: Verify that MTIME changelog records contain the parent FID ========================================================== 05:52:40 (1753437160) [10723.122165] Lustre: lustre-MDD0000: changelog on [10723.124060] Lustre: Skipped 4 previous similar messages [10728.262180] Lustre: lustre-MDD0000: changelog off [10728.264171] Lustre: Skipped 4 previous similar messages [10729.158705] Lustre: DEBUG MARKER: == sanity test 160m: Changelog clear race ================ 05:52:47 (1753437167) [10732.228665] LustreError: 171879:0:(mdd_device.c:394:llog_changelog_cancel_cb()) cfs_race id 15f sleeping [10734.233774] LustreError: 171878:0:(mdd_device.c:394:llog_changelog_cancel_cb()) cfs_fail_race id 15f waking [10734.236775] LustreError: 171879:0:(mdd_device.c:394:llog_changelog_cancel_cb()) cfs_fail_race id 15f awake: rc=2995 [10738.416234] Lustre: DEBUG MARKER: == sanity test 160n: Changelog destroy race ============== 05:52:56 (1753437176) [11383.899262] LustreError: 171878:0:(mdd_device.c:408:llog_changelog_cancel_cb()) cfs_race id 16c sleeping [11385.904565] LustreError: 171879:0:(llog_osd.c:1129:llog_osd_next_block()) cfs_fail_race id 16c waking [11385.907677] LustreError: 171878:0:(mdd_device.c:408:llog_changelog_cancel_cb()) cfs_fail_race id 16c awake: rc=2995 [11393.321757] Lustre: lustre-MDD0000: changelog off [11393.323483] Lustre: Skipped 1 previous similar message [11394.343322] Lustre: DEBUG MARKER: == sanity test 160o: changelog user name and mask ======== 06:03:52 (1753437832) [11395.404653] Lustre: lustre-MDD0000: changelog on [11395.405832] Lustre: Skipped 2 previous similar messages [11395.708676] LustreError: 178995:0:(mdd_device.c:1701:mdd_changelog_name_check()) lustre-MDD0000: wrong char '#' in name 'Tt3_-#': rc = -22 [11396.029673] Lustre: 179043:0:(mdd_device.c:1718:mdd_changelog_name_check()) lustre-MDD0000: changelog name test_160o exists already: rc = -17 [11396.374229] LustreError: 179091:0:(mdd_device.c:1710:mdd_changelog_name_check()) lustre-MDD0000: name 'test_160toolongname' is over 16 symbols limit: rc = -36 [11405.468494] Lustre: DEBUG MARKER: == sanity test 160p: Changelog orphan cleanup with no users ========================================================== 06:04:03 (1753437843) [11406.162664] Lustre: DEBUG MARKER: SKIP: sanity test_160p ldiskfs only test [11406.803188] Lustre: DEBUG MARKER: == sanity test 160q: changelog effective mask is DEFMASK if not set ========================================================== 06:04:05 (1753437845) [11411.094252] Lustre: DEBUG MARKER: == sanity test 160s: changelog garbage collect on idle records * time ========================================================== 06:04:09 (1753437849) [11418.404317] Lustre: 172376:0:(mdd_dir.c:1079:mdd_changelog_store()) lustre-MDD0000: starting changelog garbage collection [11418.408843] Lustre: 181234:0:(mdd_trans.c:150:mdd_chlg_garbage_collect()) lustre-MDD0000: force deregister of changelog user cl24 idle for 864005s with 500000004 unprocessed records [11424.576333] Lustre: DEBUG MARKER: == sanity test 160t: changelog garbage collect on lack of space ========================================================== 06:04:23 (1753437863) [11448.765594] Lustre: *** cfs_fail_loc=18c, val=1211660*** [11448.767693] Lustre: 172407:0:(mdd_dir.c:966:mdd_changelog_is_space_safe()) lustre-MDD0000: changelog uses 33MB with 1MB space limit [11448.771839] Lustre: 172407:0:(mdd_dir.c:1079:mdd_changelog_store()) lustre-MDD0000: starting changelog garbage collection [11448.776353] Lustre: 182810:0:(mdd_trans.c:150:mdd_chlg_garbage_collect()) lustre-MDD0000: force deregister of changelog user cl25-user1 idle for 23s with 7505 unprocessed records [11449.496309] Lustre: *** cfs_fail_loc=18c, val=1211660*** [11463.361765] Lustre: DEBUG MARKER: == sanity test 160u: changelog rename record type name and sname strings are correct ========================================================== 06:05:01 (1753437901) [11475.820711] Lustre: DEBUG MARKER: == sanity test 161a: link ea sanity ====================== 06:05:13 (1753437913) [11491.236218] Lustre: DEBUG MARKER: == sanity test 161b: link ea sanity under remote directory ========================================================== 06:05:29 (1753437929) [11491.795483] Lustre: DEBUG MARKER: SKIP: sanity test_161b skipping remote directory test [11492.449954] Lustre: DEBUG MARKER: == sanity test 161c: check CL_RENME[UNLINK] changelog record flags ========================================================== 06:05:30 (1753437930) [11499.036870] Lustre: DEBUG MARKER: == sanity test 161d: create with concurrent .lustre/fid access ========================================================== 06:05:37 (1753437937) [11506.677937] Lustre: DEBUG MARKER: == sanity test 162a: path lookup sanity ================== 06:05:45 (1753437945) [11509.938889] Lustre: DEBUG MARKER: == sanity test 162b: striped directory path lookup sanity ========================================================== 06:05:48 (1753437948) [11510.662914] Lustre: DEBUG MARKER: SKIP: sanity test_162b needs >= 2 MDTs [11511.433251] Lustre: DEBUG MARKER: == sanity test 162c: fid2path works with paths 100 or more directories deep ========================================================== 06:05:49 (1753437949) [11536.059097] Lustre: DEBUG MARKER: == sanity test 165a: ofd access log discovery ============ 06:06:14 (1753437974) [11542.495113] Lustre: Failing over lustre-OST0000 [11542.499554] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -19 [11542.504871] Lustre: lustre-OST0000-osc-MDT0000: Connection to lustre-OST0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [11542.510665] Lustre: Skipped 1 previous similar message [11542.514349] Lustre: lustre-OST0000: Not available for connect from 0@lo (stopping) [11542.517025] Lustre: Skipped 1 previous similar message [11542.580138] LustreError: 186602:0:(obd_class.h:479:obd_check_dev()) Device 14 not setup [11542.582844] LustreError: 186602:0:(obd_class.h:479:obd_check_dev()) Skipped 5 previous similar messages [11542.604677] Lustre: server umount lustre-OST0000 complete [11543.400801] LustreError: 156200:0:(ldlm_lib.c:1113:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.202.44@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [11543.406816] LustreError: 156200:0:(ldlm_lib.c:1113:target_handle_connect()) Skipped 2 previous similar messages [11547.617523] LustreError: 156200:0:(ldlm_lib.c:1113:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [11550.374193] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [11550.382228] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [11551.730433] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [11552.022192] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [11552.022500] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 192.168.202.144@tcp (at 0@lo) [11552.034088] Lustre: Skipped 1 previous similar message [11552.992960] Lustre: DEBUG MARKER: oleg244-server.virtnet: executing set_default_debug all all [11554.893603] Lustre: DEBUG MARKER: == sanity test 165b: ofd access log entries are produced and consumed ========================================================== 06:06:33 (1753437993) [11580.489376] Lustre: Failing over lustre-OST0000 [11580.534135] LustreError: 188513:0:(obd_class.h:479:obd_check_dev()) Device 14 not setup [11580.535898] LustreError: 188513:0:(obd_class.h:479:obd_check_dev()) Skipped 1 previous similar message [11580.550218] Lustre: server umount lustre-OST0000 complete [11581.412921] Lustre: lustre-OST0000-osc-MDT0000: Connection to lustre-OST0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [11581.422158] LustreError: 156197:0:(ldlm_lib.c:1113:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [11581.427440] LustreError: 156197:0:(ldlm_lib.c:1113:target_handle_connect()) Skipped 1 previous similar message [11584.005989] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [11584.013412] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [11584.347682] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [11585.165031] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [11585.165384] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 192.168.202.144@tcp (at 0@lo) [11586.170300] Lustre: DEBUG MARKER: oleg244-server.virtnet: executing set_default_debug all all [11587.595745] Lustre: DEBUG MARKER: == sanity test 165c: full ofd access logs do not block IOs ========================================================== 06:07:06 (1753438026) [11602.437170] Lustre: Failing over lustre-OST0000 [11604.451723] Lustre: lustre-OST0000-osc-MDT0000: Connection to lustre-OST0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [11604.462160] Lustre: lustre-OST0000: Not available for connect from 0@lo (stopping) [11604.550967] LustreError: 190018:0:(obd_class.h:479:obd_check_dev()) Device 14 not setup [11604.553623] LustreError: 190018:0:(obd_class.h:479:obd_check_dev()) Skipped 1 previous similar message [11604.567073] Lustre: server umount lustre-OST0000 complete [11604.828865] LustreError: 150362:0:(ldlm_lib.c:1113:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.202.44@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [11608.082068] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [11608.089386] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [11609.568421] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [11609.863261] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [11609.863505] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 192.168.202.144@tcp (at 0@lo) [11610.547185] Lustre: DEBUG MARKER: oleg244-server.virtnet: executing set_default_debug all all [11611.964419] Lustre: DEBUG MARKER: == sanity test 165d: ofd_access_log mask works =========== 06:07:30 (1753438050) [11637.852548] Lustre: Failing over lustre-OST0000 [11637.891259] LustreError: 192324:0:(obd_class.h:479:obd_check_dev()) Device 14 not setup [11637.893364] LustreError: 192324:0:(obd_class.h:479:obd_check_dev()) Skipped 1 previous similar message [11637.906544] Lustre: server umount lustre-OST0000 complete [11638.754717] Lustre: lustre-OST0000-osc-MDT0000: Connection to lustre-OST0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [11638.764452] LustreError: 150360:0:(ldlm_lib.c:1113:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [11641.537753] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [11641.547172] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [11642.613856] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [11643.076808] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [11643.078490] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 192.168.202.144@tcp (at 0@lo) [11644.003986] Lustre: DEBUG MARKER: oleg244-server.virtnet: executing set_default_debug all all [11645.579866] Lustre: DEBUG MARKER: == sanity test 165e: ofd_access_log MDT index filter works ========================================================== 06:08:03 (1753438083) [11646.332239] Lustre: DEBUG MARKER: SKIP: sanity test_165e needs >= 2 MDTs [11647.155388] Lustre: DEBUG MARKER: == sanity test 165f: ofd_access_log_reader --exit-on-close works ========================================================== 06:08:05 (1753438085) [11653.404981] Lustre: Failing over lustre-OST0000 [11653.444488] LustreError: 193517:0:(obd_class.h:479:obd_check_dev()) Device 14 not setup [11653.447875] LustreError: 193517:0:(obd_class.h:479:obd_check_dev()) Skipped 1 previous similar message [11653.464487] Lustre: server umount lustre-OST0000 complete [11653.599930] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [11653.603893] Lustre: lustre-OST0000-osc-MDT0000: Connection to lustre-OST0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [11653.610080] LustreError: 156197:0:(ldlm_lib.c:1113:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [11653.615068] LustreError: 156197:0:(ldlm_lib.c:1113:target_handle_connect()) Skipped 1 previous similar message [11660.402785] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [11660.410886] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [11661.135439] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [11661.636681] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [11661.636912] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 192.168.202.144@tcp (at 0@lo) [11662.687964] Lustre: DEBUG MARKER: oleg244-server.virtnet: executing set_default_debug all all [11664.208649] Lustre: DEBUG MARKER: == sanity test 165g: ofd_access_log_reader --keepalive works ========================================================== 06:08:22 (1753438102) [11705.721525] Lustre: Failing over lustre-OST0000 [11705.757126] LustreError: 195037:0:(obd_class.h:479:obd_check_dev()) Device 14 not setup [11705.760636] LustreError: 195037:0:(obd_class.h:479:obd_check_dev()) Skipped 1 previous similar message [11705.776476] Lustre: server umount lustre-OST0000 complete [11706.338535] Lustre: lustre-OST0000-osc-MDT0000: Connection to lustre-OST0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [11706.344071] LustreError: 156197:0:(ldlm_lib.c:1113:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [11706.349728] LustreError: 156197:0:(ldlm_lib.c:1113:target_handle_connect()) Skipped 2 previous similar messages [11712.892554] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [11712.900658] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [11714.861433] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 1 client reconnects [11714.918050] Lustre: lustre-OST0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [11714.923802] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 192.168.202.144@tcp (at 0@lo) [11715.517542] Lustre: DEBUG MARKER: oleg244-server.virtnet: executing set_default_debug all all [11717.261542] Lustre: DEBUG MARKER: == sanity test 169: parallel read and truncate should not deadlock ========================================================== 06:09:15 (1753438155) [11718.057862] Lustre: DEBUG MARKER: creating a 10 Mb file [11742.414121] Lustre: DEBUG MARKER: starting reads [11743.210288] Lustre: DEBUG MARKER: truncating the file [11744.077260] Lustre: DEBUG MARKER: killing dd [11744.762644] Lustre: DEBUG MARKER: removing the temporary file [11747.826547] Lustre: DEBUG MARKER: == sanity test 170a: test lctl df to handle corrupted log ========================================================== 06:09:46 (1753438186) [11751.461074] Lustre: DEBUG MARKER: == sanity test 170b: check filename encoding ============= 06:09:49 (1753438189) [11762.573684] Lustre: DEBUG MARKER: == sanity test 171: test libcfs_debug_dumplog_thread stuck in do_exit() ================================================================ 06:10:01 (1753438201) [11768.570280] Lustre: DEBUG MARKER: == sanity test 172: manual device removal with lctl cleanup/detach ================================================================ 06:10:06 (1753438206) [11773.050706] Lustre: DEBUG MARKER: == sanity test 180a: test obdecho on osc ================= 06:10:11 (1753438211) [11773.843620] Lustre: DEBUG MARKER: SKIP: sanity test_180a obdecho on osc is no longer supported [11774.667391] Lustre: DEBUG MARKER: == sanity test 180b: test obdecho directly on obdfilter == 06:10:13 (1753438213) [11776.068038] Lustre: DEBUG MARKER: oleg244-server.virtnet: executing load_module obdecho/obdecho [11783.855804] Lustre: DEBUG MARKER: == sanity test 180c: test huge bulk I/O size on obdfilter, don't LASSERT ========================================================== 06:10:22 (1753438222) [11785.194282] Lustre: DEBUG MARKER: oleg244-server.virtnet: executing load_module obdecho/obdecho [11785.256562] Lustre: Echo OBD driver; http://www.lustre.org/ [11793.504961] Lustre: DEBUG MARKER: == sanity test 181: Test open-unlinked dir ================================================================================== 06:10:31 (1753438231) [11828.597957] Lustre: DEBUG MARKER: == sanity test 182a: Test parallel modify metadata operations from mdc ========================================================== 06:11:06 (1753438266) [11831.587914] ODEBUG: object 0000000026451ee6 is on stack 00000000b5244cee, but NOT annotated. [11831.591911] WARNING: CPU: 3 PID: 171880 at lib/debugobjects.c:368 __debug_object_init.cold.5+0x35/0x15f [11831.595620] Modules linked in: lustre(O) osp(O) ofd(O) lod(O) mdt(O) mdd(O) mgs(O) osd_zfs(O) lquota(O) lfsck(O) mgc(O) mdc(O) lov(O) osc(O) lmv(O) fid(O) fld(O) ptlrpc_gss(O) ptlrpc(O) obdclass(O) ksocklnd(O) lnet(O) libcfs(O) zfs(O) spl(O) rpcsec_gss_krb5 auth_rpcgss nfsv4 dns_resolver intel_rapl_msr intel_rapl_common sb_edac rapl pcspkr i2c_piix4 squashfs crct10dif_pclmul crc32_pclmul ata_generic crc32c_intel ghash_clmulni_intel ata_piix serio_raw libata dm_mirror dm_region_hash dm_log dm_mod sha512_ssse3 sha512_generic [last unloaded: obdecho] [11831.615277] CPU: 3 PID: 171880 Comm: mdt00_002 Kdump: loaded Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [11831.618225] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.16.2-1.fc38 04/01/2014 [11831.620228] RIP: 0010:__debug_object_init.cold.5+0x35/0x15f [11831.621544] Code: be a9 48 83 05 23 61 0c 03 01 89 05 59 69 0c 03 65 48 8b 04 25 00 dd 01 00 48 8b 50 18 e8 93 68 99 ff 48 83 05 1b 61 0c 03 01 <0f> 0b 48 83 05 19 61 0c 03 01 48 83 05 19 61 0c 03 01 e9 3f ee ff [11831.627613] RSP: 0018:ffff9cfcc195b4a0 EFLAGS: 00010002 [11831.630340] RAX: 0000000000000050 RBX: ffff9cfcc195b5a8 RCX: 0000000000000000 [11831.633069] RDX: 0000000000000000 RSI: ffff91054219e5a8 RDI: ffff91054219e5a8 [11831.635816] RBP: ffffffffaa306ae0 R08: 0000000000000000 R09: c0000000ffff7fff [11831.638658] R10: 0000000000000001 R11: ffff9cfcc195b298 R12: ffffffffabaf72c8 [11831.641315] R13: 0000000000009ae0 R14: ffffffffabaf72c0 R15: ffff91042ef7e168 [11831.644819] FS: 0000000000000000(0000) GS:ffff910542180000(0000) knlGS:0000000000000000 [11831.647565] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [11831.649901] CR2: 00007f83f73c7040 CR3: 0000000083816006 CR4: 0000000000170ee0 [11831.652405] Call Trace: [11831.653971] ? show_regs.cold.9+0x22/0x2f [11831.655164] ? __warn+0xc8/0x150 [11831.656046] ? __debug_object_init.cold.5+0x35/0x15f [11831.657310] ? report_bug+0x113/0x140 [11831.658308] ? do_error_trap+0xb6/0x130 [11831.659367] ? do_invalid_op+0x46/0x60 [11831.660554] ? __debug_object_init.cold.5+0x35/0x15f [11831.662149] ? invalid_op+0x14/0x20 [11831.663273] ? __debug_object_init.cold.5+0x35/0x15f [11831.664896] ? lod_set_pool+0x280/0x280 [lod] [11831.666133] debug_object_init+0x22/0x30 [11831.667179] init_timer_key+0x28/0x120 [11831.668157] lod_ost_alloc_qos+0x79c/0x1b40 [lod] [11831.669583] ? slab_post_alloc_hook+0x66/0x380 [11831.670993] ? lod_qos_prep_create+0x39c/0x1c10 [lod] [11831.672745] ? __kmalloc+0x1b4/0x4a0 [11831.673904] lod_qos_prep_create+0x131a/0x1c10 [lod] [11831.675506] ? osd_declare_quota+0x39/0x730 [osd_zfs] [11831.677107] lod_prepare_create+0x204/0x460 [lod] [11831.678658] lod_declare_striped_create+0x270/0xf80 [lod] [11831.680631] ? lod_sub_declare_create+0x111/0x320 [lod] [11831.682464] lod_declare_create+0x3d4/0x9c0 [lod] [11831.684249] mdd_declare_create_object_internal+0x107/0x4a0 [mdd] [11831.686461] ? lod_alloc_comp_entries+0x2a7/0x660 [lod] [11831.688442] mdd_declare_create_object.isra.25+0x55/0xc40 [mdd] [11831.690531] mdd_declare_create+0x6a/0x6c0 [mdd] [11831.692298] mdd_create+0x5bd/0x1d00 [mdd] [11831.693846] ? mdt_version_save+0xa8/0x210 [mdt] [11831.695548] mdt_reint_open+0x337c/0x3c10 [mdt] [11831.697163] ? old_init_ucred_common+0x1ae/0x840 [mdt] [11831.699058] ? lustre_swab_generic_32s+0x20/0x20 [ptlrpc] [11831.701013] mdt_reint_rec+0x139/0x2b0 [mdt] [11831.702360] mdt_reint_internal+0x6a0/0xdc0 [mdt] [11831.703957] mdt_intent_open+0x180/0x5b0 [mdt] [11831.705628] mdt_intent_opc.constprop.44+0x153/0xfb0 [mdt] [11831.707203] ? mdt_intent_fixup_resent+0x2e0/0x2e0 [mdt] [11831.708917] mdt_intent_policy+0x14b/0x670 [mdt] [11831.710381] ldlm_lock_enqueue+0x43c/0xcd0 [ptlrpc] [11831.711999] ? _raw_read_unlock+0x12/0x30 [11831.712958] ? cfs_hash_rw_unlock+0x11/0x30 [obdclass] [11831.715126] ldlm_handle_enqueue+0x43f/0x2320 [ptlrpc] [11831.717170] tgt_enqueue+0xd0/0x300 [ptlrpc] [11831.718949] tgt_handle_request0+0x137/0xaf0 [ptlrpc] [11831.721006] tgt_request_handle+0x351/0x1c00 [ptlrpc] [11831.724211] ? obd_export_timed_fini+0xe8/0x110 [obdclass] [11831.727139] ptlrpc_server_handle_request+0x443/0x13b0 [ptlrpc] [11831.729348] ? lprocfs_counter_add+0x15b/0x210 [obdclass] [11831.731454] ptlrpc_main+0xd1e/0x1440 [ptlrpc] [11831.733368] ? ptlrpc_wait_event+0x980/0x980 [ptlrpc] [11831.735426] kthread+0x1d1/0x200 [11831.736435] ? set_kthread_struct+0x70/0x70 [11831.737671] ret_from_fork+0x1f/0x30 [11831.739022] ---[ end trace 062a11e1678f2cb8 ]--- [11831.772566] ODEBUG: object 0000000005ae3737 is on stack 00000000e0d77545, but NOT annotated. [11831.777108] WARNING: CPU: 3 PID: 171878 at lib/debugobjects.c:368 __debug_object_init.cold.5+0x35/0x15f [11831.781146] Modules linked in: lustre(O) osp(O) ofd(O) lod(O) mdt(O) mdd(O) mgs(O) osd_zfs(O) lquota(O) lfsck(O) mgc(O) mdc(O) lov(O) osc(O) lmv(O) fid(O) fld(O) ptlrpc_gss(O) ptlrpc(O) obdclass(O) ksocklnd(O) lnet(O) libcfs(O) zfs(O) spl(O) rpcsec_gss_krb5 auth_rpcgss nfsv4 dns_resolver intel_rapl_msr intel_rapl_common sb_edac rapl pcspkr i2c_piix4 squashfs crct10dif_pclmul crc32_pclmul ata_generic crc32c_intel ghash_clmulni_intel ata_piix serio_raw libata dm_mirror dm_region_hash dm_log dm_mod sha512_ssse3 sha512_generic [last unloaded: obdecho] [11831.799960] CPU: 3 PID: 171878 Comm: mdt00_000 Kdump: loaded Tainted: G W O -------- - - 4.18.0rh8.10-debug #2 [11831.803560] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.16.2-1.fc38 04/01/2014 [11831.807077] RIP: 0010:__debug_object_init.cold.5+0x35/0x15f [11831.808957] Code: be a9 48 83 05 23 61 0c 03 01 89 05 59 69 0c 03 65 48 8b 04 25 00 dd 01 00 48 8b 50 18 e8 93 68 99 ff 48 83 05 1b 61 0c 03 01 <0f> 0b 48 83 05 19 61 0c 03 01 48 83 05 19 61 0c 03 01 e9 3f ee ff [11831.814888] RSP: 0018:ffff9cfcc1d7b4a0 EFLAGS: 00010002 [11831.816504] RAX: 0000000000000050 RBX: ffff9cfcc1d7b5a8 RCX: 0000000000000000 [11831.818604] RDX: 0000000000000000 RSI: ffff91054219e5a8 RDI: ffff91054219e5a8 [11831.821271] RBP: ffffffffaa306ae0 R08: 0000000000000000 R09: c0000000ffff7fff [11831.823664] R10: 0000000000000001 R11: ffff9cfcc1d7b298 R12: ffffffffabb24c28 [11831.825570] R13: 0000000000037440 R14: ffffffffabb24c20 R15: ffff91051aadf578 [11831.827896] FS: 0000000000000000(0000) GS:ffff910542180000(0000) knlGS:0000000000000000 [11831.830280] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [11831.831860] CR2: 00007f69319a1000 CR3: 0000000083816005 CR4: 0000000000170ee0 [11831.833279] Call Trace: [11831.833691] ? show_regs.cold.9+0x22/0x2f [11831.834739] ? __warn+0xc8/0x150 [11831.835690] ? __debug_object_init.cold.5+0x35/0x15f [11831.837197] ? report_bug+0x113/0x140 [11831.838447] ? do_error_trap+0xb6/0x130 [11831.839555] ? do_invalid_op+0x46/0x60 [11831.840631] ? __debug_object_init.cold.5+0x35/0x15f [11831.842230] ? invalid_op+0x14/0x20 [11831.843462] ? __debug_object_init.cold.5+0x35/0x15f [11831.845019] ? lod_set_pool+0x280/0x280 [lod] [11831.846578] debug_object_init+0x22/0x30 [11831.847834] init_timer_key+0x28/0x120 [11831.848788] lod_ost_alloc_qos+0x79c/0x1b40 [lod] [11831.850300] ? slab_post_alloc_hook+0x66/0x380 [11831.851719] ? lod_qos_prep_create+0x39c/0x1c10 [lod] [11831.853111] ? __kmalloc+0x1b4/0x4a0 [11831.854323] lod_qos_prep_create+0x131a/0x1c10 [lod] [11831.856003] ? osd_declare_quota+0x39/0x730 [osd_zfs] [11831.857400] lod_prepare_create+0x204/0x460 [lod] [11831.859045] lod_declare_striped_create+0x270/0xf80 [lod] [11831.860500] ? lod_sub_declare_create+0x111/0x320 [lod] [11831.862460] lod_declare_create+0x3d4/0x9c0 [lod] [11831.863884] mdd_declare_create_object_internal+0x107/0x4a0 [mdd] [11831.865800] ? lod_alloc_comp_entries+0x2a7/0x660 [lod] [11831.867743] mdd_declare_create_object.isra.25+0x55/0xc40 [mdd] [11831.869494] mdd_declare_create+0x6a/0x6c0 [mdd] [11831.871932] mdd_create+0x5bd/0x1d00 [mdd] [11831.873403] ? mdt_version_save+0xa8/0x210 [mdt] [11831.875471] mdt_reint_open+0x337c/0x3c10 [mdt] [11831.877240] ? old_init_ucred_common+0x1ae/0x840 [mdt] [11831.879105] ? lustre_swab_generic_32s+0x20/0x20 [ptlrpc] [11831.880793] mdt_reint_rec+0x139/0x2b0 [mdt] [11831.881896] mdt_reint_internal+0x6a0/0xdc0 [mdt] [11831.884143] mdt_intent_open+0x180/0x5b0 [mdt] [11831.885979] mdt_intent_opc.constprop.44+0x153/0xfb0 [mdt] [11831.887540] ? mdt_intent_fixup_resent+0x2e0/0x2e0 [mdt] [11831.889791] mdt_intent_policy+0x14b/0x670 [mdt] [11831.891487] ldlm_lock_enqueue+0x43c/0xcd0 [ptlrpc] [11831.893017] ? _raw_read_unlock+0x12/0x30 [11831.893955] ? cfs_hash_rw_unlock+0x11/0x30 [obdclass] [11831.895265] ldlm_handle_enqueue+0x43f/0x2320 [ptlrpc] [11831.896770] tgt_enqueue+0xd0/0x300 [ptlrpc] [11831.898227] tgt_handle_request0+0x137/0xaf0 [ptlrpc] [11831.899660] tgt_request_handle+0x351/0x1c00 [ptlrpc] [11831.901386] ? obd_export_timed_fini+0xe8/0x110 [obdclass] [11831.902833] ptlrpc_server_handle_request+0x443/0x13b0 [ptlrpc] [11831.904673] ? lprocfs_counter_add+0x15b/0x210 [obdclass] [11831.906004] ptlrpc_main+0xd1e/0x1440 [ptlrpc] [11831.907903] ? ptlrpc_wait_event+0x980/0x980 [ptlrpc] [11831.909968] kthread+0x1d1/0x200 [11831.911117] ? set_kthread_struct+0x70/0x70 [11831.911928] ret_from_fork+0x1f/0x30 [11831.912929] ---[ end trace 062a11e1678f2cb9 ]--- [11831.924903] ODEBUG: object 00000000b0bbe2ea is on stack 0000000009fded93, but NOT annotated. [11831.927881] WARNING: CPU: 3 PID: 172407 at lib/debugobjects.c:368 __debug_object_init.cold.5+0x35/0x15f [11831.930870] Modules linked in: lustre(O) osp(O) ofd(O) lod(O) mdt(O) mdd(O) mgs(O) osd_zfs(O) lquota(O) lfsck(O) mgc(O) mdc(O) lov(O) osc(O) lmv(O) fid(O) fld(O) ptlrpc_gss(O) ptlrpc(O) obdclass(O) ksocklnd(O) lnet(O) libcfs(O) zfs(O) spl(O) rpcsec_gss_krb5 auth_rpcgss nfsv4 dns_resolver intel_rapl_msr intel_rapl_common sb_edac rapl pcspkr i2c_piix4 squashfs crct10dif_pclmul crc32_pclmul ata_generic crc32c_intel ghash_clmulni_intel ata_piix serio_raw libata dm_mirror dm_region_hash dm_log dm_mod sha512_ssse3 sha512_generic [last unloaded: obdecho] [11831.944697] CPU: 3 PID: 172407 Comm: mdt00_004 Kdump: loaded Tainted: G W O -------- - - 4.18.0rh8.10-debug #2 [11831.947535] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.16.2-1.fc38 04/01/2014 [11831.950157] RIP: 0010:__debug_object_init.cold.5+0x35/0x15f [11831.951540] Code: be a9 48 83 05 23 61 0c 03 01 89 05 59 69 0c 03 65 48 8b 04 25 00 dd 01 00 48 8b 50 18 e8 93 68 99 ff 48 83 05 1b 61 0c 03 01 <0f> 0b 48 83 05 19 61 0c 03 01 48 83 05 19 61 0c 03 01 e9 3f ee ff [11831.957712] RSP: 0018:ffff9cfcc2e574a0 EFLAGS: 00010006 [11831.959323] RAX: 0000000000000050 RBX: ffff9cfcc2e575a8 RCX: 0000000000000000 [11831.961649] RDX: 0000000000000000 RSI: ffff91054219e5a8 RDI: ffff91054219e5a8 [11831.963764] RBP: ffffffffaa306ae0 R08: 0000000000000000 R09: c0000000ffff7fff [11831.965505] R10: 0000000000000001 R11: ffff9cfcc2e57298 R12: ffffffffabb6d1e8 [11831.967601] R13: 000000000007fa00 R14: ffffffffabb6d1e0 R15: ffff91042ef7edc0 [11831.969818] FS: 0000000000000000(0000) GS:ffff910542180000(0000) knlGS:0000000000000000 [11831.971663] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [11831.973167] CR2: 00007f07416ea030 CR3: 0000000083816006 CR4: 0000000000170ee0 [11831.975509] Call Trace: [11831.976211] ? show_regs.cold.9+0x22/0x2f [11831.977059] ? __warn+0xc8/0x150 [11831.977633] ? __debug_object_init.cold.5+0x35/0x15f [11831.978525] ? report_bug+0x113/0x140 [11831.979771] ? do_error_trap+0xb6/0x130 [11831.980713] ? do_invalid_op+0x46/0x60 [11831.981675] ? __debug_object_init.cold.5+0x35/0x15f [11831.983270] ? invalid_op+0x14/0x20 [11831.984301] ? __debug_object_init.cold.5+0x35/0x15f [11831.985339] ? lod_set_pool+0x280/0x280 [lod] [11831.986741] debug_object_init+0x22/0x30 [11831.987941] init_timer_key+0x28/0x120 [11831.989191] lod_ost_alloc_qos+0x79c/0x1b40 [lod] [11831.990693] ? slab_post_alloc_hook+0x66/0x380 [11831.991788] ? lod_qos_prep_create+0x39c/0x1c10 [lod] [11831.993272] ? __kmalloc+0x1b4/0x4a0 [11831.994305] lod_qos_prep_create+0x131a/0x1c10 [lod] [11831.995621] ? osd_declare_quota+0x39/0x730 [osd_zfs] [11831.996954] lod_prepare_create+0x204/0x460 [lod] [11831.998460] lod_declare_striped_create+0x270/0xf80 [lod] [11831.999949] ? lod_sub_declare_create+0x111/0x320 [lod] [11832.000947] lod_declare_create+0x3d4/0x9c0 [lod] [11832.001922] mdd_declare_create_object_internal+0x107/0x4a0 [mdd] [11832.003612] ? lod_alloc_comp_entries+0x2a7/0x660 [lod] [11832.005028] mdd_declare_create_object.isra.25+0x55/0xc40 [mdd] [11832.006509] mdd_declare_create+0x6a/0x6c0 [mdd] [11832.007415] mdd_create+0x5bd/0x1d00 [mdd] [11832.008697] ? mdt_version_save+0xa8/0x210 [mdt] [11832.010201] mdt_reint_open+0x337c/0x3c10 [mdt] [11832.011508] ? old_init_ucred_common+0x1ae/0x840 [mdt] [11832.012939] ? lustre_swab_generic_32s+0x20/0x20 [ptlrpc] [11832.014932] mdt_reint_rec+0x139/0x2b0 [mdt] [11832.016339] mdt_reint_internal+0x6a0/0xdc0 [mdt] [11832.017955] mdt_intent_open+0x180/0x5b0 [mdt] [11832.019462] mdt_intent_opc.constprop.44+0x153/0xfb0 [mdt] [11832.020988] ? mdt_intent_fixup_resent+0x2e0/0x2e0 [mdt] [11832.022722] mdt_intent_policy+0x14b/0x670 [mdt] [11832.024208] ldlm_lock_enqueue+0x43c/0xcd0 [ptlrpc] [11832.026039] ? _raw_read_unlock+0x12/0x30 [11832.027142] ? cfs_hash_rw_unlock+0x11/0x30 [obdclass] [11832.028803] ldlm_handle_enqueue+0x43f/0x2320 [ptlrpc] [11832.030829] tgt_enqueue+0xd0/0x300 [ptlrpc] [11832.032420] tgt_handle_request0+0x137/0xaf0 [ptlrpc] [11832.034129] tgt_request_handle+0x351/0x1c00 [ptlrpc] [11832.036131] ? obd_export_timed_fini+0xe8/0x110 [obdclass] [11832.037893] ptlrpc_server_handle_request+0x443/0x13b0 [ptlrpc] [11832.040632] ? lprocfs_counter_add+0x15b/0x210 [obdclass] [11832.041928] ptlrpc_main+0xd1e/0x1440 [ptlrpc] [11832.043167] ? ptlrpc_wait_event+0x980/0x980 [ptlrpc] [11832.044483] kthread+0x1d1/0x200 [11832.045185] ? set_kthread_struct+0x70/0x70 [11832.046074] ret_from_fork+0x1f/0x30 [11832.046837] ---[ end trace 062a11e1678f2cba ]--- [11832.074919] ODEBUG: object 000000004183face is on stack 00000000d4638df3, but NOT annotated. [11832.079018] WARNING: CPU: 2 PID: 171879 at lib/debugobjects.c:368 __debug_object_init.cold.5+0x35/0x15f [11832.084114] Modules linked in: lustre(O) osp(O) ofd(O) lod(O) mdt(O) mdd(O) mgs(O) osd_zfs(O) lquota(O) lfsck(O) mgc(O) mdc(O) lov(O) osc(O) lmv(O) fid(O) fld(O) ptlrpc_gss(O) ptlrpc(O) obdclass(O) ksocklnd(O) lnet(O) libcfs(O) zfs(O) spl(O) rpcsec_gss_krb5 auth_rpcgss nfsv4 dns_resolver intel_rapl_msr intel_rapl_common sb_edac rapl pcspkr i2c_piix4 squashfs crct10dif_pclmul crc32_pclmul ata_generic crc32c_intel ghash_clmulni_intel ata_piix serio_raw libata dm_mirror dm_region_hash dm_log dm_mod sha512_ssse3 sha512_generic [last unloaded: obdecho] [11832.088433] ODEBUG: object 0000000053b0eac1 is on stack 00000000f358fee9, but NOT annotated. [11832.109250] CPU: 2 PID: 171879 Comm: mdt00_001 Kdump: loaded Tainted: G W O -------- - - 4.18.0rh8.10-debug #2 [11832.116227] WARNING: CPU: 1 PID: 172376 at lib/debugobjects.c:368 __debug_object_init.cold.5+0x35/0x15f [11832.121722] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.16.2-1.fc38 04/01/2014 [11832.127993] Modules linked in: lustre(O) osp(O) [11832.133066] RIP: 0010:__debug_object_init.cold.5+0x35/0x15f [11832.133081] ofd(O) [11832.133088] Code: be a9 48 83 05 23 61 0c 03 01 89 05 59 69 0c 03 65 48 8b 04 25 00 dd 01 00 48 8b 50 18 e8 93 68 99 ff 48 83 05 1b 61 0c 03 01 <0f> 0b 48 83 05 19 61 0c 03 01 48 83 05 19 61 0c 03 01 e9 3f ee ff [11832.135159] lod(O) [11832.138129] RSP: 0018:ffff9cfcc1cfb4a0 EFLAGS: 00010002 [11832.139378] mdt(O) [11832.148386] [11832.149202] mdd(O) [11832.152399] RAX: 0000000000000050 RBX: ffff9cfcc1cfb5a8 RCX: 0000000000000000 [11832.153663] mgs(O) [11832.154477] RDX: 0000000000000000 RSI: ffff91054211e5a8 RDI: ffff91054211e5a8 [11832.155470] osd_zfs(O) [11832.159195] RBP: ffffffffaa306ae0 R08: 0000000000000000 R09: c0000000ffff7fff [11832.161148] lquota(O) [11832.166016] R10: 0000000000000001 R11: ffff9cfcc1cfb298 R12: ffffffffabb32a08 [11832.166516] lfsck(O) [11832.169253] R13: 0000000000045220 R14: ffffffffabb32a00 R15: ffff910520780618 [11832.170230] mgc(O) [11832.172373] FS: 0000000000000000(0000) GS:ffff910542100000(0000) knlGS:0000000000000000 [11832.173098] mdc(O) [11832.175793] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [11832.177676] lov(O) [11832.180720] CR2: 00007f57d8e23030 CR3: 0000000083816004 CR4: 0000000000170ee0 [11832.181540] osc(O) [11832.184405] Call Trace: [11832.185515] lmv(O) [11832.187654] ? show_regs.cold.9+0x22/0x2f [11832.188795] fid(O) [11832.189511] ? __warn+0xc8/0x150 [11832.190427] fld(O) [11832.192668] ? __debug_object_init.cold.5+0x35/0x15f [11832.193623] ptlrpc_gss(O) [11832.195202] ? report_bug+0x113/0x140 [11832.195907] ptlrpc(O) [11832.198671] ? do_error_trap+0xb6/0x130 [11832.199471] obdclass(O) [11832.201815] ? do_invalid_op+0x46/0x60 [11832.202584] ksocklnd(O) [11832.204274] ? __debug_object_init.cold.5+0x35/0x15f [11832.204823] lnet(O) [11832.206798] ? invalid_op+0x14/0x20 [11832.208194] libcfs(O) [11832.210881] ? __debug_object_init.cold.5+0x35/0x15f [11832.212125] zfs(O) [11832.214430] ? lod_set_pool+0x280/0x280 [lod] [11832.215494] spl(O) [11832.217575] debug_object_init+0x22/0x30 [11832.218295] rpcsec_gss_krb5 [11832.219123] init_timer_key+0x28/0x120 [11832.219673] auth_rpcgss [11832.220494] lod_ost_alloc_qos+0x79c/0x1b40 [lod] [11832.221582] nfsv4 [11832.223516] ? mutex_spin_on_owner+0x7e/0x160 [11832.224727] dns_resolver [11832.226705] ? __mutex_lock.isra.10+0x315/0xec0 [11832.227538] intel_rapl_msr [11832.229804] ? slab_post_alloc_hook+0x66/0x380 [11832.231002] intel_rapl_common [11832.233342] ? lod_qos_prep_create+0x39c/0x1c10 [lod] [11832.234499] sb_edac [11832.236885] ? __kmalloc+0x1b4/0x4a0 [11832.238322] rapl [11832.241267] lod_qos_prep_create+0x131a/0x1c10 [lod] [11832.242299] pcspkr [11832.244218] ? osd_declare_quota+0x39/0x730 [osd_zfs] [11832.245302] i2c_piix4 [11832.247173] lod_prepare_create+0x204/0x460 [lod] [11832.248932] squashfs [11832.250688] lod_declare_striped_create+0x270/0xf80 [lod] [11832.251412] crct10dif_pclmul [11832.253086] ? lod_sub_declare_create+0x111/0x320 [lod] [11832.254227] crc32_pclmul [11832.257121] lod_declare_create+0x3d4/0x9c0 [lod] [11832.258864] ata_generic [11832.261862] mdd_declare_create_object_internal+0x107/0x4a0 [mdd] [11832.263614] crc32c_intel [11832.265643] ? lod_alloc_comp_entries+0x2a7/0x660 [lod] [11832.267343] ghash_clmulni_intel [11832.269868] mdd_declare_create_object.isra.25+0x55/0xc40 [mdd] [11832.271340] ata_piix [11832.272708] mdd_declare_create+0x6a/0x6c0 [mdd] [11832.274545] serio_raw [11832.277710] mdd_create+0x5bd/0x1d00 [mdd] [11832.278381] libata [11832.280894] ? mdt_version_save+0xa8/0x210 [mdt] [11832.282149] dm_mirror [11832.283934] mdt_reint_open+0x337c/0x3c10 [mdt] [11832.285580] dm_region_hash [11832.288242] ? old_init_ucred_common+0x1ae/0x840 [mdt] [11832.289162] dm_log [11832.291445] ? lustre_swab_generic_32s+0x20/0x20 [ptlrpc] [11832.292560] dm_mod [11832.294330] mdt_reint_rec+0x139/0x2b0 [mdt] [11832.295224] sha512_ssse3 [11832.298101] mdt_reint_internal+0x6a0/0xdc0 [mdt] [11832.299774] sha512_generic [11832.302455] mdt_intent_open+0x180/0x5b0 [mdt] [11832.303817] [last unloaded: obdecho] [11832.306909] mdt_intent_opc.constprop.44+0x153/0xfb0 [mdt] [11832.307992] [11832.310417] ? mdt_intent_fixup_resent+0x2e0/0x2e0 [mdt] [11832.312322] CPU: 1 PID: 172376 Comm: mdt00_003 Kdump: loaded Tainted: G W O -------- - - 4.18.0rh8.10-debug #2 [11832.315101] mdt_intent_policy+0x14b/0x670 [mdt] [11832.315575] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.16.2-1.fc38 04/01/2014 [11832.318713] ldlm_lock_enqueue+0x43c/0xcd0 [ptlrpc] [11832.323363] RIP: 0010:__debug_object_init.cold.5+0x35/0x15f [11832.324567] ? _raw_read_unlock+0x12/0x30 [11832.328380] Code: be a9 48 83 05 23 61 0c 03 01 89 05 59 69 0c 03 65 48 8b 04 25 00 dd 01 00 48 8b 50 18 e8 93 68 99 ff 48 83 05 1b 61 0c 03 01 <0f> 0b 48 83 05 19 61 0c 03 01 48 83 05 19 61 0c 03 01 e9 3f ee ff [11832.330307] ? cfs_hash_rw_unlock+0x11/0x30 [obdclass] [11832.333102] RSP: 0018:ffff9cfcc2c974a0 EFLAGS: 00010006 [11832.335262] ldlm_handle_enqueue+0x43f/0x2320 [ptlrpc] [11832.345480] [11832.348040] tgt_enqueue+0xd0/0x300 [ptlrpc] [11832.350899] RAX: 0000000000000050 RBX: ffff9cfcc2c975a8 RCX: 0000000000000000 [11832.353968] tgt_handle_request0+0x137/0xaf0 [ptlrpc] [11832.355027] RDX: 0000000000000000 RSI: ffff91054209e5a8 RDI: ffff91054209e5a8 [11832.357876] tgt_request_handle+0x351/0x1c00 [ptlrpc] [11832.361378] RBP: ffffffffaa306ae0 R08: 30207463656a626f R09: 203a47554245444f [11832.362800] ? obd_export_timed_fini+0xe8/0x110 [obdclass] [11832.365272] R10: 30207463656a626f R11: 203a47554245444f R12: ffffffffabb5da88 [11832.367169] ptlrpc_server_handle_request+0x443/0x13b0 [ptlrpc] [11832.371880] R13: 00000000000702a0 R14: ffffffffabb5da80 R15: ffff9104379f1ac8 [11832.374577] ? lprocfs_counter_add+0x15b/0x210 [obdclass] [11832.378501] FS: 0000000000000000(0000) GS:ffff910542080000(0000) knlGS:0000000000000000 [11832.381370] ptlrpc_main+0xd1e/0x1440 [ptlrpc] [11832.384886] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [11832.387333] ? ptlrpc_wait_event+0x980/0x980 [ptlrpc] [11832.391902] CR2: 00007f693199c000 CR3: 0000000083816002 CR4: 0000000000170ee0 [11832.394019] kthread+0x1d1/0x200 [11832.395992] Call Trace: [11832.397657] ? set_kthread_struct+0x70/0x70 [11832.401862] ? show_regs.cold.9+0x22/0x2f [11832.403152] ret_from_fork+0x1f/0x30 [11832.404251] ? __warn+0xc8/0x150 [11832.406490] ---[ end trace 062a11e1678f2cbb ]--- [11832.408314] ? __debug_object_init.cold.5+0x35/0x15f [11832.416056] ? report_bug+0x113/0x140 [11832.418288] ? do_error_trap+0xb6/0x130 [11832.419277] ? do_invalid_op+0x46/0x60 [11832.420678] ? __debug_object_init.cold.5+0x35/0x15f [11832.422861] ? invalid_op+0x14/0x20 [11832.424626] ? __debug_object_init.cold.5+0x35/0x15f [11832.426911] ? lod_set_pool+0x280/0x280 [lod] [11832.429697] debug_object_init+0x22/0x30 [11832.432403] init_timer_key+0x28/0x120 [11832.436341] lod_ost_alloc_qos+0x79c/0x1b40 [lod] [11832.439595] ? slab_post_alloc_hook+0x66/0x380 [11832.442088] ? lod_qos_prep_create+0x39c/0x1c10 [lod] [11832.445208] ? __kmalloc+0x1b4/0x4a0 [11832.447053] lod_qos_prep_create+0x131a/0x1c10 [lod] [11832.450496] ? osd_declare_quota+0x39/0x730 [osd_zfs] [11832.453498] lod_prepare_create+0x204/0x460 [lod] [11832.456851] lod_declare_striped_create+0x270/0xf80 [lod] [11832.458603] ? lod_sub_declare_create+0x111/0x320 [lod] [11832.461092] lod_declare_create+0x3d4/0x9c0 [lod] [11832.463939] mdd_declare_create_object_internal+0x107/0x4a0 [mdd] [11832.468998] ? lod_alloc_comp_entries+0x2a7/0x660 [lod] [11832.473608] mdd_declare_create_object.isra.25+0x55/0xc40 [mdd] [11832.476967] mdd_declare_create+0x6a/0x6c0 [mdd] [11832.481628] mdd_create+0x5bd/0x1d00 [mdd] [11832.484332] ? mdt_version_save+0xa8/0x210 [mdt] [11832.487115] mdt_reint_open+0x337c/0x3c10 [mdt] [11832.489754] ? old_init_ucred_common+0x1ae/0x840 [mdt] [11832.492698] ? lustre_swab_generic_32s+0x20/0x20 [ptlrpc] [11832.496094] mdt_reint_rec+0x139/0x2b0 [mdt] [11832.498554] mdt_reint_internal+0x6a0/0xdc0 [mdt] [11832.500732] mdt_intent_open+0x180/0x5b0 [mdt] [11832.503434] mdt_intent_opc.constprop.44+0x153/0xfb0 [mdt] [11832.507200] ? mdt_intent_fixup_resent+0x2e0/0x2e0 [mdt] [11832.509503] mdt_intent_policy+0x14b/0x670 [mdt] [11832.511915] ldlm_lock_enqueue+0x43c/0xcd0 [ptlrpc] [11832.515354] ? _raw_read_unlock+0x12/0x30 [11832.517558] ? cfs_hash_rw_unlock+0x11/0x30 [obdclass] [11832.521470] ldlm_handle_enqueue+0x43f/0x2320 [ptlrpc] [11832.525691] tgt_enqueue+0xd0/0x300 [ptlrpc] [11832.528627] tgt_handle_request0+0x137/0xaf0 [ptlrpc] [11832.533016] tgt_request_handle+0x351/0x1c00 [ptlrpc] [11832.536553] ? obd_export_timed_fini+0xe8/0x110 [obdclass] [11832.540497] ptlrpc_server_handle_request+0x443/0x13b0 [ptlrpc] [11832.544482] ? lprocfs_counter_add+0x15b/0x210 [obdclass] [11832.547503] ptlrpc_main+0xd1e/0x1440 [ptlrpc] [11832.551986] ? ptlrpc_wait_event+0x980/0x980 [ptlrpc] [11832.555944] kthread+0x1d1/0x200 [11832.558284] ? set_kthread_struct+0x70/0x70 [11832.561059] ret_from_fork+0x1f/0x30 [11832.563900] ---[ end trace 062a11e1678f2cbc ]--- [11857.900387] Lustre: DEBUG MARKER: == sanity test 182b: Test parallel modify metadata operations from osp ========================================================== 06:11:36 (1753438296) [11858.553482] Lustre: DEBUG MARKER: SKIP: sanity test_182b needs >= 2 MDTs [11859.248487] Lustre: DEBUG MARKER: == sanity test 183: No crash or request leak in case of strange dispositions ================================================================== 06:11:37 (1753438297) [11859.769060] Lustre: *** cfs_fail_loc=148, val=0*** [11862.628184] Lustre: DEBUG MARKER: == sanity test 184a: Basic layout swap =================== 06:11:41 (1753438301) [11866.912574] Lustre: DEBUG MARKER: == sanity test 184b: Forbidden layout swap (will generate errors) ========================================================== 06:11:45 (1753438305) [11869.859916] Lustre: DEBUG MARKER: == sanity test 184c: Concurrent write and layout swap ==== 06:11:48 (1753438308) [11888.737830] Lustre: DEBUG MARKER: == sanity test 184d: allow stripeless layouts swap ======= 06:12:07 (1753438327) [11892.651811] Lustre: DEBUG MARKER: == sanity test 184e: Recreate layout after stripeless layout swaps ========================================================== 06:12:11 (1753438331) [11896.398548] Lustre: DEBUG MARKER: == sanity test 184f: IOC_MDC_GETFILEINFO for files with long names but no striping ========================================================== 06:12:14 (1753438334) [11899.076337] Lustre: DEBUG MARKER: == sanity test 185: Volatile file support ================ 06:12:17 (1753438337) [11902.944831] Lustre: DEBUG MARKER: == sanity test 185a: Volatile file creation in .lustre/fid/ ========================================================== 06:12:21 (1753438341) [11907.877893] Lustre: DEBUG MARKER: == sanity test 187a: Test data version change ============ 06:12:26 (1753438346) [11911.749826] Lustre: DEBUG MARKER: == sanity test 187b: Test data version change on volatile file ========================================================== 06:12:30 (1753438350) [11918.109924] Lustre: DEBUG MARKER: == sanity test complete, duration 11761 sec ============== 06:12:36 (1753438356) [11918.840808] Lustre: DEBUG MARKER: === sanity: start cleanup 06:12:37 (1753438357) === [11937.695733] Lustre: DEBUG MARKER: === sanity: finish cleanup 06:12:56 (1753438376) === [11943.393891] Lustre: lustre-MDT0000-lwp-OST0000: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [11943.394744] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [11943.398866] Lustre: Skipped 1 previous similar message [11943.402865] Lustre: Skipped 1 previous similar message [11945.109323] LustreError: 207194:0:(obd_class.h:479:obd_check_dev()) Device 9 not setup [11945.113296] LustreError: 207194:0:(obd_class.h:479:obd_check_dev()) Skipped 1 previous similar message [11945.220320] Lustre: server umount lustre-MDT0000 complete [11947.001347] LustreError: 150133:0:(ldlm_lockd.c:2550:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1753438386 with bad export cookie 6795403068769736165 [11947.003378] LustreError: MGC192.168.202.144@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [11947.005919] LustreError: 150133:0:(ldlm_lockd.c:2550:ldlm_cancel_handler()) Skipped 2 previous similar messages [11947.050369] Lustre: server umount lustre-OST0000 complete [11948.742413] Lustre: server umount lustre-OST0001 complete [11954.452700] Lustre: DEBUG MARKER: oleg244-server.virtnet: executing unload_modules_local [11955.606692] Key type lgssc unregistered [11955.738472] LNet: 208162:0:(lib-ptl.c:966:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [11956.773706] LNet: Removed LNI 192.168.202.144@tcp [11957.065739] Key type .llcrypt unregistered [11957.066867] Key type ._llcrypt unregistered