[ 0.000000] Linux version 4.18.0rh8.10-debug (green@maintenance) (gcc version 8.5.0 20210514 (Red Hat 8.5.0-26) (GCC)) #2 SMP Mon Jul 14 01:24:22 EDT 2025 [ 0.000000] Command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers' [ 0.000000] x86/fpu: xstate_offset[2]: 576, xstate_sizes[2]: 256 [ 0.000000] x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'standard' format. [ 0.000000] signal: max sigframe size: 1776 [ 0.000000] BIOS-provided physical RAM map: [ 0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable [ 0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000000100000-0x00000000bffcdfff] usable [ 0.000000] BIOS-e820: [mem 0x00000000bffce000-0x00000000bfffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000100000000-0x0000000146dfffff] usable [ 0.000000] NX (Execute Disable) protection: active [ 0.000000] SMBIOS 2.8 present. [ 0.000000] DMI: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.17.0-10.fc44 06/10/2025 [ 0.000000] Hypervisor detected: KVM [ 0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00 [ 0.000000] kvm-clock: using sched offset of 1027597275 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 0x000f54b0-0x000f54bf] [ 0.000000] RAMDISK: [mem 0xbcc54000-0xbffbffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F52D0 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE247C 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE2318 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 0022D8 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE238C 000090 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE241C 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE2454 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe2318-0xbffe238b] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe2317] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe238c-0xbffe241b] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe241c-0xbffe2453] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe2454-0xbffe247b] [ 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: 2895240K/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.001012] APIC: Switch to symmetric I/O mode setup [ 0.002403] x2apic enabled [ 0.003008] Switched APIC routing to physical x2apic. [ 0.004014] kvm-guest: setup PV IPIs [ 0.007000] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.007000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.007017] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.008000] pid_max: default: 32768 minimum: 301 [ 0.008040] LSM: Security Framework initializing [ 0.009038] Yama: becoming mindful. [ 0.010027] SELinux: Initializing. [ 0.011051] *** VALIDATE selinux *** [ 0.018646] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.023211] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.025105] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.026103] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.027096] *** VALIDATE tmpfs *** [ 0.029046] *** VALIDATE proc *** [ 0.029927] *** VALIDATE cgroup *** [ 0.030009] *** VALIDATE cgroup2 *** [ 0.031255] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.032141] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.033005] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.034026] Spectre V2 : User space: Vulnerable [ 0.035007] Speculative Store Bypass: Vulnerable [ 0.038360] debug: unmapping init [mem 0xffffffff95a59000-0xffffffff95a60fff] [ 0.040889] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.041845] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.042026] ... version: 2 [ 0.042935] ... bit width: 48 [ 0.043013] ... generic registers: 4 [ 0.043832] ... value mask: 0000ffffffffffff [ 0.044010] ... max period: 00007fffffffffff [ 0.045008] ... fixed-purpose events: 3 [ 0.045818] ... event mask: 000000070000000f [ 0.046280] rcu: Hierarchical SRCU implementation. [ 0.048465] smp: Bringing up secondary CPUs ... [ 0.049521] x86: Booting SMP configuration: [ 0.050020] .... node #0, CPUs: #1 #2 #3 [ 0.053248] smp: Brought up 1 node, 4 CPUs [ 0.054861] smpboot: Max logical packages: 1 [ 0.055012] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.138709] node 0 deferred pages initialised in 79ms [ 0.141255] devtmpfs: initialized [ 0.142274] x86/mm: Memory block size: 128MB [ 0.145838] gcov: version magic: 0x41383552 [ 0.147158] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.151101] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.152311] pinctrl core: initialized pinctrl subsystem [ 0.154153] [ 0.154590] ************************************************************* [ 0.156012] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.158012] ** ** [ 0.160010] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.162010] ** ** [ 0.164010] ** This means that this kernel is built to expose internal ** [ 0.165008] ** IOMMU data structures, which may compromise security on ** [ 0.167008] ** your system. ** [ 0.168009] ** ** [ 0.170011] ** If you see this message and you are not debugging the ** [ 0.171007] ** kernel, report this immediately to your vendor! ** [ 0.173006] ** ** [ 0.174010] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.175008] ************************************************************* [ 0.177778] NET: Registered protocol family 16 [ 0.179469] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.181041] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.184084] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.188097] cpuidle: using governor menu [ 0.189921] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.192828] PCI: Using configuration type 1 for base access [ 0.196113] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.206058] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.209024] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.213148] cryptd: max_cpu_qlen set to 1000 [ 0.215250] ACPI: Added _OSI(Module Device) [ 0.216012] ACPI: Added _OSI(Processor Device) [ 0.217014] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.218020] ACPI: Added _OSI(Processor Aggregator Device) [ 0.223224] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.228469] ACPI: Interpreter enabled [ 0.229981] ACPI: PM: (supports S0 S3 S4 S5) [ 0.231013] ACPI: Using IOAPIC for interrupt routing [ 0.233281] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.235534] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.246940] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.249100] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.251025] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.253072] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.259082] acpiphp: Slot [2] registered [ 0.261122] acpiphp: Slot [5] registered [ 0.262143] acpiphp: Slot [6] registered [ 0.263120] acpiphp: Slot [7] registered [ 0.265097] acpiphp: Slot [8] registered [ 0.266098] acpiphp: Slot [9] registered [ 0.267094] acpiphp: Slot [10] registered [ 0.269140] acpiphp: Slot [3] registered [ 0.270075] acpiphp: Slot [4] registered [ 0.272082] acpiphp: Slot [11] registered [ 0.273255] acpiphp: Slot [12] registered [ 0.274081] acpiphp: Slot [13] registered [ 0.276079] acpiphp: Slot [14] registered [ 0.277196] acpiphp: Slot [15] registered [ 0.278107] acpiphp: Slot [16] registered [ 0.279090] acpiphp: Slot [17] registered [ 0.280105] acpiphp: Slot [18] registered [ 0.281095] acpiphp: Slot [19] registered [ 0.282094] acpiphp: Slot [20] registered [ 0.283075] acpiphp: Slot [21] registered [ 0.285077] acpiphp: Slot [22] registered [ 0.286071] acpiphp: Slot [23] registered [ 0.288122] acpiphp: Slot [24] registered [ 0.289072] acpiphp: Slot [25] registered [ 0.290095] acpiphp: Slot [26] registered [ 0.291080] acpiphp: Slot [27] registered [ 0.292078] acpiphp: Slot [28] registered [ 0.293095] acpiphp: Slot [29] registered [ 0.294090] acpiphp: Slot [30] registered [ 0.295130] acpiphp: Slot [31] registered [ 0.296067] PCI host bridge to bus 0000:00 [ 0.297013] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.299027] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.301022] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.303017] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.304016] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.306081] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.308216] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.311043] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.314000] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.325749] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.330354] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.332017] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.335016] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.337012] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.339594] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.342811] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.345036] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.347837] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.355015] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.369019] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.376020] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.383987] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.390016] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.397018] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.422020] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.437812] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.452016] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.467017] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.491016] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.504465] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.511016] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.519017] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.539020] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.547840] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.555015] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.564013] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.582017] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.595028] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.606016] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.612017] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.631062] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 0.640227] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.646018] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.654017] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.674020] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 0.689080] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.692377] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.694675] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.697561] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.699254] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.707037] iommu: Default domain type: Passthrough [ 0.709481] SCSI subsystem initialized [ 0.711172] ACPI: bus type USB registered [ 0.712083] usbcore: registered new interface driver usbfs [ 0.714270] usbcore: registered new interface driver hub [ 0.718109] usbcore: registered new device driver usb [ 0.720144] pps_core: LinuxPPS API ver. 1 registered [ 0.721006] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.724049] PTP clock support registered [ 0.726068] EDAC MC: Ver: 3.0.0 [ 0.727206] PCI: Using ACPI for IRQ routing [ 0.731093] NetLabel: Initializing [ 0.732010] NetLabel: domain hash size = 128 [ 0.734015] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.737151] NetLabel: unlabeled traffic allowed by default [ 0.739311] vgaarb: loaded [ 0.742051] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.743011] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.752705] clocksource: Switched to clocksource kvm-clock [ 0.881192] VFS: Disk quotas dquot_6.6.0 [ 0.883794] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.887272] *** VALIDATE ramfs *** [ 0.889141] *** VALIDATE hugetlbfs *** [ 0.891610] pnp: PnP ACPI init [ 0.895168] pnp: PnP ACPI: found 6 devices [ 0.913319] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.917733] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.920706] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.923276] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.926165] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.928291] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.930590] NET: Registered protocol family 2 [ 0.932950] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.937429] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.941188] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.949732] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.953495] TCP: Hash tables configured (established 65536 bind 65536) [ 0.956721] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.960199] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.962750] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.965643] NET: Registered protocol family 1 [ 0.968703] RPC: Registered named UNIX socket transport module. [ 0.971192] RPC: Registered udp transport module. [ 0.973253] RPC: Registered tcp transport module. [ 0.975622] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.978232] NET: Registered protocol family 44 [ 0.980341] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.982881] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.985575] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.987995] PCI: CLS 0 bytes, default 64 [ 0.989952] Unpacking initramfs... [ 2.402785] debug: unmapping init [mem 0xffff9d653cc54000-0xffff9d653ffbffff] [ 2.406982] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.408797] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.410894] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 2.980283] Initialise system trusted keyrings [ 2.981898] Key type blacklist registered [ 2.983422] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.999739] zbud: loaded [ 3.007059] *** VALIDATE nfs *** [ 3.007953] *** VALIDATE nfs4 *** [ 3.009230] pstore: using deflate compression [ 3.012651] Platform Keyring initialized [ 3.137286] NET: Registered protocol family 38 [ 3.138823] Key type asymmetric registered [ 3.140286] Asymmetric key parser 'x509' registered [ 3.141662] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 3.144165] io scheduler mq-deadline registered [ 3.145428] io scheduler kyber registered [ 3.146881] io scheduler bfq registered [ 3.148573] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 3.151110] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 3.153658] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 3.156319] ACPI: Power Button [PWRF] [ 3.161835] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 3.168753] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 3.207303] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 3.232850] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 3.301645] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 3.329311] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.357313] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.364912] Non-volatile memory driver v1.3 [ 3.365921] Linux agpgart interface v0.103 [ 3.400302] virtio_blk virtio1: [vda] 145808 512-byte logical blocks (74.7 MB/71.2 MiB) [ 3.402174] vda: detected capacity change from 0 to 74653696 [ 3.444888] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.446823] vdb: detected capacity change from 0 to 1073741824 [ 3.472611] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.475410] vdc: detected capacity change from 0 to 2621440000 [ 3.488875] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.491129] vdd: detected capacity change from 0 to 2621440000 [ 3.508050] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.509804] vde: detected capacity change from 0 to 4294967296 [ 3.523246] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.525225] vdf: detected capacity change from 0 to 4294967296 [ 3.531747] libphy: Fixed MDIO Bus: probed [ 3.538727] usbcore: registered new interface driver usbserial_generic [ 3.540154] usbserial: USB Serial support registered for generic [ 3.541553] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.545731] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.547034] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.548844] mousedev: PS/2 mouse device common for all mice [ 3.551455] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.553330] rtc_cmos 00:05: RTC can wake from S4 [ 3.557119] rtc_cmos 00:05: registered as rtc0 [ 3.558248] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.560701] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.562680] intel_pstate: CPU model not supported [ 3.567290] hid: raw HID events driver (C) Jiri Kosina [ 3.568561] usbcore: registered new interface driver usbhid [ 3.570108] usbhid: USB HID core driver [ 3.571191] drop_monitor: Initializing network drop monitor service [ 3.573108] Initializing XFRM netlink socket [ 3.574504] NET: Registered protocol family 10 [ 3.576962] Segment Routing with IPv6 [ 3.577898] NET: Registered protocol family 17 [ 3.579333] mpls_gso: MPLS GSO support [ 3.582620] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.589145] RAS: Correctable Errors collector initialized. [ 3.590679] AVX version of gcm_enc/dec engaged. [ 3.591981] AES CTR mode by8 optimization enabled [ 3.676657] sched_clock: Marking stable (3676584502, 0)->(4524214557, -847630055) [ 3.679643] registered taskstats version 1 [ 3.681325] Loading compiled-in X.509 certificates [ 3.683144] zswap: loaded using pool lzo/zbud [ 3.708728] Key type big_key registered [ 3.720754] Key type encrypted registered [ 3.722204] ima: No TPM chip found, activating TPM-bypass! [ 3.723726] ima: Allocated hash algorithm: sha1 [ 3.724853] ima: No architecture policies found [ 3.725943] evm: Initialising EVM extended attributes: [ 3.727220] evm: security.selinux [ 3.728228] evm: security.ima [ 3.728864] evm: security.capability [ 3.729673] evm: HMAC attrs: 0x1 [ 3.732174] rtc_cmos 00:05: setting system clock to 2026-07-13 12:41:35 UTC (1783946495) [ 3.737484] debug: unmapping init [mem 0xffffffff96a03000-0xffffffff96bfffff] [ 3.739544] debug: unmapping init [mem 0xffffffff95782000-0xffffffff95a58fff] [ 3.748073] Write protecting the kernel read-only data: 28672k [ 3.750773] debug: unmapping init [mem 0xffffffff93e03000-0xffffffff93ffffff] [ 3.752625] debug: unmapping init [mem 0xffffffff94714000-0xffffffff947fffff] [ 3.784227] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 3.789787] systemd[1]: Detected virtualization kvm. [ 3.790988] systemd[1]: Detected architecture x86-64. [ 3.792320] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.813975] systemd[1]: No hostname configured. [ 3.815043] systemd[1]: Set hostname to . [ 3.816356] random: systemd: uninitialized urandom read (16 bytes read) [ 3.818040] systemd[1]: Initializing machine ID from random generator. [ 3.960041] random: systemd: uninitialized urandom read (16 bytes read) [ 3.961898] systemd[1]: Reached target Swap. [ OK ] Reached target Swap. [ 3.965808] random: systemd: uninitialized urandom read (16 bytes read) [ 3.967836] systemd[1]: Listening on udev Control Socket. [ OK ] Listening on udev Control Socket. [ 3.971278] systemd[1]: Reached target Local File Systems. [ OK ] Reached target Local File Systems. [ OK ] Listening on udev Kernel Socket. [ OK ] Listening on Journal Socket. [ OK ] Started Memstrack Anylazing Service. Starting Create Volatile Files and Directories... Starting Setup Virtual Console... [ OK ] Listening on Journal Socket (/dev/log). [ OK ] Reached target Sockets. Starting Journal Service... [ OK ] Reached target Timers. [ OK ] Reached target Slices. Starting Create list of required st…ce nodes for the current kernel... Starting Apply Kernel Variables... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. [ OK ] Reached target Initrd Root Device. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Setup Virtual Console. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Apply Kernel Variables. Starting Create Static Device Nodes in /dev... Starting dracut cmdline hook... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started Journal Service. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 4.806719] device-mapper: uevent: version 1.0.3 [ 4.809190] 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 ] Started udev Coldplug all Devices. [ 5.916397] virtio_net virtio0 ens2: renamed from eth0 [ 5.925428] random: fast init done [ OK ] Mounted Kernel Configuration File System. [ OK ] Reached target System Initialization. [ 5.972849] scsi host0: ata_piix [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting dracut initqueue hook... [ 6.104975] scsi host1: ata_piix [ 6.106536] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 6.110615] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 10.309225] dracut-initqueue[568]: RTNETLINK answers: File exists [ 11.234260] random: crng init done [ 11.235592] random: 7 urandom warning(s) missed due to ratelimiting Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Mounting /sysroot... [ 12.378984] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped target Timers. [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped target Basic System. [ OK ] Stopped target Slices. [ OK ] Stopped target Sockets. [ OK ] Stopped target Paths. [ OK ] Stopped target System Initialization. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped target Local File Systems. [ OK ] Stopped target Swap. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. Stopping udev Kernel Device Manager... [ 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.862302] printk: systemd: 26 output lines suppressed due to ratelimiting [ 14.183104] SELinux: Disabled at runtime. [ 14.288217] 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) [ 14.293134] systemd[1]: Detected virtualization kvm. [ 14.294310] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 14.967857] systemd[1]: initrd-switch-root.service: Succeeded. [ 14.972463] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 14.977728] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 14.980736] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 14.984774] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 14.996643] systemd[1]: Starting Journal Service... Starting Journal Service... [ 15.005382] systemd[1]: Mounting Huge Pages File System... Mounting Huge Pages File System... Activating swap /dev/disk/by-label/SWAP... [ OK ] Listening on Process Core Dump Socket. [ OK ] Stopped target Switch Root. [ 15.051308] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS [ OK ] Stopped target Initrd Root File System. [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Reached target RPC Port Mapper. [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. Starting Apply Kernel Variables... Mounting Kernel Debug File System... [ OK ] Listening on udev Control Socket. [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Listening on udev Kernel Socket. Starting udev Coldplug all Devices... Starting Create list of required st…ce nodes for the current kernel... [ OK ] Created slice User and Session Slice. [ OK ] Reached target Slices. Starting Remount Root and Kernel File Systems... [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Created slice system-getty.slice. [ OK ] Reached target rpc_pipefs.target. [ OK ] Created slice system-sshd\x2dkeygen.slice. Mounting POSIX Message Queue File System... [ OK ] Stopped target Initrd File Systems. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. [ OK ] Started Journal Service. [ OK ] Mounted Huge Pages File System. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Started Apply Kernel Variables. [ OK ] Mounted Kernel Debug File System. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Mounted POSIX Message Queue File System. Starting Configure read-only root support... Starting Create Static Device Nodes in /dev... [ OK ] Reached target Swap. Starting Flush Journal to Persistent Storage... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started udev Coldplug all Devices. [ OK ] Started Create Static Device Nodes in /dev. Starting udev Kernel Device Manager... [ OK ] Reached target Local File Systems (Pre). Mounting /home/green/git/lustre-release... Mounting /mnt... [ OK ] Mounted /mnt. [ 15.702583] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 16.606619] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 16.619504] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 16.695390] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 16.724245] EDAC sbridge: Ver: 1.1.2 [ 18.994378] Key type dns_resolver registered [ 19.331548] NFS: Registering the id_resolver key type [ 19.333330] Key type id_resolver registered [ 19.334358] Key type id_legacy registered [ OK ] Started Configure read-only root support. [ OK ] Reached target Local File Systems. Starting Mark the need to relabel after reboot... Starting Rebuild Dynamic Linker Cache... Starting Create Volatile Files and Directories... Starting Load/Save Random Seed... [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Load/Save Random Seed. [ OK ] Started Create Volatile Files and Directories. Starting 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 update of the root trust anchor for DNSSEC. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Started dnf makecache --timer. [ OK ] Reached target Timers. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. Starting Login Service... [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Started irqbalance daemon. [ OK ] Reached target sshd-keygen.target. [ OK ] Started D-Bus System Message Bus. Starting Network Manager... Starting Restore /run/initramfs on shutdown... [ 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 GSSAPI Proxy Daemon... Starting Dynamic System Tuning Daemon... Starting OpenSSH server daemon... Starting Hostname Service... [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... [ OK ] Started Permit User Sessions. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Serial Getty on ttyS1. [ OK ] Started Getty on tty1. [ OK ] Reached target Login Prompts. [ OK ] Started Command Scheduler. [ OK ] Started OpenSSH server daemon. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting System Logging Service... Starting Notify NFS peers of a restart... Starting Crash recovery kernel arming... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Starting Authorization Manager... [ OK ] Started Authorization Manager. [ OK ] Started Dynamic System Tuning Daemon. [ OK ] Reached target Multi-User System. [ OK ] Reached target Graphical Interface. Starting Update UTMP about System Runlevel Changes... [ OK ] Started Update UTMP about System Runlevel Changes. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg452-server login: [ 60.327192] libcfs: loading out-of-tree module taints kernel. [ 60.420829] Key type ._llcrypt registered [ 60.423524] Key type .llcrypt registered [ 60.607386] Lustre: DEBUG MARKER: oleg452-server.virtnet: executing set_hostid [ 82.942515] Lustre: DEBUG MARKER: oleg452-server.virtnet: executing load_modules_local [ 84.665384] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 84.704272] alg: No test for adler32 (adler32-zlib) [ 86.532513] Lustre: Lustre: Build Version: 2.17.54_162_ga4ac164 [ 88.526195] LNet: Added LNI 192.168.204.152@tcp [8/256/0/180] [ 90.799268] Key type lgssc registered [ 92.208266] hrtimer: interrupt took 6249975 ns [ 94.019087] Lustre: Echo OBD driver; http://www.lustre.org/ [ 115.912451] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 149.250567] Lustre: DEBUG MARKER: oleg452-server.virtnet: executing load_modules_local [ 166.529661] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 166.559785] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 167.894923] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 167.938246] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 168.030309] Lustre: lustre-MDT0000: new disk, initializing [ 168.165233] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 168.202881] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 173.965949] Lustre: DEBUG MARKER: oleg452-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 179.610130] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 193.067294] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 193.547877] Lustre: lustre-OST0000: new disk, initializing [ 193.565618] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 193.571791] Lustre: Skipped 1 previous similar message [ 193.581190] Lustre: 6944:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 193.693561] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 199.732710] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:0:ost [ 199.750417] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:0:ost] [ 199.804281] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x240000400 [ 199.950161] Lustre: DEBUG MARKER: oleg452-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 215.873705] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 215.943339] Lustre: lustre-OST0001: new disk, initializing [ 215.945865] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 215.951260] Lustre: 8011:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 215.976692] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 222.956312] Lustre: DEBUG MARKER: oleg452-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 224.862996] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:1:ost [ 224.873251] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:1:ost] [ 224.904407] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x280000400 [ 234.708167] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 242.022112] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 249.325851] Lustre: DEBUG MARKER: oleg452-server.virtnet: executing check_logdir /tmp/testlogs/ [ 255.043313] Lustre: DEBUG MARKER: oleg452-server.virtnet: executing yml_node [ 261.156481] Lustre: DEBUG MARKER: Client: 2.17.54.162 [ 263.972108] Lustre: DEBUG MARKER: MDS: 2.17.54.162 [ 266.451751] Lustre: DEBUG MARKER: OSS: 2.17.54.162 [ 268.262017] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity ============----- Mon Jul 13 08:45:58 EDT 2026 [ 287.729374] Lustre: DEBUG MARKER: - need MDS1_VERSION <= 2.16.61-1-g89cf292a8c2 (34682530 <= 34618625) for LU-18938, skip 360 [ 289.597354] Lustre: DEBUG MARKER: - need MDS1_VERSION < v2_14_55-100-g8a84c7f9c7 (34682530 < 34486116) for LU-14927, skip 0f [ 291.403724] Lustre: DEBUG MARKER: - need OST1_VERSION < v2_17_50-410-gbd8e7b9555 (34682530 < 34681754) for LU-12550, skip 216 [ 293.319475] Lustre: DEBUG MARKER: excepting tests: 42a 42c 42b 118c 118d 407 119i 216 817 411a [ 295.103254] Lustre: DEBUG MARKER: skipping tests SLOW=no: 27m 60i 64b 68 71 135 136 230d 300o 842 51c 51e 834 [ 296.936582] Lustre: DEBUG MARKER: === sanity: start setup 08:46:26 (1783946786) === [ 303.620800] Lustre: DEBUG MARKER: oleg452-client.virtnet: executing check_config_client /mnt/lustre [ 321.603060] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 325.450956] Lustre: 11853:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 329.006387] Lustre: DEBUG MARKER: oleg452-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 334.670310] Lustre: DEBUG MARKER: === sanity: finish setup 08:47:04 (1783946824) === [ 341.826689] Lustre: DEBUG MARKER: == sanity test 60a: llog_test run from kernel module and test llog_reader ========================================================== 08:47:11 (1783946831) [ 345.540311] Lustre: DEBUG MARKER: SKIP: sanity test_60a missing subtest run-llog.sh [ 347.662986] Lustre: DEBUG MARKER: == sanity test 60b: limit repeated messages from CERROR/CWARN ========================================================== 08:47:17 (1783946837) [ 357.848538] Lustre: DEBUG MARKER: == sanity test 60c: unlink file when mds full ============ 08:47:27 (1783946847) [ 573.321993] Lustre: DEBUG MARKER: == sanity test 60d: test printk console message masking == 08:51:03 (1783947063) [ 582.394163] Lustre: DEBUG MARKER: == sanity test 60e: no space while new llog is being created ========================================================== 08:51:11 (1783947071) [ 583.886484] Lustre: *** cfs_fail_loc=15b, val=0*** [ 583.891442] Lustre: *** cfs_fail_loc=15b, val=0*** [ 583.897714] LustreError: 6952:0:(llog_cat_server.c:483:llog_cat_add_rec()) lustre-OST0001-osc-MDT0000: initialization error: rc = -28 [ 592.339727] Lustre: DEBUG MARKER: == sanity test 60f: change debug_path works ============== 08:51:21 (1783947081) [ 601.787145] Lustre: DEBUG MARKER: == sanity test 60g: transaction abort won't cause MDT hung ========================================================== 08:51:30 (1783947090) [ 603.434979] Lustre: *** cfs_fail_loc=19a, val=0*** [ 604.857785] Lustre: *** cfs_fail_loc=19a, val=0*** [ 605.962176] Lustre: *** cfs_fail_loc=19a, val=0*** [ 608.504331] Lustre: *** cfs_fail_loc=19a, val=0*** [ 608.513591] Lustre: Skipped 1 previous similar message [ 613.470614] Lustre: *** cfs_fail_loc=19a, val=0*** [ 613.479397] Lustre: Skipped 2 previous similar messages [ 622.176500] Lustre: *** cfs_fail_loc=19a, val=0*** [ 622.186808] Lustre: Skipped 6 previous similar messages [ 638.518992] Lustre: *** cfs_fail_loc=19a, val=0*** [ 638.520621] Lustre: Skipped 11 previous similar messages [ 670.682634] Lustre: *** cfs_fail_loc=19a, val=0*** [ 670.686293] Lustre: Skipped 31 previous similar messages [ 727.017053] Lustre: DEBUG MARKER: == sanity test 60h: striped directory with missing stripes can be accessed ========================================================== 08:53:36 (1783947216) [ 729.172396] Lustre: DEBUG MARKER: SKIP: sanity test_60h Need at least 2 MDTs [ 730.968767] Lustre: DEBUG MARKER: SKIP: sanity test_60i skipping SLOW test 60i [ 733.346904] Lustre: DEBUG MARKER: == sanity test 60j: llog_reader reports corruptions ====== 08:53:42 (1783947222) [ 740.032610] Lustre: lustre-MDD0000: changelog on [ 749.801373] Lustre: DEBUG MARKER: SKIP: sanity test_60j path oi.1/0x1:0xa:0x0 is not in 'O/1/d/' format [ 752.772733] Lustre: lustre-MDD0000: changelog off [ 755.609725] Lustre: DEBUG MARKER: == sanity test 61a: mmap() writes don't make sync hang ========================================================================== 08:54:05 (1783947245) [ 763.976585] Lustre: DEBUG MARKER: == sanity test 61b: mmap() of unstriped file is successful ========================================================== 08:54:13 (1783947253) [ 771.394780] Lustre: DEBUG MARKER: == sanity test 63a: Verify oig_wait interruption does not crash ================================================================= 08:54:21 (1783947261) [ 841.060834] Lustre: DEBUG MARKER: == sanity test 63b: async write errors should be returned to fsync ============================================================= 08:55:30 (1783947330) [ 854.414516] Lustre: DEBUG MARKER: == sanity test 64a: verify filter grant calculations (in kernel) =============================================================== 08:55:44 (1783947344) [ 862.483584] Lustre: DEBUG MARKER: SKIP: sanity test_64b skipping SLOW test 64b [ 864.344964] Lustre: DEBUG MARKER: == sanity test 64c: verify grant shrink ================== 08:55:54 (1783947354) [ 872.392136] Lustre: DEBUG MARKER: == sanity test 64d: check grant limit exceed ============= 08:56:02 (1783947362) [ 927.628300] Lustre: DEBUG MARKER: == sanity test 64e: check grant consumption (no grant allocation) ========================================================== 08:56:57 (1783947417) [ 932.209225] Lustre: *** cfs_fail_loc=725, val=0*** [ 943.571493] Lustre: *** cfs_fail_loc=725, val=0*** [ 952.119950] Lustre: DEBUG MARKER: == sanity test 64f: check grant consumption (with grant allocation) ========================================================== 08:57:21 (1783947441) [ 964.981490] Lustre: DEBUG MARKER: == sanity test 64g: grant shrink on MDT ================== 08:57:35 (1783947455) [ 994.707558] Lustre: DEBUG MARKER: == sanity test 64h: grant shrink on read ================= 08:58:03 (1783947483) [ 1016.907912] Lustre: DEBUG MARKER: == sanity test 64i: shrink on reconnect ================== 08:58:27 (1783947507) [ 1026.916889] Lustre: *** cfs_fail_loc=513, val=17*** [ 1026.918852] LustreError: 12987:0:(service.c:2341:ptlrpc_server_handle_req_in()) drop incoming rpc opc 17, x1870603550228608 [ 1028.513224] Lustre: Failing over lustre-OST0000 [ 1028.577643] 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 [ 1028.715468] Lustre: server umount lustre-OST0000 complete [ 1033.696240] LustreError: 12995:0:(ldlm_lib.c:1192: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. [ 1033.729100] LustreError: 12995:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 3 previous similar messages [ 1035.187753] LustreError: 6930:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.204.52@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1038.817553] LustreError: 8991:0:(ldlm_lib.c:1192: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. [ 1043.939947] LustreError: 13000:0:(ldlm_lib.c:1192: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. [ 1043.956776] LustreError: 13000:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 1 previous similar message [ 1047.393735] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 1047.778154] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [ 1047.795276] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 1049.017055] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 1049.375279] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 1049.375316] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 1054.542318] Lustre: DEBUG MARKER: oleg452-server.virtnet: executing set_default_debug all all [ 1064.562927] Lustre: DEBUG MARKER: oleg452-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 1065.996392] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 1077.196702] Lustre: DEBUG MARKER: == sanity test 64j: check grants on re-done rpc ========== 08:59:27 (1783947567) [ 1078.395364] Lustre: *** cfs_fail_loc=256, val=0*** [ 1088.298099] Lustre: DEBUG MARKER: == sanity test 65a: directory with no stripe info ======== 08:59:38 (1783947578) [ 1095.417858] Lustre: DEBUG MARKER: == sanity test 65b: directory setstripe -S stripe_size*2 -i 0 -c 1 ========================================================== 08:59:45 (1783947585) [ 1102.399668] Lustre: DEBUG MARKER: == sanity test 65c: directory setstripe -S stripe_size*4 -i 1 -c 1 ========================================================== 08:59:52 (1783947592) [ 1109.536674] Lustre: DEBUG MARKER: == sanity test 65d: directory setstripe -S stripe_size -c stripe_count ========================================================== 08:59:59 (1783947599) [ 1117.851488] Lustre: DEBUG MARKER: == sanity test 65e: directory setstripe defaults ========= 09:00:07 (1783947607) [ 1124.948614] Lustre: DEBUG MARKER: == sanity test 65f: dir setstripe permission (should return error) ============================================================= 09:00:15 (1783947615) [ 1132.036677] Lustre: DEBUG MARKER: == sanity test 65g: directory setstripe -d =============== 09:00:21 (1783947621) [ 1139.254691] Lustre: DEBUG MARKER: == sanity test 65h: directory stripe info inherit ============================================================================== 09:00:29 (1783947629) [ 1147.783525] Lustre: DEBUG MARKER: == sanity test 65i: various tests to set root directory striping ========================================================== 09:00:37 (1783947637) [ 1157.466702] Lustre: DEBUG MARKER: == sanity test 65j: set default striping on root directory (bug 6367)=========================================================== 09:00:47 (1783947647) [ 1165.527723] Lustre: DEBUG MARKER: == sanity test 65k: validate manual striping works properly with deactivated OSCs ========================================================== 09:00:55 (1783947655) [ 1167.641353] 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 [ 1167.654642] Lustre: lustre-OST0000: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnecting [ 1167.666251] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 1168.566823] Lustre: lustre-OST0001: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnecting [ 1191.222815] Lustre: setting import lustre-OST0000_UUID INACTIVE by administrator request [ 1210.106042] 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 [ 1210.115173] Lustre: Skipped 1 previous similar message [ 1210.118142] Lustre: lustre-OST0000: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnecting [ 1210.135785] LustreError: lustre-OST0000-osc-MDT0000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 1210.152343] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 1210.155305] Lustre: Skipped 1 previous similar message [ 1214.897130] Lustre: DEBUG MARKER: oleg452-server.virtnet: executing wait_import_state FULL os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid 50 [ 1215.132116] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid in FULL state after 0 sec [ 1235.750438] Lustre: setting import lustre-OST0001_UUID INACTIVE by administrator request [ 1253.626201] 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 [ 1253.643216] Lustre: lustre-OST0001: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnecting [ 1253.652698] LustreError: lustre-OST0001-osc-MDT0000: This client was evicted by lustre-OST0001; in progress operations using this service will fail. [ 1253.663982] Lustre: lustre-OST0001-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 1259.290334] Lustre: DEBUG MARKER: oleg452-server.virtnet: executing wait_import_state FULL os[cp].lustre-OST0001-osc-MDT0000.ost_server_uuid 50 [ 1259.512412] Lustre: DEBUG MARKER: os[cp].lustre-OST0001-osc-MDT0000.ost_server_uuid in FULL state after 0 sec [ 1265.971743] Lustre: DEBUG MARKER: == sanity test 65l: lfs find on -1 stripe dir ================================================================================== 09:02:36 (1783947756) [ 1273.484198] Lustre: DEBUG MARKER: == sanity test 65m: normal user can't set filesystem default stripe ========================================================== 09:02:43 (1783947763) [ 1280.541426] Lustre: DEBUG MARKER: == sanity test 65n: don't inherit default layout from root for new subdirectories ========================================================== 09:02:50 (1783947770) [ 1293.943946] Lustre: DEBUG MARKER: SKIP: sanity test_65n needs >= 2 MDTs [ 1307.968385] Lustre: DEBUG MARKER: == sanity test 65o: pool inheritance for mdt component === 09:03:18 (1783947798) [ 1335.685472] Lustre: DEBUG MARKER: == sanity test 65p: setstripe with yaml file and huge number ========================================================== 09:03:45 (1783947825) [ 1343.786934] Lustre: DEBUG MARKER: == sanity test 65q: setstripe with >=8E offset should fail ========================================================== 09:03:54 (1783947834) [ 1351.813930] Lustre: DEBUG MARKER: == sanity test 65r: prevent all-zero offsets ============= 09:04:01 (1783947841) [ 1359.833748] Lustre: DEBUG MARKER: == sanity test 66: update inode blocks count on client ========================================================================= 09:04:10 (1783947850) [ 1374.952348] Lustre: DEBUG MARKER: == sanity test 69: verify oa2dentry return -ENOENT doesn't LBUG ================================================================ 09:04:25 (1783947865) [ 1377.217953] Lustre: *** cfs_fail_loc=217, val=0*** [ 1380.004730] Lustre: *** cfs_fail_loc=217, val=0*** [ 1380.010069] Lustre: Skipped 1 previous similar message [ 1388.598157] Lustre: DEBUG MARKER: == sanity test 70a: verify health_check, health_write don't explode (on OST) ========================================================== 09:04:38 (1783947878) [ 1402.394788] Lustre: DEBUG MARKER: SKIP: sanity test_71 skipping SLOW test 71 [ 1404.211915] Lustre: DEBUG MARKER: == sanity test 72a: Test that remove suid works properly (bug5695) ============================================================== 09:04:54 (1783947894) [ 1412.747209] Lustre: DEBUG MARKER: == sanity test 72b: Test that we keep mode setting if without file data changed (bug 24226) ========================================================== 09:05:02 (1783947902) [ 1422.277968] Lustre: DEBUG MARKER: == sanity test 73: multiple MDC requests (should not deadlock) ========================================================== 09:05:12 (1783947912) [ 1457.303315] Lustre: DEBUG MARKER: == sanity test 74a: ldlm_enqueue freed-export error path, ls (shouldn't LBUG) ========================================================== 09:05:47 (1783947947) [ 1465.335810] Lustre: DEBUG MARKER: == sanity test 74b: ldlm_enqueue freed-export error path, touch (shouldn't LBUG) ========================================================== 09:05:55 (1783947955) [ 1473.619678] Lustre: DEBUG MARKER: == sanity test 74c: ldlm_lock_create error path, (shouldn't LBUG) ========================================================== 09:06:03 (1783947963) [ 1481.353456] Lustre: DEBUG MARKER: == sanity test 76a: confirm clients recycle inodes properly ============================================================== 09:06:11 (1783947971) [ 1572.699543] Lustre: DEBUG MARKER: == sanity test 76b: confirm clients recycle directory inodes properly ============================================================== 09:07:42 (1783948062) [ 1629.748775] Lustre: DEBUG MARKER: == sanity test 77a: normal checksum read/write operation ========================================================== 09:08:40 (1783948120) [ 1638.017867] Lustre: DEBUG MARKER: == sanity test 77b: checksum error on client write, read ========================================================== 09:08:48 (1783948128) [ 1638.699967] LustreError: lustre-OST0000: BAD WRITE CHECKSUM: from 12345-192.168.204.52@tcp inode [0x200000406:0xc34:0x0] object 0x240000400:3836 extent [0-4194303]: client csum fb2f0c78, server csum fb2f0c77 [ 1642.248135] Lustre: DEBUG MARKER: set checksum type to crc32, rc = 0 [ 1643.582379] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.204.52@tcp inode [0x200000406:0xc34:0x0] object 0x240000400:3836 extent [0-4194303], client returned csum 7dabe5a2 (type 1), server csum 82e8b1b1 (type 1) [ 1646.181592] Lustre: DEBUG MARKER: set checksum type to adler, rc = 0 [ 1647.883081] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.204.52@tcp inode [0x200000406:0xc34:0x0] object 0x240000400:3836 extent [0-4194303], client returned csum 54f101a7 (type 2), server csum 843401f8 (type 2) [ 1651.212168] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 1653.021888] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.204.52@tcp inode [0x200000406:0xc34:0x0] object 0x240000400:3836 extent [0-4194303], client returned csum d76c1e63 (type 4), server csum fb2f0c77 (type 4) [ 1656.823584] Lustre: DEBUG MARKER: set checksum type to t10ip512, rc = 0 [ 1658.361569] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.204.52@tcp inode [0x200000406:0xc34:0x0] object 0x240000400:3836 extent [0-4194303], client returned csum 7f2032be (type 10), server csum 3e20326d (type 10) [ 1661.433724] Lustre: DEBUG MARKER: set checksum type to t10ip4K, rc = 0 [ 1662.985068] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.204.52@tcp inode [0x200000406:0xc34:0x0] object 0x240000400:3836 extent [0-4194303], client returned csum 7d7d0562 (type 20), server csum f57c0511 (type 20) [ 1666.168420] Lustre: DEBUG MARKER: set checksum type to t10crc512, rc = 0 [ 1670.159153] Lustre: DEBUG MARKER: set checksum type to t10crc4K, rc = 0 [ 1671.691061] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.204.52@tcp inode [0x200000406:0xc34:0x0] object 0x240000400:3836 extent [0-4194303], client returned csum 2409030b (type 80), server csum 7c880296 (type 80) [ 1671.720627] LustreError: Skipped 1 previous similar message [ 1674.176570] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 1680.680041] Lustre: DEBUG MARKER: == sanity test 77c: checksum error on client read with debug ========================================================== 09:09:30 (1783948170) [ 1686.519802] Lustre: 20395:0:(tgt_handler.c:2012:dump_all_bulk_pages()) dumping checksum data to /tmp/lustre-log-checksum_dump-ost-[0x200000406:0xc35:0x0]:[0-1048575]-dbb716e4-5233e937 [ 1686.540140] LustreError: dumping log to /tmp/lustre-log.1783948178.20395 [ 1713.721957] Lustre: DEBUG MARKER: == sanity test 77d: checksum error on OST direct write, read ========================================================== 09:10:03 (1783948203) [ 1714.297907] LustreError: lustre-OST0001: BAD WRITE CHECKSUM: from 12345-192.168.204.52@tcp inode [0x200000406:0xc37:0x0] object 0x280000400:3827 extent [0-4194303]: client csum de2bf73f, server csum de2bf73e [ 1717.239104] LustreError: lustre-OST0001: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.204.52@tcp inode [0x200000406:0xc37:0x0] object 0x280000400:3827 extent [0-4194303], client returned csum f5a99216 (type 4), server csum de2bf73e (type 4) [ 1717.261609] LustreError: Skipped 1 previous similar message [ 1724.348993] Lustre: DEBUG MARKER: == sanity test 77f: repeat checksum error on write (expect error) ========================================================== 09:10:14 (1783948214) [ 1726.165112] Lustre: DEBUG MARKER: set checksum type to crc32, rc = 0 [ 1726.475599] LustreError: lustre-OST0000: BAD WRITE CHECKSUM: from 12345-192.168.204.52@tcp inode [0x200000406:0xc38:0x0] object 0x240000400:3838 extent [0-4194303]: client csum 8b19b060, server csum 8b19b05f [ 1729.859399] Lustre: DEBUG MARKER: set checksum type to adler, rc = 0 [ 1730.349233] LustreError: lustre-OST0001: BAD WRITE CHECKSUM: from 12345-192.168.204.52@tcp inode [0x200000406:0xc39:0x0] object 0x280000400:3828 extent [0-4194303]: client csum 7d33b9a0, server csum 7d33b99f [ 1730.369708] LustreError: Skipped 3 previous similar messages [ 1733.540853] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 1735.206281] LustreError: lustre-OST0000: BAD WRITE CHECKSUM: from 12345-192.168.204.52@tcp inode [0x200000406:0xc3a:0x0] object 0x240000400:3839 extent [0-4194303]: client csum de2bf73f, server csum de2bf73e [ 1735.229448] LustreError: Skipped 5 previous similar messages [ 1737.317996] Lustre: DEBUG MARKER: set checksum type to t10ip512, rc = 0 [ 1741.273274] Lustre: DEBUG MARKER: set checksum type to t10ip4K, rc = 0 [ 1744.705591] Lustre: DEBUG MARKER: set checksum type to t10crc512, rc = 0 [ 1745.139465] LustreError: lustre-OST0001: BAD WRITE CHECKSUM: from 12345-192.168.204.52@tcp inode [0x200000406:0xc3d:0x0] object 0x280000400:3830 extent [0-4194303]: client csum a30822f0, server csum a30822ef [ 1745.176392] LustreError: Skipped 9 previous similar messages [ 1748.242314] Lustre: DEBUG MARKER: set checksum type to t10crc4K, rc = 0 [ 1756.610681] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 1758.881194] Lustre: DEBUG MARKER: == sanity test 77g: checksum error on OST write, read ==== 09:10:48 (1783948248) [ 1760.751915] Lustre: *** cfs_fail_loc=21a, val=0*** [ 1765.599237] Lustre: *** cfs_fail_loc=21b, val=0*** [ 1774.947564] Lustre: DEBUG MARKER: == sanity test 77k: enable/disable checksum correctly ==== 09:11:04 (1783948264) [ 1775.939165] Lustre: Setting parameter lustre.osc.lustre*.checksums=0 in log params [ 1783.158943] Lustre: Modifying parameter lustre.osc.lustre*.checksums=1 in log params [ 1788.829350] Lustre: Disabling parameter lustre.osc.lustre*.checksums= in log params [ 1803.630100] Lustre: Setting parameter lustre.osc.lustre*.checksums=0 in log params [ 1807.777327] Lustre: DEBUG MARKER: == sanity test 77l: preferred checksum type is remembered after reconnected ========================================================== 09:11:37 (1783948297) [ 1809.579870] Lustre: DEBUG MARKER: set checksum type to invalid, rc = 22 [ 1811.293923] Lustre: DEBUG MARKER: set checksum type to crc32, rc = 0 [ 1816.943232] Lustre: DEBUG MARKER: oleg452-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff9b2d115d0000.ost_server_uuid 50 [ 1818.486877] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9b2d115d0000.ost_server_uuid in IDLE state after 0 sec [ 1823.941741] Lustre: DEBUG MARKER: oleg452-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9b2d115d0000.ost_server_uuid 50 [ 1825.251090] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9b2d115d0000.ost_server_uuid in FULL state after 0 sec [ 1826.692679] Lustre: DEBUG MARKER: set checksum type to adler, rc = 0 [ 1832.545977] Lustre: DEBUG MARKER: oleg452-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff9b2d115d0000.ost_server_uuid 50 [ 1840.430127] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9b2d115d0000.ost_server_uuid in IDLE state after 6 sec [ 1846.396969] Lustre: DEBUG MARKER: oleg452-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9b2d115d0000.ost_server_uuid 50 [ 1847.925473] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9b2d115d0000.ost_server_uuid in FULL state after 0 sec [ 1849.542990] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 1854.895696] Lustre: DEBUG MARKER: oleg452-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff9b2d115d0000.ost_server_uuid 50 [ 1866.878538] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9b2d115d0000.ost_server_uuid in IDLE state after 9 sec [ 1872.457320] Lustre: DEBUG MARKER: oleg452-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9b2d115d0000.ost_server_uuid 50 [ 1874.015243] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9b2d115d0000.ost_server_uuid in FULL state after 0 sec [ 1875.654810] Lustre: DEBUG MARKER: set checksum type to t10ip512, rc = 0 [ 1881.513287] Lustre: DEBUG MARKER: oleg452-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff9b2d115d0000.ost_server_uuid 50 [ 1891.925562] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9b2d115d0000.ost_server_uuid in IDLE state after 8 sec [ 1897.330339] Lustre: DEBUG MARKER: oleg452-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9b2d115d0000.ost_server_uuid 50 [ 1898.818063] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9b2d115d0000.ost_server_uuid in FULL state after 0 sec [ 1900.530549] Lustre: DEBUG MARKER: set checksum type to t10ip4K, rc = 0 [ 1905.493995] Lustre: DEBUG MARKER: oleg452-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff9b2d115d0000.ost_server_uuid 50 [ 1917.059525] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9b2d115d0000.ost_server_uuid in IDLE state after 9 sec [ 1921.898927] Lustre: DEBUG MARKER: oleg452-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9b2d115d0000.ost_server_uuid 50 [ 1923.190470] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9b2d115d0000.ost_server_uuid in FULL state after 0 sec [ 1924.467103] Lustre: DEBUG MARKER: set checksum type to t10crc512, rc = 0 [ 1929.840721] Lustre: DEBUG MARKER: oleg452-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff9b2d115d0000.ost_server_uuid 50 [ 1937.370657] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9b2d115d0000.ost_server_uuid in IDLE state after 6 sec [ 1942.367630] Lustre: DEBUG MARKER: oleg452-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9b2d115d0000.ost_server_uuid 50 [ 1943.905257] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9b2d115d0000.ost_server_uuid in FULL state after 0 sec [ 1945.573222] Lustre: DEBUG MARKER: set checksum type to t10crc4K, rc = 0 [ 1951.566615] Lustre: DEBUG MARKER: oleg452-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff9b2d115d0000.ost_server_uuid 50 [ 1957.461601] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9b2d115d0000.ost_server_uuid in IDLE state after 4 sec [ 1962.702421] Lustre: DEBUG MARKER: oleg452-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9b2d115d0000.ost_server_uuid 50 [ 1964.162562] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9b2d115d0000.ost_server_uuid in FULL state after 0 sec [ 1970.552142] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 1972.376558] Lustre: DEBUG MARKER: == sanity test 77m: Verify checksum_speed is correctly read ========================================================== 09:14:22 (1783948462) [ 1978.796676] Lustre: DEBUG MARKER: == sanity test 77n: Verify read from a hole inside contiguous blocks with T10PI ========================================================== 09:14:28 (1783948468) [ 1980.928324] Lustre: DEBUG MARKER: set checksum type to t10ip512, rc = 0 [ 1982.487842] Lustre: DEBUG MARKER: set checksum type to t10ip4K, rc = 0 [ 1983.939699] Lustre: DEBUG MARKER: set checksum type to t10crc512, rc = 0 [ 1985.257867] Lustre: DEBUG MARKER: set checksum type to t10crc4K, rc = 0 [ 1991.727494] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 1993.735566] Lustre: DEBUG MARKER: == sanity test 77o: Verify checksum_type for server (mdt and ofd(obdfilter)) ========================================================== 09:14:43 (1783948483) [ 2005.639956] Lustre: DEBUG MARKER: == sanity test 78: handle large O_DIRECT writes correctly ====================================================================== 09:14:55 (1783948495) [ 2015.261200] Lustre: DEBUG MARKER: == sanity test 79: df report consistency check =========== 09:15:05 (1783948505) [ 2030.441073] Lustre: DEBUG MARKER: == sanity test 80: Page eviction is equally fast at high offsets too ========================================================== 09:15:20 (1783948520) [ 2039.264495] Lustre: DEBUG MARKER: == sanity test 81a: OST should retry write when get -ENOSPC ========================================================================= 09:15:29 (1783948529) [ 2040.925684] Lustre: *** cfs_fail_loc=228, val=0*** [ 2047.819834] Lustre: DEBUG MARKER: == sanity test 81b: OST should return -ENOSPC when retry still fails ================================================================= 09:15:37 (1783948537) [ 2049.496894] Lustre: *** cfs_fail_loc=228, val=0*** [ 2056.041828] Lustre: DEBUG MARKER: == sanity test 99: cvs strange file/directory operations ========================================================== 09:15:46 (1783948546) [ 2085.098120] Lustre: DEBUG MARKER: == sanity test 100: check local port using privileged port ========================================================== 09:16:14 (1783948574) [ 2093.669612] Lustre: DEBUG MARKER: == sanity test 101a: check read-ahead for random reads === 09:16:23 (1783948583) [ 2303.310338] Lustre: DEBUG MARKER: == sanity test 101b: check stride-io mode read-ahead =========================================================================== 09:19:53 (1783948793) [ 2334.924822] Lustre: DEBUG MARKER: == sanity test 101c: check stripe_size aligned read-ahead ========================================================== 09:20:24 (1783948824) [ 2433.316952] Lustre: DEBUG MARKER: == sanity test 101d: file read with and without read-ahead enabled ========================================================== 09:22:03 (1783948923) [ 2770.291860] Lustre: DEBUG MARKER: == sanity test 101e: check read-ahead for small read(1k) for small files(500k) ========================================================== 09:27:40 (1783949260) [ 2875.937619] Lustre: DEBUG MARKER: == sanity test 101f: check mmap read performance ========= 09:29:25 (1783949365) [ 2887.470484] Lustre: DEBUG MARKER: == sanity test 101g: Big bulk(4/16 MiB) readahead ======== 09:29:36 (1783949376) [ 2959.210485] Lustre: DEBUG MARKER: == sanity test 101h: Readahead should cover current read window ========================================================== 09:30:49 (1783949449) [ 2978.777740] Lustre: DEBUG MARKER: == sanity test 101i: allow current readahead to exceed reservation ========================================================== 09:31:08 (1783949468) [ 2988.193476] Lustre: DEBUG MARKER: == sanity test 101j: A complete read block should be submitted when no RA ========================================================== 09:31:18 (1783949478) [ 3051.540311] Lustre: DEBUG MARKER: == sanity test 101m: read ahead for small file and last stripe of the file ========================================================== 09:32:21 (1783949541) [ 3063.605101] Lustre: DEBUG MARKER: == sanity test 102a: user xattr test ============================================================================================ 09:32:33 (1783949553) [ 3071.980660] Lustre: DEBUG MARKER: == sanity test 102b: getfattr/setfattr for trusted.lov EAs ========================================================== 09:32:41 (1783949561) [ 3083.687518] Lustre: DEBUG MARKER: == sanity test 102c: non-root getfattr/setfattr for lustre.lov EAs ===================================================================== 09:32:53 (1783949573) [ 3091.100823] Lustre: DEBUG MARKER: == sanity test 102d: tar restore stripe info from tarfile,not keep osts ========================================================== 09:33:01 (1783949581) [ 3111.480907] Lustre: DEBUG MARKER: == sanity test 102f: tar copy files, not keep osts ======= 09:33:21 (1783949601) [ 3133.355027] Lustre: DEBUG MARKER: == sanity test 102h: grow xattr from inside inode to external block ========================================================== 09:33:43 (1783949623) [ 3136.383273] Lustre: DEBUG MARKER: save trusted.big on /mnt/lustre/f102h.sanity [ 3138.635200] Lustre: DEBUG MARKER: save trusted.sml on /mnt/lustre/f102h.sanity [ 3140.610354] Lustre: DEBUG MARKER: grow trusted.sml on /mnt/lustre/f102h.sanity [ 3142.614959] Lustre: DEBUG MARKER: trusted.big still valid after growing trusted.sml [ 3150.021371] Lustre: DEBUG MARKER: == sanity test 102ha: grow xattr from inside inode to external inode ========================================================== 09:33:59 (1783949639) [ 3153.562778] Lustre: DEBUG MARKER: save trusted.big on /mnt/lustre/f102ha.sanity [ 3155.608153] Lustre: DEBUG MARKER: save trusted.sml on /mnt/lustre/f102ha.sanity [ 3157.748355] Lustre: DEBUG MARKER: grow trusted.sml on /mnt/lustre/f102ha.sanity [ 3159.579823] Lustre: DEBUG MARKER: trusted.big still valid after growing trusted.sml [ 3161.804874] Lustre: DEBUG MARKER: save trusted.big on /mnt/lustre/f102ha.sanity [ 3169.007376] Lustre: DEBUG MARKER: == sanity test 102i: lgetxattr test on symbolic link ====================================================================== 09:34:18 (1783949658) [ 3178.497788] Lustre: DEBUG MARKER: == sanity test 102j: non-root tar restore stripe info from tarfile, not keep osts ============================================================= 09:34:28 (1783949668) [ 3199.722972] Lustre: DEBUG MARKER: == sanity test 102k: setfattr without parameter of value shouldn't cause a crash ========================================================== 09:34:49 (1783949689) [ 3208.126289] Lustre: DEBUG MARKER: == sanity test 102l: listxattr size test ============================================================================================ 09:34:57 (1783949697) [ 3218.242343] Lustre: DEBUG MARKER: == sanity test 102m: Ensure listxattr fails on small bufffer ================================================================== 09:35:07 (1783949707) [ 3226.312769] Lustre: DEBUG MARKER: == sanity test 102n: silently ignore setxattr on internal trusted xattrs ========================================================== 09:35:16 (1783949716) [ 3236.645918] Lustre: DEBUG MARKER: == sanity test 102p: check setxattr(2) correctly fails without permission ========================================================== 09:35:26 (1783949726) [ 3244.749250] Lustre: DEBUG MARKER: == sanity test 102q: flistxattr should not return trusted.link EAs for orphans ========================================================== 09:35:34 (1783949734) [ 3251.706843] Lustre: DEBUG MARKER: == sanity test 102r: set EAs with empty values =========== 09:35:41 (1783949741) [ 3259.642415] Lustre: DEBUG MARKER: == sanity test 102s: getting nonexistent xattrs should fail ========================================================== 09:35:49 (1783949749) [ 3267.784988] Lustre: DEBUG MARKER: == sanity test 102t: zero length xattr values handled correctly ========================================================== 09:35:57 (1783949757) [ 3276.893299] Lustre: DEBUG MARKER: == sanity test 103a: acl test ============================ 09:36:06 (1783949766) [ 3612.349356] Lustre: DEBUG MARKER: == sanity test 103b: umask lfs setstripe ================= 09:41:42 (1783950102) [ 3818.937857] Lustre: DEBUG MARKER: == sanity test 103c: 'cp -rp' won't set empty acl ======== 09:45:07 (1783950307) [ 3828.100429] Lustre: DEBUG MARKER: == sanity test 103e: inheritance of big amount of default ACLs ========================================================== 09:45:17 (1783950317) [ 3853.094029] Lustre: 53859:0:(osd_handler.c:2191:osd_trans_start()) lustre-MDT0000: credits 30549 > trans_max 3200 [ 3853.099575] Lustre: 53859:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 4/16/0, destroy: 1/4/0 [ 3853.108178] Lustre: 53859:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 2003/2003/0, xattr_set: 3004/28292/0 [ 3853.124580] Lustre: 53859:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 20/142/0, punch: 0/0/0, quota 0/0/0 [ 3853.142030] Lustre: 53859:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 5/84/0, delete: 2/5/0 [ 3853.158552] Lustre: 53859:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 1/1/0, ref_del: 2/2/0 [ 3853.182921] CPU: 0 PID: 53859 Comm: mdt00_005 Kdump: loaded Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 3853.193895] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.17.0-10.fc44 06/10/2025 [ 3853.201917] Call Trace: [ 3853.204985] ? dump_stack+0xbb/0x10e [ 3853.207658] ? osd_trans_start+0x8db/0x9d0 [osd_ldiskfs] [ 3853.211911] ? dt_trans_start+0x1c/0x70 [obdclass] [ 3853.228335] ? top_trans_start+0x4fd/0xd00 [ptlrpc] [ 3853.238486] ? lod_declare_ref_add+0x1a/0x30 [lod] [ 3853.246456] ? dt_declare_ref_add+0x6c/0x200 [obdclass] [ 3853.250539] ? lod_trans_start+0x109/0x4c0 [lod] [ 3853.253610] ? mdd_declare_links_add+0x60/0x90 [mdd] [ 3853.259844] ? mdd_trans_start+0x18/0x30 [mdd] [ 3853.263788] ? mdd_unlink+0x7a4/0x13c0 [mdd] [ 3853.268847] ? mdt_reint_unlink+0x14aa/0x1a30 [mdt] [ 3853.275355] ? mdt_reint_rec+0x139/0x2b0 [mdt] [ 3853.278782] ? mdt_reint_internal+0x693/0xdc0 [mdt] [ 3853.284878] ? mdt_reint+0x163/0x190 [mdt] [ 3853.293562] ? tgt_handle_request0+0x137/0xaf0 [ptlrpc] [ 3853.301769] ? tgt_request_handle+0x575/0x1f70 [ptlrpc] [ 3853.306126] ? ptlrpc_server_handle_request+0x443/0x13b0 [ptlrpc] [ 3853.317963] ? lprocfs_counter_add+0x15b/0x210 [obdclass] [ 3853.331340] ? ptlrpc_main+0xce8/0x1400 [ptlrpc] [ 3853.341696] ? ptlrpc_wait_event+0x690/0x690 [ptlrpc] [ 3853.346604] ? kthread+0x1d1/0x200 [ 3853.351388] ? set_kthread_struct+0x70/0x70 [ 3853.356557] ? ret_from_fork+0x1f/0x30 [ 3867.015578] Lustre: DEBUG MARKER: == sanity test 103f: changelog doesn't interfere with default ACLs buffers ========================================================== 09:45:56 (1783950356) [ 3872.715913] Lustre: lustre-MDD0000: changelog on [ 3881.927196] Lustre: lustre-MDD0000: changelog off [ 3885.200535] Lustre: DEBUG MARKER: == sanity test 103g: no MDS_GETXATTR storm for inodes without ACL_ACCESS (LU-17238) ========================================================== 09:46:14 (1783950374) [ 3895.054068] Lustre: DEBUG MARKER: == sanity test 104a: lfs df [-ih] [path] test =================================================================================== 09:46:24 (1783950384) [ 3895.898945] Lustre: lustre-OST0000: Client c22998d9-c0a0-4d11-9532-344e64be6da6 (at 192.168.204.52@tcp) reconnecting [ 3902.260324] Lustre: DEBUG MARKER: oleg452-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0000-osc-ffff9b2d11528800.ost_server_uuid 50 [ 3904.036031] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9b2d11528800.ost_server_uuid in FULL state after 0 sec [ 3911.921691] Lustre: DEBUG MARKER: == sanity test 104b: runas -u 500 -g 500 lfs check servers test ============================================================================== 09:46:41 (1783950401) [ 3919.095974] Lustre: DEBUG MARKER: == sanity test 104c: Verify df vs lfs_df stays same after recordsize change ========================================================== 09:46:48 (1783950408) [ 3921.101896] Lustre: DEBUG MARKER: SKIP: sanity test_104c zfs only test [ 3922.792263] Lustre: DEBUG MARKER: == sanity test 104d: runas -u 500 -g 500 lctl dl test ==== 09:46:52 (1783950412) [ 3930.426641] Lustre: DEBUG MARKER: == sanity test 105a: flock when mounted without -o flock test ================================================================== 09:47:00 (1783950420) [ 3937.079754] Lustre: DEBUG MARKER: == sanity test 105b: fcntl when mounted without -o flock test ================================================================== 09:47:06 (1783950426) [ 3944.625455] Lustre: DEBUG MARKER: == sanity test 105c: lockf when mounted without -o flock test ========================================================== 09:47:14 (1783950434) [ 3952.142812] Lustre: DEBUG MARKER: == sanity test 105d: flock race (should not freeze) ================================================================== 09:47:22 (1783950442) [ 3971.404211] Lustre: DEBUG MARKER: == sanity test 105e: Two conflicting flocks from same process ========================================================== 09:47:40 (1783950460) [ 3981.394930] Lustre: DEBUG MARKER: == sanity test 105f: Enqueue same range flocks =========== 09:47:50 (1783950470) [ 3991.360914] Lustre: DEBUG MARKER: == sanity test 105g: ldlm_lock_debug stack test ========== 09:48:01 (1783950481) [ 4003.186697] Lustre: DEBUG MARKER: == sanity test 105h: Flock functional verify ============= 09:48:12 (1783950492) [ 4013.169518] Lustre: DEBUG MARKER: == sanity test 105i: Flock deadlock verify =============== 09:48:22 (1783950502) [ 4027.437446] Lustre: DEBUG MARKER: == sanity test 106: attempt exec of dir followed by chown of that dir ========================================================== 09:48:36 (1783950516) [ 4035.629305] Lustre: DEBUG MARKER: == sanity test 107: Coredump on SIG ====================== 09:48:45 (1783950525) [ 4046.190077] Lustre: DEBUG MARKER: == sanity test 110: filename length checking ============= 09:48:56 (1783950536) [ 4054.289938] Lustre: DEBUG MARKER: == sanity test 116a: stripe QOS: free space balance ============================================================================= 09:49:04 (1783950544) [ 4251.490977] Lustre: DEBUG MARKER: == sanity test 116b: QoS shouldn't LBUG if not enough OSTs found on the 2nd pass ========================================================== 09:52:21 (1783950741) [ 4254.688466] Lustre: *** cfs_fail_loc=147, val=0*** [ 4255.211178] Lustre: *** cfs_fail_loc=147, val=0*** [ 4255.217208] Lustre: Skipped 35 previous similar messages [ 4264.651755] Lustre: DEBUG MARKER: == sanity test 117: verify osd extend ==================== 09:52:34 (1783950754) [ 4271.776693] Lustre: DEBUG MARKER: == sanity test 118a: verify O_SYNC works ================= 09:52:41 (1783950761) [ 4279.680404] Lustre: DEBUG MARKER: == sanity test 118b: Reclaim dirty pages on fatal error ==================================================================== 09:52:49 (1783950769) [ 4282.078462] Lustre: *** cfs_fail_loc=217, val=0*** [ 4282.085323] Lustre: Skipped 42 previous similar messages [ 4290.964807] Lustre: DEBUG MARKER: SKIP: sanity test_118c skipping ALWAYS excluded test 118c [ 4292.950030] Lustre: DEBUG MARKER: SKIP: sanity test_118d skipping ALWAYS excluded test 118d [ 4294.689822] Lustre: DEBUG MARKER: == sanity test 118f: Simulate unrecoverable OSC side error ==================================================================== 09:53:04 (1783950784) [ 4302.599583] Lustre: DEBUG MARKER: == sanity test 118g: Don't stay in wait if we got local -ENOMEM ==================================================================== 09:53:12 (1783950792) [ 4311.834671] Lustre: DEBUG MARKER: == sanity test 118h: Verify timeout in handling recoverables errors ==================================================================== 09:53:21 (1783950801) [ 4313.854697] Lustre: *** cfs_fail_loc=20e, val=0*** [ 4314.546586] Lustre: *** cfs_fail_loc=20e, val=0*** [ 4316.593075] Lustre: *** cfs_fail_loc=20e, val=0*** [ 4319.673498] Lustre: *** cfs_fail_loc=20e, val=0*** [ 4323.709320] Lustre: *** cfs_fail_loc=20e, val=0*** [ 4333.973785] Lustre: DEBUG MARKER: == sanity test 118i: Fix error before timeout in recoverable error ==================================================================== 09:53:43 (1783950823) [ 4336.456834] Lustre: *** cfs_fail_loc=20e, val=0*** [ 4351.266898] Lustre: DEBUG MARKER: == sanity test 118j: Simulate unrecoverable OST side error ==================================================================== 09:54:00 (1783950840) [ 4354.093776] Lustre: *** cfs_fail_loc=220, val=0*** [ 4354.100908] Lustre: Skipped 2 previous similar messages [ 4363.687403] Lustre: DEBUG MARKER: == sanity test 118k: bio alloc -ENOMEM and IO TERM handling =================================================================== 09:54:13 (1783950853) [ 4390.531576] Lustre: DEBUG MARKER: == sanity test 118l: fsync dir =========================== 09:54:39 (1783950879) [ 4399.211135] Lustre: DEBUG MARKER: == sanity test 118m: fdatasync dir ======================= 09:54:48 (1783950888) [ 4407.978370] Lustre: DEBUG MARKER: == sanity test 118n: statfs() sends OST_STATFS requests in parallel ========================================================== 09:54:57 (1783950897) [ 4412.910970] LustreError: 12816:0:(ofd_dev.c:1917:ofd_statfs_hdl()) cfs_fail_timeout id 242 sleeping for 10000ms [ 4414.079107] LustreError: 12816:0:(ofd_dev.c:1917:ofd_statfs_hdl()) cfs_fail_timeout interrupted [ 4422.710863] Lustre: DEBUG MARKER: == sanity test 119a: Short directIO read must return actual read amount ========================================================== 09:55:12 (1783950912) [ 4431.689956] Lustre: DEBUG MARKER: == sanity test 119b: Sparse directIO read must return actual read amount ========================================================== 09:55:21 (1783950921) [ 4441.070518] Lustre: DEBUG MARKER: == sanity test 119c: Testing for direct read hitting hole ========================================================== 09:55:30 (1783950930) [ 4450.243198] Lustre: DEBUG MARKER: == sanity test 119e: Basic tests of dio read and write at various sizes ========================================================== 09:55:39 (1783950939) [ 4494.456780] Lustre: DEBUG MARKER: == sanity test 119f: dio vs dio race ===================== 09:56:24 (1783950984) [ 4542.103986] Lustre: DEBUG MARKER: == sanity test 119g: dio vs buffered I/O race ============ 09:57:11 (1783951031) [ 4593.106799] Lustre: DEBUG MARKER: == sanity test 119h: basic tests of memory unaligned dio ========================================================== 09:58:02 (1783951082) [ 4629.967623] Lustre: DEBUG MARKER: SKIP: sanity test_119i skipping ALWAYS excluded test 119i [ 4632.165846] Lustre: DEBUG MARKER: == sanity test 119j: basic tests of hybrid IO switching == 09:58:41 (1783951121) [ 4642.212249] Lustre: DEBUG MARKER: == sanity test 119k: hybrid IO counting with stats and disabling ========================================================== 09:58:51 (1783951131) [ 4665.454989] Lustre: DEBUG MARKER: == sanity test 119m: Test DIO readv/writev: exercise iter duplication ========================================================== 09:59:14 (1783951154) [ 4677.587261] Lustre: DEBUG MARKER: == sanity test 119n: Test Unaligned DIO readv() and writev() with unpatched ZFS ========================================================== 09:59:26 (1783951166) [ 4679.997523] Lustre: DEBUG MARKER: SKIP: sanity test_119n need ZFS server without unaligned_dio support [ 4682.435557] Lustre: DEBUG MARKER: == sanity test 119o: Test Unaligned DIO readv() and writev() with unpatched servers ========================================================== 09:59:31 (1783951171) [ 4684.783806] Lustre: DEBUG MARKER: SKIP: sanity test_119o need ldiskfs without unaligned_dio support. [ 4687.744972] Lustre: DEBUG MARKER: == sanity test 119p: Test Unaligned DIO readv() and writev() with patched servers ========================================================== 09:59:36 (1783951176) [ 4698.166032] Lustre: DEBUG MARKER: == sanity test 119q: Test patchded Unaligned DIO readv() and writev() ========================================================== 09:59:47 (1783951187) [ 4717.530711] Lustre: DEBUG MARKER: == sanity test 119r: Test error handling in unaligned DIO user copy ========================================================== 10:00:07 (1783951207) [ 4727.426747] Lustre: DEBUG MARKER: == sanity test 120a: Early Lock Cancel: mkdir test ======= 10:00:17 (1783951217) [ 4739.757411] Lustre: DEBUG MARKER: == sanity test 120b: Early Lock Cancel: create test ====== 10:00:29 (1783951229) [ 4751.334613] Lustre: DEBUG MARKER: == sanity test 120c: Early Lock Cancel: link test ======== 10:00:41 (1783951241) [ 4763.957162] Lustre: DEBUG MARKER: == sanity test 120d: Early Lock Cancel: setattr test ===== 10:00:53 (1783951253) [ 4775.573276] Lustre: DEBUG MARKER: == sanity test 120e: Early Lock Cancel: unlink test ====== 10:01:05 (1783951265) [ 4794.713953] Lustre: DEBUG MARKER: == sanity test 120f: Early Lock Cancel: rename test ====== 10:01:24 (1783951284) [ 4815.436696] Lustre: DEBUG MARKER: == sanity test 120g: Early Lock Cancel: performance test ========================================================== 10:01:45 (1783951305) [ 5384.070881] Lustre: DEBUG MARKER: == sanity test 121: read cancel race ===================== 10:11:13 (1783951873) [ 5391.916406] Lustre: DEBUG MARKER: == sanity test 123aa: verify statahead work ============== 10:11:21 (1783951881) [ 5404.006528] Lustre: DEBUG MARKER: 'ls -l' 100 files without statahead: 3 sec [ 5407.263948] Lustre: DEBUG MARKER: 'ls -l' 100 files with statahead: 1 sec [ 5458.282807] Lustre: DEBUG MARKER: 'ls -l' 1000 files without statahead: 28 sec [ 5468.718200] Lustre: DEBUG MARKER: 'ls -l' 1000 files with statahead: 7 sec [ 5470.643911] Lustre: DEBUG MARKER: 'ls -l' done [ 5496.401518] Lustre: DEBUG MARKER: unlink + rm -r /mnt/lustre/d123aa.sanity: 23 seconds [ 5507.866599] Lustre: DEBUG MARKER: == sanity test 123ab: verify statahead work by using statx ========================================================== 10:13:17 (1783951997) [ 5519.299546] Lustre: DEBUG MARKER: 'statx -l' 100 files without statahead: 3 sec [ 5522.472247] Lustre: DEBUG MARKER: 'statx -l' 100 files with statahead: 1 sec [ 5574.274892] Lustre: DEBUG MARKER: 'statx -l' 1000 files without statahead: 27 sec [ 5588.746751] Lustre: DEBUG MARKER: 'statx -l' 1000 files with statahead: 8 sec [ 5590.570265] Lustre: DEBUG MARKER: 'statx -l' done [ 5614.782530] Lustre: DEBUG MARKER: unlink + rm -r /mnt/lustre/d123ab.sanity: 22 seconds [ 5627.916021] Lustre: DEBUG MARKER: == sanity test 123ac: verify statahead work by using statx without glimpse RPCs ========================================================== 10:15:17 (1783952117) [ 5638.630869] Lustre: DEBUG MARKER: 'statx -c 1 [ 5641.314981] Lustre: DEBUG MARKER: 'statx -c 1 [ 5678.659292] Lustre: DEBUG MARKER: 'statx -c 1 [ 5685.813122] Lustre: DEBUG MARKER: 'statx -c 1 [ 5687.404683] Lustre: DEBUG MARKER: 'statx -c 1 [ 5709.382167] Lustre: DEBUG MARKER: unlink + rm -r /mnt/lustre/d123ac.sanity: 20 seconds [ 5716.888247] Lustre: DEBUG MARKER: 'statx --cached=always -D' 100 files without statahead: 0 sec [ 5719.088528] Lustre: DEBUG MARKER: 'statx --cached=always -D' 100 files with statahead: 0 sec [ 5742.344880] Lustre: DEBUG MARKER: 'statx --cached=always -D' 1000 files without statahead: 1 sec [ 5744.802495] Lustre: DEBUG MARKER: 'statx --cached=always -D' 1000 files with statahead: 0 sec [ 5909.789563] Lustre: DEBUG MARKER: 'statx --cached=always -D' 10000 files without statahead: 0 sec [ 5912.317952] Lustre: DEBUG MARKER: 'statx --cached=always -D' 10000 files with statahead: 0 sec [ 5914.235594] Lustre: DEBUG MARKER: 'statx --cached=always -D' done [ 6271.134630] Lustre: DEBUG MARKER: unlink + rm -r /mnt/lustre/d123ac.sanity: 355 seconds [ 6289.321784] Lustre: DEBUG MARKER: == sanity test 123ad: Verify batching statahead works correctly ========================================================== 10:26:19 (1783952779) [ 6300.964820] Lustre: DEBUG MARKER: 'ls -l' 100 files without statahead: 3 sec [ 6304.483659] Lustre: DEBUG MARKER: 'ls -l' 100 files with statahead: 1 sec [ 6352.380408] Lustre: DEBUG MARKER: 'ls -l' 1000 files without statahead: 26 sec [ 6368.646563] Lustre: DEBUG MARKER: 'ls -l' 1000 files with statahead: 12 sec [ 6370.954957] Lustre: DEBUG MARKER: 'ls -l' done [ 6398.095113] Lustre: DEBUG MARKER: unlink + rm -r /mnt/lustre/d123ad.sanity: 24 seconds [ 7139.730123] Lustre: DEBUG MARKER: 'ls -l' 100 files without statahead: 3 sec [ 7143.760628] Lustre: DEBUG MARKER: 'ls -l' 100 files with statahead: 2 sec [ 7196.568196] Lustre: DEBUG MARKER: 'ls -l' 1000 files without statahead: 29 sec [ 7209.147519] Lustre: DEBUG MARKER: 'ls -l' 1000 files with statahead: 9 sec [ 7211.089487] Lustre: DEBUG MARKER: 'ls -l' done [ 7237.397580] Lustre: DEBUG MARKER: unlink + rm -r /mnt/lustre/d123ad.sanity: 24 seconds [ 7846.838616] Lustre: DEBUG MARKER: == sanity test 123b: not panic with network error in statahead enqueue (bug 15027) ========================================================== 10:52:16 (1783954336) [ 7883.031575] Lustre: DEBUG MARKER: ls done [ 7917.552544] Lustre: DEBUG MARKER: == sanity test 123c: Can not initialize inode warning on DNE statahead ========================================================== 10:53:27 (1783954407) [ 7919.479827] Lustre: DEBUG MARKER: SKIP: sanity test_123c needs >= 2 MDTs [ 7921.717531] Lustre: DEBUG MARKER: == sanity test 123d: Statahead on striped directories works correctly ========================================================== 10:53:31 (1783954411) [ 7940.340306] Lustre: DEBUG MARKER: == sanity test 123e: statahead with large wide striping == 10:53:49 (1783954429) [ 8114.755804] Lustre: 71630:0:(mdt_handler.c:4704:mdt_unpack_req_pack_rep()) lustre-MDT0000: cannot pack response: rc = -75 [ 8292.941029] Lustre: DEBUG MARKER: == sanity test 123f: Retry mechanism with large wide striping files ========================================================== 10:59:39 (1783954779) [ 8423.287994] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x280000400 to 0x280000401 [ 8423.307150] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x240000400 to 0x240000401 [ 8731.159507] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x280000401 to 0x280000402 [ 8735.931701] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x240000401 to 0x240000402 [ 9341.835453] Lustre: 6952:0:(osd_handler.c:2191:osd_trans_start()) lustre-MDT0000: credits 30573 > trans_max 3200 [ 9341.847357] Lustre: 6952:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 4/16/0, destroy: 1/4/0 [ 9341.855318] Lustre: 6952:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 2003/2003/0, xattr_set: 3004/28292/0 [ 9341.864334] Lustre: 6952:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 20/166/0, punch: 0/0/0, quota 0/0/0 [ 9341.878246] Lustre: 6952:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 5/84/0, delete: 2/5/0 [ 9341.888657] Lustre: 6952:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 1/1/0, ref_del: 2/2/0 [ 9341.899522] CPU: 3 PID: 6952 Comm: mdt00_003 Kdump: loaded Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 9341.915572] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.17.0-10.fc44 06/10/2025 [ 9341.922353] Call Trace: [ 9341.930204] ? dump_stack+0xbb/0x10e [ 9341.933326] ? osd_trans_start+0x8db/0x9d0 [osd_ldiskfs] [ 9341.937698] ? dt_trans_start+0x1c/0x70 [obdclass] [ 9341.941424] ? top_trans_start+0x4fd/0xd00 [ptlrpc] [ 9341.947439] ? lod_declare_ref_add+0x1a/0x30 [lod] [ 9341.952701] ? dt_declare_ref_add+0x6c/0x200 [obdclass] [ 9341.956522] ? lod_trans_start+0x109/0x4c0 [lod] [ 9341.959722] ? mdd_declare_links_add+0x60/0x90 [mdd] [ 9341.966092] ? mdd_trans_start+0x18/0x30 [mdd] [ 9341.969221] ? mdd_unlink+0x7a4/0x13c0 [mdd] [ 9341.975487] ? mdt_reint_unlink+0x14aa/0x1a30 [mdt] [ 9341.980779] ? mdt_reint_rec+0x139/0x2b0 [mdt] [ 9341.982462] ? mdt_reint_internal+0x693/0xdc0 [mdt] [ 9341.985666] ? mdt_reint+0x163/0x190 [mdt] [ 9341.989725] ? tgt_handle_request0+0x137/0xaf0 [ptlrpc] [ 9341.994415] ? tgt_request_handle+0x575/0x1f70 [ptlrpc] [ 9341.998203] ? ptlrpc_server_handle_request+0x443/0x13b0 [ptlrpc] [ 9342.002578] ? lprocfs_counter_add+0x15b/0x210 [obdclass] [ 9342.010708] ? ptlrpc_main+0xce8/0x1400 [ptlrpc] [ 9342.014916] ? ptlrpc_wait_event+0x690/0x690 [ptlrpc] [ 9342.020477] ? kthread+0x1d1/0x200 [ 9342.026602] ? set_kthread_struct+0x70/0x70 [ 9342.032149] ? ret_from_fork+0x1f/0x30 [ 9402.709322] Lustre: 6952:0:(osd_handler.c:2191:osd_trans_start()) lustre-MDT0000: credits 26169 > trans_max 3200 [ 9402.720169] Lustre: 6952:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 4/16/0, destroy: 1/4/0 [ 9402.727202] Lustre: 6952:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1711/1711/0, xattr_set: 2566/24204/0 [ 9402.737376] Lustre: 6952:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 20/142/0, punch: 0/0/0, quota 0/0/0 [ 9402.748391] Lustre: 6952:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 5/84/0, delete: 2/5/0 [ 9402.753106] Lustre: 6952:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 1/1/0, ref_del: 2/2/0 [ 9402.758713] CPU: 1 PID: 6952 Comm: mdt00_003 Kdump: loaded Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 9402.773291] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.17.0-10.fc44 06/10/2025 [ 9402.776891] Call Trace: [ 9402.783322] ? dump_stack+0xbb/0x10e [ 9402.785458] ? osd_trans_start+0x8db/0x9d0 [osd_ldiskfs] [ 9402.790699] ? dt_trans_start+0x1c/0x70 [obdclass] [ 9402.796662] ? top_trans_start+0x4fd/0xd00 [ptlrpc] [ 9402.800443] ? lod_declare_ref_add+0x1a/0x30 [lod] [ 9402.804231] ? dt_declare_ref_add+0x6c/0x200 [obdclass] [ 9402.811641] ? lod_trans_start+0x109/0x4c0 [lod] [ 9402.821162] ? mdd_declare_links_add+0x60/0x90 [mdd] [ 9402.826959] ? mdd_trans_start+0x18/0x30 [mdd] [ 9402.830826] ? mdd_unlink+0x7a4/0x13c0 [mdd] [ 9402.840771] ? mdt_reint_unlink+0x14aa/0x1a30 [mdt] [ 9402.842699] ? mdt_reint_rec+0x139/0x2b0 [mdt] [ 9402.845089] ? mdt_reint_internal+0x693/0xdc0 [mdt] [ 9402.849153] ? mdt_reint+0x163/0x190 [mdt] [ 9402.851720] ? tgt_handle_request0+0x137/0xaf0 [ptlrpc] [ 9402.854446] ? tgt_request_handle+0x575/0x1f70 [ptlrpc] [ 9402.856703] ? ptlrpc_server_handle_request+0x443/0x13b0 [ptlrpc] [ 9402.862292] ? lprocfs_counter_add+0x15b/0x210 [obdclass] [ 9402.866048] ? ptlrpc_main+0xce8/0x1400 [ptlrpc] [ 9402.869020] ? ptlrpc_wait_event+0x690/0x690 [ptlrpc] [ 9402.872336] ? kthread+0x1d1/0x200 [ 9402.873764] ? set_kthread_struct+0x70/0x70 [ 9402.875459] ? ret_from_fork+0x1f/0x30 [ 9463.045606] Lustre: 12692:0:(osd_handler.c:2191:osd_trans_start()) lustre-MDT0000: credits 30549 > trans_max 3200 [ 9463.072906] Lustre: 12692:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 4/16/0, destroy: 1/4/0 [ 9463.086940] Lustre: 12692:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 2003/2003/0, xattr_set: 3004/28292/0 [ 9463.107828] Lustre: 12692:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 20/142/0, punch: 0/0/0, quota 0/0/0 [ 9463.122244] Lustre: 12692:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 5/84/0, delete: 2/5/0 [ 9463.133582] Lustre: 12692:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 1/1/0, ref_del: 2/2/0 [ 9463.142644] CPU: 3 PID: 12692 Comm: mdt00_004 Kdump: loaded Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 9463.162299] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.17.0-10.fc44 06/10/2025 [ 9463.170441] Call Trace: [ 9463.172842] ? dump_stack+0xbb/0x10e [ 9463.178885] ? osd_trans_start+0x8db/0x9d0 [osd_ldiskfs] [ 9463.186442] ? dt_trans_start+0x1c/0x70 [obdclass] [ 9463.199161] ? top_trans_start+0x4fd/0xd00 [ptlrpc] [ 9463.203329] ? lod_declare_ref_add+0x1a/0x30 [lod] [ 9463.208990] ? dt_declare_ref_add+0x6c/0x200 [obdclass] [ 9463.219029] ? lod_trans_start+0x109/0x4c0 [lod] [ 9463.226678] ? mdd_declare_links_add+0x60/0x90 [mdd] [ 9463.234055] ? mdd_trans_start+0x18/0x30 [mdd] [ 9463.240038] ? mdd_unlink+0x7a4/0x13c0 [mdd] [ 9463.242193] ? mdt_reint_unlink+0x14aa/0x1a30 [mdt] [ 9463.248411] ? mdt_reint_rec+0x139/0x2b0 [mdt] [ 9463.255364] ? mdt_reint_internal+0x693/0xdc0 [mdt] [ 9463.260256] ? mdt_reint+0x163/0x190 [mdt] [ 9463.265824] ? tgt_handle_request0+0x137/0xaf0 [ptlrpc] [ 9463.275930] ? tgt_request_handle+0x575/0x1f70 [ptlrpc] [ 9463.282888] ? ptlrpc_server_handle_request+0x443/0x13b0 [ptlrpc] [ 9463.294968] ? lprocfs_counter_add+0x15b/0x210 [obdclass] [ 9463.304549] ? ptlrpc_main+0xce8/0x1400 [ptlrpc] [ 9463.311421] ? ptlrpc_wait_event+0x690/0x690 [ptlrpc] [ 9463.314196] ? kthread+0x1d1/0x200 [ 9463.319819] ? set_kthread_struct+0x70/0x70 [ 9463.323004] ? ret_from_fork+0x1f/0x30 [ 9553.558516] Lustre: 5942:0:(osd_handler.c:2191:osd_trans_start()) lustre-MDT0000: credits 30573 > trans_max 3200 [ 9553.565850] Lustre: 5942:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 4/16/0, destroy: 1/4/0 [ 9553.571950] Lustre: 5942:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 2003/2003/0, xattr_set: 3004/28292/0 [ 9553.578966] Lustre: 5942:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 20/166/0, punch: 0/0/0, quota 0/0/0 [ 9553.585901] Lustre: 5942:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 5/84/0, delete: 2/5/0 [ 9553.592043] Lustre: 5942:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 1/1/0, ref_del: 2/2/0 [ 9553.598723] CPU: 3 PID: 5942 Comm: mdt00_000 Kdump: loaded Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 9553.605533] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.17.0-10.fc44 06/10/2025 [ 9553.610926] Call Trace: [ 9553.612727] ? dump_stack+0xbb/0x10e [ 9553.615873] ? osd_trans_start+0x8db/0x9d0 [osd_ldiskfs] [ 9553.618088] ? dt_trans_start+0x1c/0x70 [obdclass] [ 9553.620943] ? top_trans_start+0x4fd/0xd00 [ptlrpc] [ 9553.624895] ? lod_declare_ref_add+0x1a/0x30 [lod] [ 9553.628695] ? dt_declare_ref_add+0x6c/0x200 [obdclass] [ 9553.632382] ? lod_trans_start+0x109/0x4c0 [lod] [ 9553.635523] ? mdd_declare_links_add+0x60/0x90 [mdd] [ 9553.638522] ? mdd_trans_start+0x18/0x30 [mdd] [ 9553.643869] ? mdd_unlink+0x7a4/0x13c0 [mdd] [ 9553.650907] ? mdt_reint_unlink+0x14aa/0x1a30 [mdt] [ 9553.657099] ? mdt_reint_rec+0x139/0x2b0 [mdt] [ 9553.665317] ? mdt_reint_internal+0x693/0xdc0 [mdt] [ 9553.676846] ? mdt_reint+0x163/0x190 [mdt] [ 9553.683469] ? tgt_handle_request0+0x137/0xaf0 [ptlrpc] [ 9553.691349] ? tgt_request_handle+0x575/0x1f70 [ptlrpc] [ 9553.697539] ? ptlrpc_server_handle_request+0x443/0x13b0 [ptlrpc] [ 9553.707975] ? lprocfs_counter_add+0x15b/0x210 [obdclass] [ 9553.717302] ? ptlrpc_main+0xce8/0x1400 [ptlrpc] [ 9553.724802] ? ptlrpc_wait_event+0x690/0x690 [ptlrpc] [ 9553.733883] ? kthread+0x1d1/0x200 [ 9553.736601] ? set_kthread_struct+0x70/0x70 [ 9553.738172] ? ret_from_fork+0x1f/0x30 [ 9609.741535] Lustre: DEBUG MARKER: == sanity test 123g: Test for stat-ahead advise ========== 11:21:35 (1783956095) [ 9707.001494] Lustre: DEBUG MARKER: == sanity test 123h: Verify statahead work with the fname pattern via du ========================================================== 11:23:15 (1783956195) [11450.750215] Lustre: DEBUG MARKER: == sanity test 123i: Verify statahead work with the fname indexing pattern ========================================================== 11:52:20 (1783957940) [11582.978276] Lustre: DEBUG MARKER: == sanity test 123j: -ENOENT error from batched statahead be handled correctly ========================================================== 11:54:32 (1783958072) [11584.650842] Lustre: DEBUG MARKER: SKIP: sanity test_123j needs >= 2 MDTs [11586.982117] Lustre: DEBUG MARKER: == sanity test 123k: Verify statahead work with mdtest shared stat() mode ========================================================== 11:54:36 (1783958076) [11589.285524] Lustre: DEBUG MARKER: SKIP: sanity test_123k mdtest not found [11591.447911] Lustre: DEBUG MARKER: == sanity test 123l: Avoid panic when revalidate a local cached entry ========================================================== 11:54:41 (1783958081) [11675.484519] Lustre: DEBUG MARKER: == sanity test 124a: lru resize ================================================================================================= 11:56:05 (1783958165) [11677.164275] Lustre: DEBUG MARKER: create 2000 files at /mnt/lustre/d124a.sanity [11728.019455] Lustre: DEBUG MARKER: NSDIR=ldlm.namespaces.lustre-MDT0000-mdc-ffff9b2d24979000 [11730.028723] Lustre: DEBUG MARKER: NS=ldlm.namespaces.lustre-MDT0000-mdc-ffff9b2d24979000 [11731.706491] Lustre: DEBUG MARKER: LRU=2003 [11733.258855] Lustre: DEBUG MARKER: LIMIT=61549 [11734.821723] Lustre: DEBUG MARKER: LVF=3687400 [11736.415729] Lustre: DEBUG MARKER: OLD_LVF=100 [11738.021426] Lustre: DEBUG MARKER: Sleep 50 sec [11790.450688] Lustre: DEBUG MARKER: Dropped 1079 locks in 50s [11792.144632] Lustre: DEBUG MARKER: unlink 2000 files at /mnt/lustre/d124a.sanity [11831.664470] Lustre: DEBUG MARKER: == sanity test 124b: lru resize (performance test) ================================================================================= 11:58:41 (1783958321) [11958.569597] Lustre: DEBUG MARKER: doing ls -la /mnt/lustre/d124b.sanity/disable_lru_resize 3 times [12156.896446] Lustre: DEBUG MARKER: ls -la time: 196 seconds [12158.871784] Lustre: DEBUG MARKER: lru_size = 400 [12402.597715] Lustre: DEBUG MARKER: doing ls -la /mnt/lustre/d124b.sanity/enable_lru_resize 3 times [12507.811860] Lustre: DEBUG MARKER: ls -la time: 97 seconds [12509.851526] Lustre: DEBUG MARKER: lru_size = 8005 [12511.672607] Lustre: DEBUG MARKER: ls -la is 50% faster with lru resize enabled [12598.541153] Lustre: DEBUG MARKER: == sanity test 124c: LRUR cancel very aged locks ========= 12:11:27 (1783959087) [12632.805848] Lustre: DEBUG MARKER: == sanity test 124d: cancel very aged locks if lru-resize disabled ========================================================== 12:12:02 (1783959122) [12667.046535] Lustre: DEBUG MARKER: == sanity test 124e: LFRU keep priv locks from eviction == 12:12:36 (1783959156) [12719.554070] Lustre: DEBUG MARKER: == sanity test 124f: LFRU priv threshold inc/dec adjustment ========================================================== 12:13:29 (1783959209) [12817.710489] Lustre: DEBUG MARKER: == sanity test 124g: LFRU performance test =============== 12:15:07 (1783959307) [13854.046370] Lustre: DEBUG MARKER: == sanity test 125: don't return EPROTO when a dir has a non-default striping and ACLs ========================================================== 12:32:23 (1783960343) [13863.328876] Lustre: DEBUG MARKER: == sanity test 126: check that the fsgid provided by the client is taken into account ========================================================== 12:32:32 (1783960352) [13872.411804] Lustre: DEBUG MARKER: == sanity test 127a: verify the client stats are sane ==== 12:32:41 (1783960361) [13884.000145] Lustre: DEBUG MARKER: == sanity test 127b: verify the llite client stats are sane ========================================================== 12:32:53 (1783960373) [13891.874757] Lustre: DEBUG MARKER: == sanity test 127c: test llite extent stats with regular [13928.284183] Lustre: DEBUG MARKER: == sanity test 127d: OSC RPC latency histograms for read and write latency ========================================================== 12:33:37 (1783960417) [13944.178267] Lustre: DEBUG MARKER: == sanity test 127e: client IO latency histograms by size ========================================================== 12:33:53 (1783960433) [13964.266907] Lustre: DEBUG MARKER: == sanity test 127f: OST IO latency histograms by size === 12:34:13 (1783960453) [13989.991543] Lustre: DEBUG MARKER: == sanity test 128: interactive lfs for 2 consecutive find's ========================================================== 12:34:39 (1783960479) [13997.578091] Lustre: DEBUG MARKER: == sanity test 129: test directory size limit ================================================================================== 12:34:47 (1783960487) [14015.958531] Lustre: 54125:0:(osd_handler.c:613:osd_ldiskfs_add_entry()) lustre-MDT0000: directory (inode: 513299, FID: [0x20000040a:0xb394:0x0]) is approaching max size limit [14035.699220] Lustre: 54126:0:(osd_handler.c:609:osd_ldiskfs_add_entry()) lustre-MDT0000: directory (inode: 513299, FID: [0x20000040a:0xb394:0x0]) has reached max size limit [14070.555798] Lustre: DEBUG MARKER: == sanity test 130a: FIEMAP (1-stripe file) ============== 12:36:00 (1783960560) [14078.716500] Lustre: DEBUG MARKER: == sanity test 130b: FIEMAP (2-stripe file) ============== 12:36:08 (1783960568) [14088.493731] Lustre: DEBUG MARKER: == sanity test 130c: FIEMAP (2-stripe file with hole) ==== 12:36:18 (1783960578) [14097.682505] Lustre: DEBUG MARKER: == sanity test 130d: FIEMAP (N-stripe file) ============== 12:36:27 (1783960587) [14099.671860] Lustre: DEBUG MARKER: SKIP: sanity test_130d needs >= 3 OSTs [14102.028362] Lustre: DEBUG MARKER: == sanity test 130e: FIEMAP (test continuation FIEMAP calls) ========================================================== 12:36:31 (1783960591) [14173.587727] Lustre: DEBUG MARKER: == sanity test 130f: FIEMAP (unstriped file) ============= 12:37:43 (1783960663) [14181.652225] Lustre: DEBUG MARKER: == sanity test 130g: FIEMAP (overstripe file) ============ 12:37:51 (1783960671) [14225.946260] Lustre: 5942:0:(osd_handler.c:2191:osd_trans_start()) lustre-MDT0000: credits 6549 > trans_max 3200 [14225.950297] Lustre: 5942:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 4/16/0, destroy: 1/4/0 [14225.953569] Lustre: 5942:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 403/403/0, xattr_set: 604/5892/0 [14225.959172] Lustre: 5942:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 20/142/0, punch: 0/0/0, quota 0/0/0 [14225.964422] Lustre: 5942:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 5/84/0, delete: 2/5/0 [14225.972157] Lustre: 5942:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 1/1/0, ref_del: 2/2/0 [14225.977694] CPU: 2 PID: 5942 Comm: mdt00_000 Kdump: loaded Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [14225.987851] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.17.0-10.fc44 06/10/2025 [14225.992392] Call Trace: [14225.993371] ? dump_stack+0xbb/0x10e [14225.995348] ? osd_trans_start+0x8db/0x9d0 [osd_ldiskfs] [14225.997457] ? dt_trans_start+0x1c/0x70 [obdclass] [14226.000319] ? top_trans_start+0x4fd/0xd00 [ptlrpc] [14226.007734] ? lod_declare_ref_add+0x1a/0x30 [lod] [14226.011153] ? dt_declare_ref_add+0x6c/0x200 [obdclass] [14226.017589] ? lod_trans_start+0x109/0x4c0 [lod] [14226.020486] ? mdd_declare_links_add+0x60/0x90 [mdd] [14226.026121] ? mdd_trans_start+0x18/0x30 [mdd] [14226.028414] ? mdd_unlink+0x7a4/0x13c0 [mdd] [14226.032653] ? mdt_reint_unlink+0x14aa/0x1a30 [mdt] [14226.036732] ? mdt_reint_rec+0x139/0x2b0 [mdt] [14226.039376] ? mdt_reint_internal+0x693/0xdc0 [mdt] [14226.041887] ? mdt_reint+0x163/0x190 [mdt] [14226.044950] ? tgt_handle_request0+0x137/0xaf0 [ptlrpc] [14226.047334] ? tgt_request_handle+0x575/0x1f70 [ptlrpc] [14226.050854] ? ptlrpc_server_handle_request+0x443/0x13b0 [ptlrpc] [14226.054399] ? lprocfs_counter_add+0x15b/0x210 [obdclass] [14226.057259] ? ptlrpc_main+0xce8/0x1400 [ptlrpc] [14226.060654] ? ptlrpc_wait_event+0x690/0x690 [ptlrpc] [14226.063475] ? kthread+0x1d1/0x200 [14226.065381] ? set_kthread_struct+0x70/0x70 [14226.067696] ? ret_from_fork+0x1f/0x30 [14233.475924] Lustre: DEBUG MARKER: == sanity test 130h: FIEMAP deadlock ===================== 12:38:42 (1783960722) [14248.892202] Lustre: DEBUG MARKER: == sanity test 130i: FIEMAP (DoM file) =================== 12:38:58 (1783960738) [14300.012653] Lustre: DEBUG MARKER: == sanity test 131a: test iov's crossing stripe boundary for writev/readv ========================================================== 12:39:49 (1783960789) [14307.571638] Lustre: DEBUG MARKER: == sanity test 131b: test append writev ================== 12:39:57 (1783960797) [14314.657681] Lustre: DEBUG MARKER: == sanity test 131c: test read/write on file w/o objects ========================================================== 12:40:04 (1783960804) [14322.621897] Lustre: DEBUG MARKER: == sanity test 131d: test short read ===================== 12:40:12 (1783960812) [14330.543905] Lustre: DEBUG MARKER: == sanity test 131e: test read hitting hole ============== 12:40:20 (1783960820) [14337.902557] Lustre: DEBUG MARKER: == sanity test 133a: Verifying MDT stats ================================================================================================== 12:40:27 (1783960827) [14364.402904] Lustre: DEBUG MARKER: == sanity test 133b: Verifying extra MDT stats ============================================================================================ 12:40:54 (1783960854) [14391.613918] Lustre: DEBUG MARKER: == sanity test 133c: Verifying OST stats ================================================================================================== 12:41:20 (1783960880) [14426.038817] Lustre: DEBUG MARKER: == sanity test 133d: Verifying rename_stats ================================================================================================== 12:41:55 (1783960915) [14471.631503] Lustre: DEBUG MARKER: == sanity test 133e: Verifying OST read_bytes write_bytes nid stats =========================================================================== 12:42:41 (1783960961) [14486.873764] Lustre: DEBUG MARKER: == sanity test 133f: Check reads/writes of client lustre proc files with bad area io ========================================================== 12:42:56 (1783960976) [14514.147967] 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 [14514.166588] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [14517.648938] Lustre: server umount lustre-MDT0000 complete [14526.339924] LustreError: 77795:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1783961018 with bad export cookie 16810184882547222327 [14526.349385] LustreError: MGC192.168.204.152@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [14526.672184] Lustre: server umount lustre-OST0000 complete [14535.589913] Lustre: server umount lustre-OST0001 complete [14551.894306] Lustre: DEBUG MARKER: oleg452-server.virtnet: executing unload_modules_local [14555.618838] Key type lgssc unregistered [14556.066071] LNet: 99226:0:(lib-ptl.c:967:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [14556.071748] LNetError: 99226:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [14556.098397] LNet: Removed LNI 192.168.204.152@tcp [14557.136823] Key type .llcrypt unregistered [14557.140468] Key type ._llcrypt unregistered [14570.721261] Key type ._llcrypt registered [14570.726256] Key type .llcrypt registered [14570.837297] Lustre: DEBUG MARKER: oleg452-server.virtnet: executing load_modules_local [14571.598496] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [14571.640484] alg: No test for adler32 (adler32-zlib) [14572.836288] Lustre: Lustre: Build Version: 2.17.54_162_ga4ac164 [14573.154473] LNet: Added LNI 192.168.204.152@tcp [8/256/0/180] [14574.863270] Key type lgssc registered [14576.006955] Lustre: Echo OBD driver; http://www.lustre.org/ [14594.137176] Lustre: DEBUG MARKER: oleg452-server.virtnet: executing load_modules_local [14608.694539] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [14608.712390] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [14610.301506] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [14615.292755] Lustre: DEBUG MARKER: oleg452-server.virtnet: executing set_default_debug all all [14618.700849] Lustre: 101653:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [14629.351031] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [14629.856347] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [14635.004708] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000402:36834 to 0x240000402:36993) [14636.772282] Lustre: DEBUG MARKER: oleg452-server.virtnet: executing set_default_debug all all [14640.106518] LustreError: 102160:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0001: 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. [14640.137761] LustreError: 102160:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 2 previous similar messages [14645.221988] LustreError: 102162:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0001: 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. [14650.139892] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [14650.343369] LustreError: 102161:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0001: 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. [14650.621360] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [14655.993130] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000402:36488 to 0x280000402:36545) [14658.172504] Lustre: DEBUG MARKER: oleg452-server.virtnet: executing set_default_debug all all [14668.328388] Lustre: DEBUG MARKER: Using TIMEOUT=20 [14672.551489] Lustre: 103830:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [14687.127246] Lustre: DEBUG MARKER: == sanity test 133g: Check reads/writes of server lustre proc files with bad area io ========================================================== 12:46:16 (1783961176) [14695.601163] LNet: 104319:0:(debug.c:376:cfs_str2mask()) unknown mask ''. [14695.601163] mask usage: [+|-] ... [14696.308724] LNet: 104360:0:(debug.c:376:cfs_str2mask()) unknown mask ''. [14696.308724] mask usage: [+|-] ... [14696.320761] LNet: 104360:0:(debug.c:376:cfs_str2mask()) Skipped 5 previous similar messages [14696.397471] Lustre: DEBUG MARKER:  [14696.411623] Lustre: DEBUG MARKER:  [14738.275364] LNet: 105523:0:(debug.c:376:cfs_str2mask()) unknown mask ''. [14738.275364] mask usage: [+|-] ... [14738.287600] LNet: 105523:0:(debug.c:376:cfs_str2mask()) Skipped 3 previous similar messages [14738.981459] Lustre: DEBUG MARKER:  [14738.989529] Lustre: DEBUG MARKER:  [14778.854221] 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 [14778.887520] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [14778.899693] Lustre: Skipped 1 previous similar message [14783.972294] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [14783.992069] Lustre: Skipped 1 previous similar message [14784.695565] Lustre: server umount lustre-MDT0000 complete [14794.629360] LustreError: 103832:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1783961286 with bad export cookie 9592633548507107111 [14794.634774] LustreError: MGC192.168.204.152@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [14794.641292] LustreError: 103832:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [14794.739265] Lustre: server umount lustre-OST0000 complete [14804.561534] Lustre: server umount lustre-OST0001 complete [14825.470773] Lustre: DEBUG MARKER: oleg452-server.virtnet: executing unload_modules_local [14830.107923] Key type lgssc unregistered [14830.682745] LNet: 108388:0:(lib-ptl.c:967:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [14830.700582] LNetError: 108388:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [14830.762361] LNet: Removed LNI 192.168.204.152@tcp [14832.329758] Key type .llcrypt unregistered [14832.331947] Key type ._llcrypt unregistered [14851.062414] Key type ._llcrypt registered [14851.064487] Key type .llcrypt registered [14851.196767] Lustre: DEBUG MARKER: oleg452-server.virtnet: executing load_modules_local [14852.698467] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [14852.718733] alg: No test for adler32 (adler32-zlib) [14853.791755] Lustre: Lustre: Build Version: 2.17.54_162_ga4ac164 [14854.047510] LNet: Added LNI 192.168.204.152@tcp [8/256/0/180] [14855.767215] Key type lgssc registered [14857.101132] Lustre: Echo OBD driver; http://www.lustre.org/ [14875.057781] Lustre: DEBUG MARKER: oleg452-server.virtnet: executing load_modules_local [14891.070620] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [14891.091159] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [14892.625080] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [14897.829459] Lustre: DEBUG MARKER: oleg452-server.virtnet: executing set_default_debug all all [14901.360055] Lustre: 110837:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [14912.939078] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [14913.512970] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [14917.640553] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000402:36834 to 0x240000402:37025) [14920.759223] Lustre: DEBUG MARKER: oleg452-server.virtnet: executing set_default_debug all all [14922.724108] LustreError: 111541:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0001: 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. [14922.753354] LustreError: 111541:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 2 previous similar messages [14927.842511] LustreError: 111342:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0001: 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. [14932.913130] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [14932.962082] LustreError: 111343:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0001: 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. [14933.186091] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [14938.642337] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000402:36488 to 0x280000402:36577) [14940.628138] Lustre: DEBUG MARKER: oleg452-server.virtnet: executing set_default_debug all all [14949.516516] Lustre: DEBUG MARKER: Using TIMEOUT=20 [14953.752176] Lustre: 113012:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [14962.993851] Lustre: DEBUG MARKER: == sanity test 133h: Proc files should end with newlines ========================================================== 12:50:52 (1783961452) [16109.292427] Lustre: DEBUG MARKER: == sanity test 134a: Server reclaims locks when reaching lock_reclaim_threshold ========================================================== 13:09:58 (1783962598) [16132.550729] Lustre: *** cfs_fail_loc=327, val=500*** [16133.481736] Lustre: *** cfs_fail_loc=327, val=500*** [16133.483992] Lustre: Skipped 512 previous similar messages [16172.024837] Lustre: DEBUG MARKER: == sanity test 134b: Server rejects lock request when reaching lock_limit_mb ========================================================== 13:11:01 (1783962661) [16181.794284] Lustre: *** cfs_fail_loc=328, val=500*** [16183.795500] Lustre: *** cfs_fail_loc=328, val=500*** [16183.803531] Lustre: Skipped 122 previous similar messages [16187.797466] Lustre: *** cfs_fail_loc=328, val=500*** [16187.801818] Lustre: Skipped 192 previous similar messages [16191.772885] Lustre: 112829:0:(ldlm_lockd.c:1326:ldlm_handle_enqueue()) @@@ Too many granted locks, reject current enqueue request and let the client retry later req@ffff9d64b9b87480 x1870619034699392/t0(0) o101->395e7eaf-f99c-4019-9e49-1d1fb730be7b@192.168.204.52@tcp:374/0 lens 648/0 e 0 to 0 dl 1783962694 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [16192.910038] Lustre: 110406:0:(ldlm_lockd.c:1326:ldlm_handle_enqueue()) @@@ Too many granted locks, reject current enqueue request and let the client retry later req@ffff9d64cfcf5180 x1870619034700160/t0(0) o101->395e7eaf-f99c-4019-9e49-1d1fb730be7b@192.168.204.52@tcp:375/0 lens 648/0 e 0 to 0 dl 1783962695 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [16193.989238] Lustre: 112829:0:(ldlm_lockd.c:1326:ldlm_handle_enqueue()) @@@ Too many granted locks, reject current enqueue request and let the client retry later req@ffff9d64cfcf4700 x1870619034701056/t0(0) o101->395e7eaf-f99c-4019-9e49-1d1fb730be7b@192.168.204.52@tcp:376/0 lens 648/0 e 0 to 0 dl 1783962696 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [16196.192253] Lustre: *** cfs_fail_loc=328, val=500*** [16196.202721] Lustre: Skipped 188 previous similar messages [16196.214759] Lustre: 110406:0:(ldlm_lockd.c:1326:ldlm_handle_enqueue()) @@@ Too many granted locks, reject current enqueue request and let the client retry later req@ffff9d64cfcf7b80 x1870619034702592/t0(0) o101->395e7eaf-f99c-4019-9e49-1d1fb730be7b@192.168.204.52@tcp:378/0 lens 648/0 e 0 to 0 dl 1783962698 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [16196.255305] Lustre: 110406:0:(ldlm_lockd.c:1326:ldlm_handle_enqueue()) Skipped 1 previous similar message [16201.937771] LustreError: 166944:0:(ldlm_lockd.c:3246:lock_reclaim_threshold_mb_store()) Failed to set lock_reclaim_threshold_mb, rc = -22. [16220.638976] Lustre: DEBUG MARKER: == sanity test 134c: Lock memory accounting includes associated structures ========================================================== 13:11:50 (1783962710) [16238.357181] Lustre: DEBUG MARKER: SKIP: sanity test_135 skipping SLOW test 135 [16240.072880] Lustre: DEBUG MARKER: SKIP: sanity test_136 skipping SLOW test 136 [16242.412305] Lustre: DEBUG MARKER: == sanity test 140: Check reasonable stack depth (shouldn't LBUG) ============================================================== 13:12:12 (1783962732) [16288.001566] Lustre: DEBUG MARKER: == sanity test 150a: truncate/append tests =============== 13:12:57 (1783962777) [16333.530758] Lustre: DEBUG MARKER: == sanity test 150b: Verify fallocate (prealloc) functionality ========================================================== 13:13:43 (1783962823) [16358.208259] Lustre: DEBUG MARKER: == sanity test 150bb: Verify fallocate modes both zero space ========================================================== 13:14:07 (1783962847) [16391.695369] Lustre: DEBUG MARKER: == sanity test 150c: Verify fallocate Size and Blocks ==== 13:14:41 (1783962881) [16414.650363] Lustre: DEBUG MARKER: == sanity test 150d: Verify fallocate Size and Blocks - Non zero start ========================================================== 13:15:04 (1783962904) [16433.277967] Lustre: DEBUG MARKER: == sanity test 150e: Verify 60% of available OST space consumed by fallocate ========================================================== 13:15:23 (1783962923) [16465.434139] Lustre: DEBUG MARKER: == sanity test 150f: Verify fallocate punch functionality ========================================================== 13:15:54 (1783962954) [16489.326254] Lustre: DEBUG MARKER: == sanity test 150g: Verify fallocate punch on large range ========================================================== 13:16:19 (1783962979) [16521.135427] Lustre: DEBUG MARKER: == sanity test 150h: Verify extend fallocate updates the file size ========================================================== 13:16:50 (1783963010) [16532.959067] Lustre: DEBUG MARKER: == sanity test 150ia: Verify fallocate zero-range ZERO functionality ========================================================== 13:17:02 (1783963022) [16557.965993] Lustre: DEBUG MARKER: == sanity test 150ib: Verify fallocate zero-range PREALLOC functionality ========================================================== 13:17:27 (1783963047) [16583.209835] Lustre: DEBUG MARKER: == sanity test 150ic: Verify fallocate LARGE zero PREALLOC functionality ========================================================== 13:17:53 (1783963073) [16584.666828] Lustre: DEBUG MARKER: SKIP: sanity test_150ic only check on DoM component [16587.040023] Lustre: DEBUG MARKER: == sanity test 151: test cache on oss and controls ========================================================================================= 13:17:56 (1783963076) [16606.514884] bash (176353): drop_caches: 1 [16619.749205] Lustre: DEBUG MARKER: == sanity test 152: test read/write with enomem ====================================================================================== 13:18:29 (1783963109) [16628.266983] Lustre: DEBUG MARKER: == sanity test 153: test if fdatasync does not crash ================================================================================= 13:18:37 (1783963117) [16636.736674] Lustre: DEBUG MARKER: == sanity test 154A: lfs path2fid and fid2path basic checks ========================================================== 13:18:46 (1783963126) [16644.653309] Lustre: DEBUG MARKER: == sanity test 154B: verify the ll_decode_linkea tool ==== 13:18:54 (1783963134) [16654.371657] Lustre: DEBUG MARKER: == sanity test 154C: lfs fid2path on OST FID ============= 13:19:03 (1783963143) [16679.975946] Lustre: DEBUG MARKER: == sanity test 154a: Open-by-FID ========================= 13:19:29 (1783963169) [16682.691903] LustreError: 135307:0:(fld_handler.c:268:fld_server_lookup()) srv-lustre-MDT0000: Cannot find sequence 0xf00000400: rc = -2 [16694.929678] Lustre: DEBUG MARKER: == sanity test 154b: Open-by-FID for remote directory ==== 13:19:44 (1783963184) [16697.025952] Lustre: DEBUG MARKER: SKIP: sanity test_154b needs >= 2 MDTs [16698.938706] Lustre: DEBUG MARKER: == sanity test 154c: lfs path2fid and fid2path multiple arguments ========================================================== 13:19:48 (1783963188) [16707.736329] Lustre: DEBUG MARKER: == sanity test 154d: Verify open file fid ================ 13:19:57 (1783963197) [16717.757352] Lustre: DEBUG MARKER: == sanity test 154e: .lustre is not returned by readdir == 13:20:07 (1783963207) [16725.477509] Lustre: DEBUG MARKER: == sanity test 154ea: .lustre is not returned by readdir (2) ========================================================== 13:20:15 (1783963215) [16784.567502] Lustre: DEBUG MARKER: == sanity test 154f: get parent fids by reading link ea == 13:21:13 (1783963273) [16794.501307] Lustre: DEBUG MARKER: == sanity test 154g: various llapi FID tests ============= 13:21:24 (1783963284) [18181.106454] Lustre: DEBUG MARKER: == sanity test 154h: Verify interactive path2fid ========= 13:44:31 (1783964671) [18188.296646] Lustre: DEBUG MARKER: == sanity test 154i: fid2path for path longer than PATH_MAX ========================================================== 13:44:38 (1783964678) [18233.400305] Lustre: DEBUG MARKER: == sanity test 154j: fid2path for long path crossing MDT boundary ========================================================== 13:45:23 (1783964723) [18235.166593] Lustre: DEBUG MARKER: SKIP: sanity test_154j needs >= 2 MDTs [18237.520319] Lustre: DEBUG MARKER: == sanity test 155a: Verify small file correctness: read cache:on write_cache:on ========================================================== 13:45:27 (1783964727) [18253.131683] Lustre: DEBUG MARKER: == sanity test 155b: Verify small file correctness: read cache:on write_cache:off ========================================================== 13:45:43 (1783964743) [18268.807144] Lustre: DEBUG MARKER: == sanity test 155c: Verify small file correctness: read cache:off write_cache:on ========================================================== 13:45:58 (1783964758) [18284.463377] Lustre: DEBUG MARKER: == sanity test 155d: Verify small file correctness: read cache:off write_cache:off ========================================================== 13:46:14 (1783964774) [18303.689976] Lustre: DEBUG MARKER: == sanity test 155e: Verify big file correctness: read cache:on write_cache:on ========================================================== 13:46:33 (1783964793) [18352.157213] Lustre: DEBUG MARKER: == sanity test 155f: Verify big file correctness: read cache:on write_cache:off ========================================================== 13:47:21 (1783964841) [18396.651918] Lustre: DEBUG MARKER: == sanity test 155g: Verify big file correctness: read cache:off write_cache:on ========================================================== 13:48:06 (1783964886) [18439.775716] Lustre: DEBUG MARKER: == sanity test 155h: Verify big file correctness: read cache:off write_cache:off ========================================================== 13:48:49 (1783964929) [18482.523216] Lustre: DEBUG MARKER: == sanity test 156: Verification of tunables ============= 13:49:32 (1783964972) [18491.727526] Lustre: DEBUG MARKER: Turn on read and write cache [18495.734301] Lustre: DEBUG MARKER: Write data and read it back. [18497.996678] Lustre: DEBUG MARKER: Read should be satisfied from the cache. [18503.086429] Lustre: DEBUG MARKER: cache hits: before: 28718, after: 28721 [18504.767468] Lustre: DEBUG MARKER: Read again; it should be satisfied from the cache. [18507.186910] Lustre: DEBUG MARKER: cache hits:: before: 28721, after: 28724 [18508.307827] Lustre: DEBUG MARKER: Turn off the read cache and turn on the write cache [18512.381357] Lustre: DEBUG MARKER: Read again; it should be satisfied from the cache. [18518.078326] Lustre: DEBUG MARKER: cache hits:: before: 28724, after: 28727 [18520.003584] Lustre: DEBUG MARKER: Write data and read it back. [18522.092625] Lustre: DEBUG MARKER: Read should be satisfied from the cache. [18527.151972] Lustre: DEBUG MARKER: cache hits:: before: 28727, after: 28730 [18528.981984] Lustre: DEBUG MARKER: Turn off read and write cache [18532.662667] Lustre: DEBUG MARKER: Write data and read it back [18534.428377] Lustre: DEBUG MARKER: It should not be satisfied from the cache. [18539.274924] Lustre: DEBUG MARKER: cache hits:: before: 28730, after: 28730 [18540.859509] Lustre: DEBUG MARKER: Turn on the read cache and turn off the write cache [18545.262284] Lustre: DEBUG MARKER: Write data and read it back [18547.003353] Lustre: DEBUG MARKER: It should not be satisfied from the cache. [18551.457286] Lustre: DEBUG MARKER: cache hits:: before: 28730, after: 28730 [18553.133903] Lustre: DEBUG MARKER: Read again; it should be satisfied from the cache. [18557.110723] Lustre: DEBUG MARKER: cache hits:: before: 28730, after: 28733 [18565.498554] Lustre: DEBUG MARKER: == sanity test 157a: llapi pool pinning API tests ======== 13:50:55 (1783965055) [18573.778648] Lustre: DEBUG MARKER: == sanity test 157b: lustre.pin inheritance on create ==== 13:51:03 (1783965063) [18582.441614] Lustre: DEBUG MARKER: == sanity test 160a: changelog sanity ==================== 13:51:12 (1783965072) [18585.791691] Lustre: lustre-MDD0000: changelog on [18601.468485] Lustre: Failing over lustre-MDT0000 [18601.852856] Lustre: server umount lustre-MDT0000 complete [18610.573617] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [18610.763341] LustreError: MGC192.168.204.152@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [18611.204633] 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 [18611.373649] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [18611.452283] Lustre: lustre-MDD0000: changelog on [18611.479312] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [18612.178782] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [18613.634182] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [18613.705672] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000402:37868 to 0x240000402:37889) [18613.707867] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000402:37424 to 0x280000402:37441) [18616.814907] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [18616.888503] Lustre: DEBUG MARKER: oleg452-server.virtnet: executing set_default_debug all all [18618.335716] Lustre: 108861:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1783965094/real 1783965094] req@ffff9d649c134380 x1870619052462720/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1783965110 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [18618.913404] Lustre: 108862:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1783965094/real 1783965094] req@ffff9d649c137100 x1870619052462848/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1783965110 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [18621.547748] Lustre: lustre-MDD0000: changelog off [18623.967179] Lustre: 108860:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1783965099/real 1783965099] req@ffff9d649c135c00 x1870619052463104/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1783965115 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [18623.991413] Lustre: 108860:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 1 previous similar message [18632.989893] Lustre: DEBUG MARKER: == sanity test 160b: Verify that very long rename doesn't crash in changelog ========================================================== 13:52:02 (1783965122) [18636.251983] Lustre: lustre-MDD0000: changelog on [18646.071404] Lustre: lustre-MDD0000: changelog off [18649.233328] Lustre: DEBUG MARKER: == sanity test 160c: verify that changelog log catch the truncate event ========================================================== 13:52:19 (1783965139) [18652.905942] Lustre: lustre-MDD0000: changelog on [18664.425313] Lustre: lustre-MDD0000: changelog off [18667.120059] Lustre: DEBUG MARKER: == sanity test 160d: verify that changelog log catch the migrate event ========================================================== 13:52:37 (1783965157) [18668.890462] Lustre: DEBUG MARKER: SKIP: sanity test_160d needs >= 2 MDTs [18670.729596] Lustre: DEBUG MARKER: == sanity test 160e: changelog negative testing (should return errors) ========================================================== 13:52:40 (1783965160) [18674.016166] Lustre: lustre-MDD0000: changelog on [18682.852216] Lustre: lustre-MDD0000: changelog off [18685.501078] Lustre: DEBUG MARKER: == sanity test 160f: changelog garbage collect (timestamped users) ========================================================== 13:52:55 (1783965175) [18689.008966] Lustre: lustre-MDD0000: changelog on [18693.632406] Lustre: DEBUG MARKER: 1783965183: creating first dirs [18713.845590] Lustre: *** cfs_fail_loc=1313, val=3*** [18713.849324] Lustre: 189730:0:(mdd_dir.c:995:mdd_changelog_emrg_cleanup()) lustre-MDD0000: changelog has only 3 free catalog entries [18713.867947] Lustre: 189730:0:(mdd_dir.c:1082:mdd_changelog_store()) lustre-MDD0000: starting changelog garbage collection [18713.883367] Lustre: 193469:0:(mdd_trans.c:163:mdd_chlg_garbage_collect()) lustre-MDD0000: force deregister of changelog user cl6 idle for 22s with 4 unprocessed records [18734.542646] Lustre: lustre-MDD0000: changelog off [18737.203295] Lustre: DEBUG MARKER: == sanity test 160g: changelog garbage collect on idle records ========================================================== 13:53:47 (1783965227) [18740.059373] Lustre: lustre-MDD0000: changelog on [18752.365162] Lustre: 189851:0:(mdd_dir.c:1082:mdd_changelog_store()) lustre-MDD0000: starting changelog garbage collection [18752.391309] Lustre: 195063:0:(mdd_trans.c:163:mdd_chlg_garbage_collect()) lustre-MDD0000: force deregister of changelog user cl8 idle for 10s with 4 unprocessed records [18767.971056] Lustre: lustre-MDD0000: changelog off [18770.212172] Lustre: DEBUG MARKER: == sanity test 160h: changelog gc thread stop upon umount, orphan records delete ========================================================== 13:54:20 (1783965260) [18773.283488] Lustre: lustre-MDD0000: changelog on [18797.276218] Lustre: *** cfs_fail_loc=1316, val=0*** [18797.278906] Lustre: 189732:0:(mdd_dir.c:1082:mdd_changelog_store()) lustre-MDD0000: simulate starting changelog garbage collection [18797.290104] Lustre: 196655:0:(mdd_trans.c:163:mdd_chlg_garbage_collect()) lustre-MDD0000: force deregister of changelog user cl10 idle for 22s with 4 unprocessed records [18799.158100] Lustre: Failing over lustre-MDT0000 [18801.625766] Lustre: lustre-MDT0000: Not available for connect from 192.168.204.52@tcp (stopping) [18804.200394] 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 [18804.204726] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [18804.212079] Lustre: Skipped 2 previous similar messages [18805.651437] Lustre: server umount lustre-MDT0000 complete [18813.825590] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [18813.989602] LustreError: MGC192.168.204.152@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [18814.406490] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [18814.449467] Lustre: 197586:0:(mdd_device.c:626:mdd_changelog_llog_init()) lustre-MDD0000 : orphan changelog records found, starting from index 34 to index 35, being cleared now [18814.471716] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [18819.198444] Lustre: DEBUG MARKER: oleg452-server.virtnet: executing set_default_debug all all [18822.131884] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [18823.666374] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [18823.717884] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000402:37868 to 0x240000402:37921) [18823.721860] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000402:37443 to 0x280000402:37473) [18824.677862] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [18824.686606] Lustre: Skipped 1 previous similar message [18836.620169] Lustre: lustre-MDD0000: changelog off [18839.433121] Lustre: DEBUG MARKER: == sanity test 160i: changelog user register/unregister race ========================================================== 13:55:29 (1783965329) [18842.039407] Lustre: lustre-MDD0000: changelog on [18842.041593] Lustre: Skipped 1 previous similar message [18846.404818] LustreError: 199050:0:(mdd_device.c:2065:mdd_changelog_user_purge()) cfs_race id 1315 sleeping [18849.321221] LustreError: 199183:0:(mdd_device.c:1780:mdd_changelog_user_register()) cfs_fail_race id 1315 waking [18849.330525] LustreError: 199050:0:(mdd_device.c:2065:mdd_changelog_user_purge()) cfs_fail_race id 1315 awake: rc=2086 [18862.846764] Lustre: DEBUG MARKER: == sanity test 160j: client can be umounted while its chanangelog is being used ========================================================== 13:55:52 (1783965352) [18875.800674] Lustre: lustre-MDD0000: changelog off [18875.804368] Lustre: Skipped 2 previous similar messages [18879.314657] Lustre: DEBUG MARKER: == sanity test 160k: Verify that changelog records are not lost ========================================================== 13:56:09 (1783965369) [18883.854888] LustreError: 197600:0:(mdd_dir.c:1050:mdd_changelog_store()) cfs_fail_timeout id 15d sleeping for 3000ms [18886.879226] LustreError: 197600:0:(mdd_dir.c:1050:mdd_changelog_store()) cfs_fail_timeout id 15d awake [18900.057569] Lustre: DEBUG MARKER: == sanity test 160l: Verify that MTIME changelog records contain the parent FID ========================================================== 13:56:30 (1783965390) [18916.624746] Lustre: DEBUG MARKER: == sanity test 160m: Changelog clear race ================ 13:56:46 (1783965406) [18927.022218] LustreError: 197598:0:(mdd_device.c:398:llog_changelog_cancel_cb()) cfs_race id 15f sleeping [18929.044507] LustreError: 197599:0:(mdd_device.c:398:llog_changelog_cancel_cb()) cfs_fail_race id 15f waking [18929.056105] LustreError: 197598:0:(mdd_device.c:398:llog_changelog_cancel_cb()) cfs_fail_race id 15f awake: rc=2982 [18940.222885] Lustre: lustre-MDD0000: changelog off [18940.235282] Lustre: Skipped 2 previous similar messages [18943.515656] Lustre: DEBUG MARKER: == sanity test 160n: Changelog destroy race ============== 13:57:12 (1783965432) [21259.774702] LustreError: 198536:0:(mdd_device.c:412:llog_changelog_cancel_cb()) cfs_race id 16c sleeping [21261.812183] LustreError: 197600:0:(llog_osd.c:1130:llog_osd_next_block()) cfs_fail_race id 16c waking [21261.828402] LustreError: 198536:0:(mdd_device.c:412:llog_changelog_cancel_cb()) cfs_fail_race id 16c awake: rc=2959 [21272.401728] Lustre: lustre-MDD0000: changelog off [21275.062625] Lustre: DEBUG MARKER: == sanity test 160o: changelog user name and mask ======== 14:36:05 (1783967765) [21277.962954] Lustre: lustre-MDD0000: changelog on [21277.967075] Lustre: Skipped 6 previous similar messages [21278.808813] LustreError: 204762:0:(mdd_device.c:1734:mdd_changelog_name_check()) lustre-MDD0000: wrong char '#' in name 'Tt3_-#': rc = -22 [21279.769407] Lustre: 204810:0:(mdd_device.c:1751:mdd_changelog_name_check()) lustre-MDD0000: changelog name test_160o exists already: rc = -17 [21280.734841] LustreError: 204858:0:(mdd_device.c:1743:mdd_changelog_name_check()) lustre-MDD0000: name 'test_160toolongname' is over 16 symbols limit: rc = -36 [21300.257560] Lustre: lustre-MDD0000: changelog off [21305.149720] Lustre: DEBUG MARKER: == sanity test 160p: Changelog orphan cleanup with no users ========================================================== 14:36:34 (1783967794) [21308.600258] Lustre: lustre-MDD0000: changelog on [21313.374343] Lustre: Failing over lustre-MDT0000 [21313.875926] Lustre: server umount lustre-MDT0000 complete [21322.974769] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [21323.178381] LustreError: MGC192.168.204.152@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [21323.521969] 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 [21323.633877] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [21323.705888] Lustre: 206613:0:(mdd_device.c:626:mdd_changelog_llog_init()) lustre-MDD0000 : orphan changelog records found, starting from index 90160 to index 18446744073709551615, being cleared now [21323.735705] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [21326.300075] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [21326.406387] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [21326.451424] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000402:37476 to 0x280000402:37505) [21326.451578] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000402:37924 to 0x240000402:37953) [21328.448761] Lustre: DEBUG MARKER: oleg452-server.virtnet: executing set_default_debug all all [21328.877456] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [21328.891225] Lustre: Skipped 1 previous similar message [21332.959885] Lustre: 108859:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1783967807/real 1783967807] req@ffff9d64a46cdc00 x1870619052990336/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1783967824 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [21332.990554] Lustre: 108859:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 1 previous similar message [21338.079237] Lustre: 108861:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1783967812/real 1783967812] req@ffff9d64a46ce680 x1870619052990720/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1783967829 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [21339.253025] Lustre: DEBUG MARKER: == sanity test 160q: changelog effective mask is DEFMASK if not set ========================================================== 14:37:09 (1783967829) [21342.389943] Lustre: lustre-MDD0000: changelog on [21344.175308] Lustre: lustre-MDD0000: changelog off [21351.056434] Lustre: DEBUG MARKER: == sanity test 160s: changelog garbage collect on idle records * time ========================================================== 14:37:21 (1783967841) [21366.147419] Lustre: 206933:0:(mdd_dir.c:1082:mdd_changelog_store()) lustre-MDD0000: starting changelog garbage collection [21366.177258] Lustre: 208332:0:(mdd_trans.c:163:mdd_chlg_garbage_collect()) lustre-MDD0000: force deregister of changelog user cl2 idle for 864011s with 500000004 unprocessed records [21380.616112] Lustre: DEBUG MARKER: == sanity test 160t: changelog garbage collect on lack of space ========================================================== 14:37:50 (1783967870) [21443.905943] Lustre: *** cfs_fail_loc=18c, val=1210732*** [21443.926171] Lustre: 206627:0:(mdd_dir.c:1082:mdd_changelog_store()) lustre-MDD0000: starting changelog garbage collection [21443.951901] Lustre: 209898:0:(mdd_dir.c:966:mdd_changelog_is_space_safe()) lustre-MDD0000: changelog size 1MB with 1MB space limit [21443.957696] Lustre: 209898:0:(mdd_trans.c:163:mdd_chlg_garbage_collect()) lustre-MDD0000: force deregister of changelog user cl3-user1 idle for 60s with 7506 unprocessed records [21459.448709] Lustre: lustre-MDD0000: changelog off [21459.451138] Lustre: Skipped 1 previous similar message [21491.336732] Lustre: DEBUG MARKER: == sanity test 160u: changelog rename record type name and sname strings are correct ========================================================== 14:39:40 (1783967980) [21495.246725] Lustre: lustre-MDD0000: changelog on [21495.249395] Lustre: Skipped 2 previous similar messages [21506.930445] Lustre: DEBUG MARKER: == sanity test 160v: setattr preserves mtime update despite inter-client clock skew ========================================================== 14:39:56 (1783967996) [21508.617810] Lustre: DEBUG MARKER: SKIP: sanity test_160v need >= 2 clients [21510.516650] Lustre: DEBUG MARKER: == sanity test 160w: lfs changelog --user --mask ========= 14:40:00 (1783968000) [21536.968602] Lustre: DEBUG MARKER: == sanity test 161a: link ea sanity ====================== 14:40:26 (1783968026) [21585.889559] Lustre: DEBUG MARKER: == sanity test 161b: link ea sanity under remote directory ========================================================== 14:41:15 (1783968075) [21587.797895] Lustre: DEBUG MARKER: SKIP: sanity test_161b skipping remote directory test [21590.215600] Lustre: DEBUG MARKER: == sanity test 161c: check CL_RENME[UNLINK] changelog record flags ========================================================== 14:41:19 (1783968079) [21607.837779] Lustre: lustre-MDD0000: changelog off [21607.848594] Lustre: Skipped 2 previous similar messages [21611.640351] Lustre: DEBUG MARKER: == sanity test 161d: create with concurrent .lustre/fid access ========================================================== 14:41:41 (1783968101) [21630.101216] Lustre: DEBUG MARKER: == sanity test 162a: path lookup sanity ================== 14:41:59 (1783968119) [21639.429654] Lustre: DEBUG MARKER: == sanity test 162b: striped directory path lookup sanity ========================================================== 14:42:09 (1783968129) [21641.167313] Lustre: DEBUG MARKER: SKIP: sanity test_162b needs >= 2 MDTs [21643.231858] Lustre: DEBUG MARKER: == sanity test 162c: fid2path works with paths 100 or more directories deep ========================================================== 14:42:13 (1783968133) [21701.773534] Lustre: DEBUG MARKER: == sanity test 165a: ofd access log discovery ============ 14:43:11 (1783968191) [21710.160787] Lustre: Failing over lustre-OST0000 [21710.301455] Lustre: lustre-OST0000: Not available for connect from 192.168.204.52@tcp (stopping) [21710.315647] Lustre: Skipped 1 previous similar message [21710.448914] Lustre: server umount lustre-OST0000 complete [21712.358109] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [21712.367689] 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 [21712.375787] Lustre: Skipped 1 previous similar message [21712.380329] LustreError: 166228:0:(ldlm_lib.c:1192: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. [21715.399236] LustreError: 167295:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.204.52@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [21717.989297] LustreError: 179241:0:(ldlm_lib.c:1192: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. [21720.512731] LustreError: 166400:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.204.52@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [21725.618675] LustreError: 166251:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.204.52@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [21725.664262] LustreError: 166251:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 1 previous similar message [21730.626870] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [21730.741143] Lustre: lustre-OST0000: Not available for connect from 192.168.204.52@tcp (not set up) [21730.867930] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [21730.887061] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [21732.584069] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [21732.960464] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [21732.964364] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [21732.980923] Lustre: Skipped 1 previous similar message [21737.314537] Lustre: DEBUG MARKER: oleg452-server.virtnet: executing set_default_debug all all [21740.992622] Lustre: DEBUG MARKER: == sanity test 165b: ofd access log entries are produced and consumed ========================================================== 14:43:50 (1783968230) [21773.347489] Lustre: Failing over lustre-OST0000 [21774.304355] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [21774.312641] 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 [21774.324393] Lustre: lustre-OST0000: Not available for connect from 0@lo (stopping) [21775.478620] Lustre: server umount lustre-OST0000 complete [21776.845230] LustreError: 179242:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.204.52@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [21776.889805] LustreError: 179242:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 2 previous similar messages [21784.298616] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [21784.769525] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [21784.812797] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [21786.031474] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [21786.689546] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [21786.691050] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [21792.490731] Lustre: DEBUG MARKER: oleg452-server.virtnet: executing set_default_debug all all [21796.886349] Lustre: DEBUG MARKER: == sanity test 165c: full ofd access logs do not block IOs ========================================================== 14:44:46 (1783968286) [21825.852915] Lustre: Failing over lustre-OST0000 [21825.999479] Lustre: server umount lustre-OST0000 complete [21826.039154] 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 [21826.070023] LustreError: 166251:0:(ldlm_lib.c:1192: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. [21826.093720] LustreError: 166251:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 2 previous similar messages [21835.798474] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [21836.349537] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [21836.380634] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [21837.517658] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [21837.937307] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [21837.941393] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [21844.080352] Lustre: DEBUG MARKER: oleg452-server.virtnet: executing set_default_debug all all [21848.967953] Lustre: DEBUG MARKER: == sanity test 165d: ofd_access_log mask works =========== 14:45:38 (1783968338) [21898.985892] Lustre: Failing over lustre-OST0000 [21899.736616] Lustre: lustre-OST0000: Not available for connect from 192.168.204.52@tcp (stopping) [21899.752544] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [21899.761557] 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 [21901.390758] Lustre: server umount lustre-OST0000 complete [21902.821838] LustreError: 166400:0:(ldlm_lib.c:1192: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. [21902.860184] LustreError: 166400:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 3 previous similar messages [21912.461895] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [21912.910307] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [21912.934418] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [21913.963185] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [21914.768461] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [21914.770147] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [21920.051443] Lustre: DEBUG MARKER: oleg452-server.virtnet: executing set_default_debug all all [21924.436772] Lustre: DEBUG MARKER: == sanity test 165e: ofd_access_log MDT index filter works ========================================================== 14:46:54 (1783968414) [21926.439584] Lustre: DEBUG MARKER: SKIP: sanity test_165e needs >= 2 MDTs [21928.525648] Lustre: DEBUG MARKER: == sanity test 165f: ofd_access_log_reader --exit-on-close works ========================================================== 14:46:58 (1783968418) [21936.767481] Lustre: Failing over lustre-OST0000 [21936.793215] LustreError: 221844:0:(ldlm_resource.c:1207:ldlm_resource_complain()) filter-lustre-OST0000_UUID: namespace resource [0x240000402:0xbb64:0x0].0x0 (ffff9d6583ab1b00) refcount nonzero (2) after lock cleanup; forcing cleanup. [21938.667366] 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 [21938.696976] Lustre: lustre-OST0000: Not available for connect from 0@lo (stopping) [21938.705225] Lustre: Skipped 1 previous similar message [21938.961348] Lustre: server umount lustre-OST0000 complete [21959.305459] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [21959.642556] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [21959.663144] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [21960.718699] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [21961.435859] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [21961.443614] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [21966.373915] Lustre: DEBUG MARKER: oleg452-server.virtnet: executing set_default_debug all all [21970.869778] Lustre: DEBUG MARKER: == sanity test 165g: ofd_access_log_reader --keepalive works ========================================================== 14:47:40 (1783968460) [22014.921188] Lustre: Failing over lustre-OST0000 [22014.934901] LustreError: 223410:0:(ldlm_resource.c:1207:ldlm_resource_complain()) filter-lustre-OST0000_UUID: namespace resource [0x240000402:0xbb64:0x0].0x0 (ffff9d6583ab1700) refcount nonzero (2) after lock cleanup; forcing cleanup. [22015.971379] 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 [22015.997582] Lustre: lustre-OST0000: Not available for connect from 0@lo (stopping) [22017.162805] Lustre: server umount lustre-OST0000 complete [22021.094080] LustreError: 179243:0:(ldlm_lib.c:1192: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. [22021.116950] LustreError: 179243:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 11 previous similar messages [22038.557390] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [22038.958795] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [22038.983544] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [22040.171368] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [22040.909489] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [22040.910148] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [22045.405886] Lustre: DEBUG MARKER: oleg452-server.virtnet: executing set_default_debug all all [22049.217383] Lustre: DEBUG MARKER: == sanity test 169: parallel read and truncate should not deadlock ========================================================== 14:48:59 (1783968539) [22051.087516] Lustre: DEBUG MARKER: creating a 10 Mb file [22140.897937] Lustre: DEBUG MARKER: starting reads [22142.844208] Lustre: DEBUG MARKER: truncating the file [22145.032378] Lustre: DEBUG MARKER: killing dd [22146.562582] Lustre: DEBUG MARKER: removing the temporary file [22153.109081] Lustre: DEBUG MARKER: == sanity test 170a: test lctl df to handle corrupted log ========================================================== 14:50:43 (1783968643) [22161.394430] Lustre: DEBUG MARKER: == sanity test 170b: check filename encoding ============= 14:50:51 (1783968651) [22188.119291] Lustre: DEBUG MARKER: == sanity test 171: test libcfs_debug_dumplog_thread stuck in do_exit() ================================================================ 14:51:18 (1783968678) [22197.541230] Lustre: DEBUG MARKER: == sanity test 172: manual device removal with lctl cleanup/detach ================================================================ 14:51:27 (1783968687) [22208.328292] Lustre: DEBUG MARKER: == sanity test 180a: test obdecho on osc ================= 14:51:38 (1783968698) [22210.220061] Lustre: DEBUG MARKER: SKIP: sanity test_180a obdecho on osc is no longer supported [22212.041942] Lustre: DEBUG MARKER: == sanity test 180b: test obdecho directly on obdfilter == 14:51:42 (1783968702) [22215.910752] Lustre: DEBUG MARKER: oleg452-server.virtnet: executing load_module obdecho/obdecho [22234.498525] Lustre: DEBUG MARKER: == sanity test 180c: test huge bulk I/O size on obdfilter, don't LASSERT ========================================================== 14:52:04 (1783968724) [22238.432877] Lustre: DEBUG MARKER: oleg452-server.virtnet: executing load_module obdecho/obdecho [22238.635597] Lustre: Echo OBD driver; http://www.lustre.org/ [22259.780354] Lustre: DEBUG MARKER: == sanity test 181: Test open-unlinked dir ================================================================================== 14:52:29 (1783968749) [22366.718760] Lustre: DEBUG MARKER: == sanity test 182a: Test parallel modify metadata operations from mdc ========================================================== 14:54:16 (1783968856) [22474.383883] Lustre: DEBUG MARKER: == sanity test 182b: Test parallel modify metadata operations from osp ========================================================== 14:56:04 (1783968964) [22475.805357] Lustre: DEBUG MARKER: SKIP: sanity test_182b needs >= 2 MDTs [22477.652855] Lustre: DEBUG MARKER: == sanity test 183: No crash or request leak in case of strange dispositions ================================================================== 14:56:07 (1783968967) [22478.757718] Lustre: *** cfs_fail_loc=148, val=0*** [22485.702596] Lustre: DEBUG MARKER: == sanity test 184a: Basic layout swap =================== 14:56:15 (1783968975) [22496.355371] Lustre: DEBUG MARKER: == sanity test 184b: Forbidden layout swap (will generate errors) ========================================================== 14:56:26 (1783968986) [22503.935876] Lustre: DEBUG MARKER: == sanity test 184c: Concurrent write and layout swap ==== 14:56:34 (1783968994) [22541.090356] Lustre: DEBUG MARKER: == sanity test 184d: allow stripeless layouts swap ======= 14:57:11 (1783969031) [22550.563740] Lustre: DEBUG MARKER: == sanity test 184e: Recreate layout after stripeless layout swaps ========================================================== 14:57:20 (1783969040) [22559.499509] Lustre: DEBUG MARKER: == sanity test 184f: IOC_MDC_GETFILEINFO for files with long names but no striping ========================================================== 14:57:29 (1783969049) [22566.376653] Lustre: DEBUG MARKER: == sanity test 185: Volatile file support ================ 14:57:36 (1783969056) [22574.892141] Lustre: DEBUG MARKER: == sanity test 185a: Volatile file creation in .lustre/fid/ ========================================================== 14:57:44 (1783969064) [22583.990526] Lustre: DEBUG MARKER: == sanity test 187a: Test data version change ============ 14:57:53 (1783969073) [22592.592392] Lustre: DEBUG MARKER: == sanity test 187b: Test data version change on volatile file ========================================================== 14:58:02 (1783969082) [22599.104735] Lustre: DEBUG MARKER: == sanity test 190a: check lfs project -p works with project name ========================================================== 14:58:09 (1783969089) [22605.956861] Lustre: DEBUG MARKER: == sanity test 190b: check lfs find --project works with project name ========================================================== 14:58:16 (1783969096) [22641.107892] Lustre: DEBUG MARKER: == sanity test 190c: check lfs project -p works with u:USERNAME ========================================================== 14:58:50 (1783969130) [22660.515709] Lustre: DEBUG MARKER: == sanity test complete, duration 22389 sec ============== 14:59:09 (1783969149) [22662.841507] Lustre: DEBUG MARKER: === sanity: start cleanup 14:59:12 (1783969152) === [22713.847810] Lustre: DEBUG MARKER: === sanity: finish cleanup 15:00:04 (1783969204) === [22719.971415] 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 [22719.974690] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [22719.997401] Lustre: Skipped 1 previous similar message [22720.014810] Lustre: Skipped 2 previous similar messages [22724.464383] Lustre: server umount lustre-MDT0000 complete [22731.798716] LustreError: 110393:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1783969223 with bad export cookie 15601465333556138835 [22731.808516] LustreError: MGC192.168.204.152@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [22731.813355] LustreError: 110393:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [22731.905725] Lustre: server umount lustre-OST0000 complete [22739.372439] Lustre: server umount lustre-OST0001 complete [22757.730329] Lustre: DEBUG MARKER: oleg452-server.virtnet: executing unload_modules_local [22760.354857] Key type lgssc unregistered [22760.704091] LNet: 237962:0:(lib-ptl.c:967:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [22760.714927] LNetError: 237962:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [22760.731239] LNet: Removed LNI 192.168.204.152@tcp [22761.924287] Key type .llcrypt unregistered [22761.929180] Key type ._llcrypt unregistered