[ 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 512273741 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2400.000 MHz processor [ 0.000000] last_pfn = 0x146e00 max_arch_pfn = 0x400000000 [ 0.000000] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT [ 0.000000] last_pfn = 0xbffce max_arch_pfn = 0x400000000 [ 0.000000] found SMP MP-table at [mem 0x000f54b0-0x000f54bf] [ 0.000000] RAMDISK: [mem 0xbcc54000-0xbffbffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F52D0 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 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: 2829652K/4306352K available (18435K kernel code, 11221K rwdata, 7248K rodata, 2908K init, 18040K bss, 524580K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] ftrace: allocating 41240 entries in 162 pages [ 0.000000] ftrace: allocated 162 pages with 3 groups [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] rcu: RCU event tracing is enabled. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ 0.000000] rcu: RCU callback double-/use-after-free debug enabled. [ 0.000000] Rude variant of Tasks RCU enabled. [ 0.000000] Tracing variant of Tasks RCU enabled. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 0.000000] NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16 [ 0.000000] random: get_random_bytes called from start_kernel+0x622/0x9a8 with crng_init=0 [ 0.001000] Console: colour *CGA 80x25 [ 0.001000] printk: console [ttyS1] enabled [ 0.001000] ACPI: Core revision 20220331 [ 0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.001013] APIC: Switch to symmetric I/O mode setup [ 0.002000] x2apic enabled [ 0.002009] Switched APIC routing to physical x2apic. [ 0.003015] kvm-guest: setup PV IPIs [ 0.006740] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.007000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x22983777dd9, max_idle_ns: 440795300422 ns [ 0.007027] Calibrating delay loop (skipped) preset value.. 4800.00 BogoMIPS (lpj=2400000) [ 0.008012] pid_max: default: 32768 minimum: 301 [ 0.010105] LSM: Security Framework initializing [ 0.011045] Yama: becoming mindful. [ 0.012040] SELinux: Initializing. [ 0.013096] *** VALIDATE selinux *** [ 0.022531] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.027433] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.028153] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.030025] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.031103] *** VALIDATE tmpfs *** [ 0.033318] *** VALIDATE proc *** [ 0.034229] *** VALIDATE cgroup *** [ 0.035009] *** VALIDATE cgroup2 *** [ 0.036265] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.038103] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.039008] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.040028] Spectre V2 : User space: Vulnerable [ 0.041008] Speculative Store Bypass: Vulnerable [ 0.044289] debug: unmapping init [mem 0xffffffffb1c59000-0xffffffffb1c60fff] [ 0.046873] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.047692] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.048022] ... version: 2 [ 0.049011] ... bit width: 48 [ 0.050011] ... generic registers: 4 [ 0.051013] ... value mask: 0000ffffffffffff [ 0.052016] ... max period: 00007fffffffffff [ 0.053014] ... fixed-purpose events: 3 [ 0.054012] ... event mask: 000000070000000f [ 0.055304] rcu: Hierarchical SRCU implementation. [ 0.057619] smp: Bringing up secondary CPUs ... [ 0.058558] x86: Booting SMP configuration: [ 0.059025] .... node #0, CPUs: #1 #2 #3 [ 0.062732] smp: Brought up 1 node, 4 CPUs [ 0.064009] smpboot: Max logical packages: 1 [ 0.065015] smpboot: Total of 4 processors activated (19200.00 BogoMIPS) [ 0.145424] node 0 deferred pages initialised in 77ms [ 0.147136] devtmpfs: initialized [ 0.149286] x86/mm: Memory block size: 128MB [ 0.152753] gcov: version magic: 0x41383552 [ 0.154226] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.155081] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.156279] pinctrl core: initialized pinctrl subsystem [ 0.157130] [ 0.157605] ************************************************************* [ 0.158011] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.159010] ** ** [ 0.160009] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.161010] ** ** [ 0.162008] ** This means that this kernel is built to expose internal ** [ 0.163010] ** IOMMU data structures, which may compromise security on ** [ 0.164009] ** your system. ** [ 0.165010] ** ** [ 0.166014] ** If you see this message and you are not debugging the ** [ 0.167011] ** kernel, report this immediately to your vendor! ** [ 0.168012] ** ** [ 0.169011] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.170012] ************************************************************* [ 0.171852] NET: Registered protocol family 16 [ 0.172468] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.173053] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.174063] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.175724] cpuidle: using governor menu [ 0.177555] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.180569] PCI: Using configuration type 1 for base access [ 0.182228] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.192149] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.195069] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.198170] cryptd: max_cpu_qlen set to 1000 [ 0.201433] ACPI: Added _OSI(Module Device) [ 0.203017] ACPI: Added _OSI(Processor Device) [ 0.206019] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.209017] ACPI: Added _OSI(Processor Aggregator Device) [ 0.218418] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.225637] ACPI: Interpreter enabled [ 0.228083] ACPI: PM: (supports S0 S3 S4 S5) [ 0.230012] ACPI: Using IOAPIC for interrupt routing [ 0.231126] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.236490] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.247016] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.249034] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.252017] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.255084] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.263308] acpiphp: Slot [2] registered [ 0.265116] acpiphp: Slot [5] registered [ 0.267076] acpiphp: Slot [6] registered [ 0.270148] acpiphp: Slot [7] registered [ 0.272124] acpiphp: Slot [8] registered [ 0.274130] acpiphp: Slot [9] registered [ 0.276121] acpiphp: Slot [10] registered [ 0.278136] acpiphp: Slot [3] registered [ 0.280110] acpiphp: Slot [4] registered [ 0.282103] acpiphp: Slot [11] registered [ 0.284170] acpiphp: Slot [12] registered [ 0.286111] acpiphp: Slot [13] registered [ 0.288083] acpiphp: Slot [14] registered [ 0.290083] acpiphp: Slot [15] registered [ 0.292139] acpiphp: Slot [16] registered [ 0.293089] acpiphp: Slot [17] registered [ 0.295083] acpiphp: Slot [18] registered [ 0.297098] acpiphp: Slot [19] registered [ 0.299093] acpiphp: Slot [20] registered [ 0.301100] acpiphp: Slot [21] registered [ 0.303080] acpiphp: Slot [22] registered [ 0.305136] acpiphp: Slot [23] registered [ 0.307140] acpiphp: Slot [24] registered [ 0.308185] acpiphp: Slot [25] registered [ 0.310113] acpiphp: Slot [26] registered [ 0.312116] acpiphp: Slot [27] registered [ 0.313089] acpiphp: Slot [28] registered [ 0.315098] acpiphp: Slot [29] registered [ 0.317114] acpiphp: Slot [30] registered [ 0.318092] acpiphp: Slot [31] registered [ 0.320051] PCI host bridge to bus 0000:00 [ 0.321014] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.324088] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.326022] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.329021] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.332023] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.335046] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.337169] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.340000] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.343307] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.352014] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.357009] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.359036] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.361013] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.363014] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.365600] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.369716] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.373046] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.375804] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.381018] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.396033] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.403016] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.408957] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.417023] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.428016] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.446016] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.456362] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.463015] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.471015] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.492017] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.502000] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.511023] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.521028] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.545014] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.556775] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.563021] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.573016] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.602016] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.617557] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.626014] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.640015] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.660015] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 0.671000] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.679014] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.692015] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.717020] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 0.728865] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.731350] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.734343] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.738976] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.741213] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.745120] iommu: Default domain type: Passthrough [ 0.747415] SCSI subsystem initialized [ 0.749168] ACPI: bus type USB registered [ 0.751096] usbcore: registered new interface driver usbfs [ 0.752147] usbcore: registered new interface driver hub [ 0.753000] usbcore: registered new device driver usb [ 0.753000] pps_core: LinuxPPS API ver. 1 registered [ 0.756013] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.760059] PTP clock support registered [ 0.762060] EDAC MC: Ver: 3.0.0 [ 0.763599] PCI: Using ACPI for IRQ routing [ 0.766024] NetLabel: Initializing [ 0.768011] NetLabel: domain hash size = 128 [ 0.769008] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.771079] NetLabel: unlabeled traffic allowed by default [ 0.773268] vgaarb: loaded [ 0.775245] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.777013] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.783554] clocksource: Switched to clocksource kvm-clock [ 0.902566] VFS: Disk quotas dquot_6.6.0 [ 0.904933] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.908072] *** VALIDATE ramfs *** [ 0.909408] *** VALIDATE hugetlbfs *** [ 0.910954] pnp: PnP ACPI init [ 0.913615] pnp: PnP ACPI: found 6 devices [ 0.930417] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.933522] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.935024] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.937239] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.939677] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.941590] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.943573] NET: Registered protocol family 2 [ 0.946276] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.951846] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.955579] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.959870] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.962881] TCP: Hash tables configured (established 65536 bind 65536) [ 0.965196] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.967609] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.969777] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.973351] NET: Registered protocol family 1 [ 0.976507] RPC: Registered named UNIX socket transport module. [ 0.978836] RPC: Registered udp transport module. [ 0.980783] RPC: Registered tcp transport module. [ 0.982595] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.985107] NET: Registered protocol family 44 [ 0.987924] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.990968] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.993752] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.997938] PCI: CLS 0 bytes, default 64 [ 1.000301] Unpacking initramfs... [ 2.443992] debug: unmapping init [mem 0xffff9a79fcc54000-0xffff9a79fffbffff] [ 2.448353] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.450710] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.453943] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x22983777dd9, max_idle_ns: 440795300422 ns [ 2.948485] Initialise system trusted keyrings [ 2.949987] Key type blacklist registered [ 2.955204] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.964807] zbud: loaded [ 2.968302] *** VALIDATE nfs *** [ 2.969455] *** VALIDATE nfs4 *** [ 2.970825] pstore: using deflate compression [ 2.975683] Platform Keyring initialized [ 3.094328] NET: Registered protocol family 38 [ 3.097291] Key type asymmetric registered [ 3.099930] Asymmetric key parser 'x509' registered [ 3.103334] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 3.109361] io scheduler mq-deadline registered [ 3.111749] io scheduler kyber registered [ 3.113362] io scheduler bfq registered [ 3.116038] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 3.120364] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 3.123122] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 3.125629] ACPI: Power Button [PWRF] [ 3.130731] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 3.136975] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 3.153666] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 3.160160] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 3.177992] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 3.207272] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.236215] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.241946] Non-volatile memory driver v1.3 [ 3.243443] Linux agpgart interface v0.103 [ 3.275204] virtio_blk virtio1: [vda] 146008 512-byte logical blocks (74.8 MB/71.3 MiB) [ 3.280017] vda: detected capacity change from 0 to 74756096 [ 3.296492] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.301474] vdb: detected capacity change from 0 to 1073741824 [ 3.318741] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.321346] vdc: detected capacity change from 0 to 2621440000 [ 3.338619] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.341585] vdd: detected capacity change from 0 to 2621440000 [ 3.358432] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.361036] vde: detected capacity change from 0 to 4294967296 [ 3.375660] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.378197] vdf: detected capacity change from 0 to 4294967296 [ 3.383683] libphy: Fixed MDIO Bus: probed [ 3.388167] usbcore: registered new interface driver usbserial_generic [ 3.390134] usbserial: USB Serial support registered for generic [ 3.391955] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.396420] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.398017] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.400240] mousedev: PS/2 mouse device common for all mice [ 3.403345] rtc_cmos 00:05: RTC can wake from S4 [ 3.410906] rtc_cmos 00:05: registered as rtc0 [ 3.412928] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.415885] intel_pstate: CPU model not supported [ 3.416689] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.424027] hid: raw HID events driver (C) Jiri Kosina [ 3.425975] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.426508] usbcore: registered new interface driver usbhid [ 3.426516] usbhid: USB HID core driver [ 3.426643] drop_monitor: Initializing network drop monitor service [ 3.426780] Initializing XFRM netlink socket [ 3.427292] NET: Registered protocol family 10 [ 3.432777] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.438382] Segment Routing with IPv6 [ 3.448468] NET: Registered protocol family 17 [ 3.451431] mpls_gso: MPLS GSO support [ 3.458853] RAS: Correctable Errors collector initialized. [ 3.462234] AVX version of gcm_enc/dec engaged. [ 3.464453] AES CTR mode by8 optimization enabled [ 3.568434] sched_clock: Marking stable (3568410024, 0)->(4506647586, -938237562) [ 3.573464] registered taskstats version 1 [ 3.576203] Loading compiled-in X.509 certificates [ 3.578875] zswap: loaded using pool lzo/zbud [ 3.612287] Key type big_key registered [ 3.628947] Key type encrypted registered [ 3.630892] ima: No TPM chip found, activating TPM-bypass! [ 3.633119] ima: Allocated hash algorithm: sha1 [ 3.635223] ima: No architecture policies found [ 3.636965] evm: Initialising EVM extended attributes: [ 3.639196] evm: security.selinux [ 3.640688] evm: security.ima [ 3.641496] evm: security.capability [ 3.642700] evm: HMAC attrs: 0x1 [ 3.645480] rtc_cmos 00:05: setting system clock to 2026-08-19 04:53:21 UTC (1787115201) [ 3.653785] debug: unmapping init [mem 0xffffffffb2c03000-0xffffffffb2dfffff] [ 3.657462] debug: unmapping init [mem 0xffffffffb1982000-0xffffffffb1c58fff] [ 3.668144] Write protecting the kernel read-only data: 28672k [ 3.672625] debug: unmapping init [mem 0xffffffffb0003000-0xffffffffb01fffff] [ 3.676223] debug: unmapping init [mem 0xffffffffb0914000-0xffffffffb09fffff] [ 3.716120] 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.726429] systemd[1]: Detected virtualization kvm. [ 3.728605] systemd[1]: Detected architecture x86-64. [ 3.730755] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.758263] systemd[1]: No hostname configured. [ 3.760431] systemd[1]: Set hostname to . [ 3.763178] random: systemd: uninitialized urandom read (16 bytes read) [ 3.765984] systemd[1]: Initializing machine ID from random generator. [ 3.824404] random: ln: uninitialized urandom read (6 bytes read) [ 3.936990] random: systemd: uninitialized urandom read (16 bytes read) [ 3.950801] systemd[1]: Reached target Initrd Root Device. [ OK ] Reached target Initrd Root Device. [ 3.973632] systemd[1]: Listening on Journal Socket. [ OK ] Listening on Journal Socket. [ 3.988336] systemd[1]: Started Memstrack Anylazing Service. [ OK ] Started Memstrack Anylazing Service. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Swap. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Listening on udev Control Socket. Starting Setup Virtual Console... [ OK ] Reached target Slices. Starting Apply Kernel Variables... [ OK ] Reached target Paths. [ OK ] Reached target Local File Systems. Starting Create Volatile Files and Directories... [ OK ] Listening on Journal Socket (/dev/log). Starting Journal Service... [ OK ] Listening on udev Kernel Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Timers. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Setup Virtual Console. [ OK ] Started Apply Kernel Variables. [ OK ] Started Create Volatile Files and Directories. Starting dracut cmdline hook... Starting Create Static Device Nodes in /dev... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started Journal Service. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 4.702231] device-mapper: uevent: version 1.0.3 [ 4.705457] device-mapper: ioctl: 4.46.0-ioctl (2022-02-22) initialised: dm-devel@redhat.com [ OK ] Started dracut pre-udev hook. Starting udev Kernel Device Manager... [ OK ] Started udev Kernel Device Manager. Starting dracut pre-trigger hook... [ OK ] Started dracut pre-trigger hook. Starting udev Coldplug all Devices... Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting dracut initqueue hook... [ 5.484570] random: fast init done [ 5.499119] virtio_net virtio0 ens2: renamed from eth0 [ 5.555147] scsi host0: ata_piix [ 5.581039] scsi host1: ata_piix [ 5.583059] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 5.586026] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 9.359954] dracut-initqueue[587]: RTNETLINK answers: File exists [ 10.153616] random: crng init done [ 10.155982] 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... [ 10.735758] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped target Timers. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Sockets. [ OK ] Stopped target Slices. [ OK ] Stopped target Paths. [ OK ] Stopped target System Initialization. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. Stopping udev Kernel Device Manager... [ OK ] Stopped target Swap. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Closed udev Control Socket. [ OK ] Closed udev Kernel Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 12.134264] printk: systemd: 26 output lines suppressed due to ratelimiting [ 12.402799] SELinux: Disabled at runtime. [ 12.471237] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 12.484517] systemd[1]: Detected virtualization kvm. [ 12.487439] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 13.058563] systemd[1]: initrd-switch-root.service: Succeeded. [ 13.063138] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 13.071512] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 13.076782] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 13.081355] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 13.092571] systemd[1]: Starting Journal Service... Starting Journal Service... [ 13.101801] systemd[1]: Created slice system-serial\x2dgetty.slice. [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Listening on udev Kernel Socket. [ OK ] Listening on RPCbind Server Activation Socket. [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Created slice system-getty.slice. [ OK ] Listening on udev Control Socket. Starting Remount Root and Kernel File Systems... [ OK ] Started Forward Password Requests to Wall Directory Watch. Starting Apply Kernel Variables... [ OK ] Created slice User and Session Slice. Mounting Kernel Debug File System... Starting udev Coldplug all Devices... [ OK ] Listening on Process Core Dump Socket. [ OK ] Reached target rpc_pipefs.target. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Listening on initctl Compatibility Named Pipe. Activating swap /dev/disk/by-label/SWAP... [ OK ] Reached target Slices. Mounting POSIX Message Queue File System... [ OK ] Reached target RPC Port Mapper. Mounting Huge Pages File System... [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd Root File System. [ OK ] Stopped target Initrd File Systems. [ 13.317223] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS [ OK ] Started Journal Service. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Started Apply Kernel Variables. [ OK ] Mounted Kernel Debug File System. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Mounted Huge Pages File System. [ OK ] Reached target Swap. Starting Configure read-only root support... Starting Create Static Device Nodes in /dev... Starting Flush Journal to Persistent Storage... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Reached target Local File Systems (Pre). Mounting /mnt... Mounting /home/green/git/lustre-release... Starting udev Kernel Device Manager... [ OK ] Started udev Coldplug all Devices. [ OK ] Mounted /mnt. [ 13.649298] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 13.982704] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 13.995842] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 14.151761] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 14.170714] EDAC sbridge: Ver: 1.1.2 [ 16.251153] Key type dns_resolver registered [ 16.610167] NFS: Registering the id_resolver key type [ 16.615318] Key type id_resolver registered [ 16.617048] Key type id_legacy registered [ OK ] Started Configure read-only root support. [ OK ] Reached target Local File Systems. Starting Rebuild Dynamic Linker Cache... Starting Mark the need to relabel after reboot... Starting Create Volatile Files and Directories... Starting Load/Save Random Seed... [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Load/Save Random Seed. Starting RPC Bind... Starting Update UTMP about System Boot/Shutdown... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. [ OK ] Started irqbalance daemon. [ OK ] Started D-Bus System Message Bus. Starting Login Service... [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Started dnf makecache --timer. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Reached target Timers. Starting Restore /run/initramfs on shutdown... Starting Network Manager... [ OK ] Reached target sshd-keygen.target. [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Login Service. [ OK ] Started Network Manager. [ OK ] Reached target Network. Starting Dynamic System Tuning Daemon... Starting OpenSSH server daemon... Starting GSSAPI Proxy Daemon... Starting Network Manager Wait Online... Starting Hostname Service... [ OK ] Started OpenSSH server daemon. [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... [ OK ] Started Permit User Sessions. [ OK ] Started Command Scheduler. [ OK ] Started Getty on tty1. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Serial Getty on ttyS1. [ OK ] Reached target Login Prompts. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting Crash recovery kernel arming... Starting Notify NFS peers of a restart... Starting System Logging Service... [ 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 oleg438-server login: [ 44.132759] libcfs: loading out-of-tree module taints kernel. [ 44.157387] Key type ._llcrypt registered [ 44.159273] Key type .llcrypt registered [ 44.213796] Lustre: DEBUG MARKER: oleg438-server.virtnet: executing set_hostid [ 61.683685] Lustre: DEBUG MARKER: oleg438-server.virtnet: executing load_modules_local [ 64.035829] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 64.083249] alg: No test for adler32 (adler32-zlib) [ 65.549756] Lustre: Lustre: Build Version: 2.17.56_4_gb718cad [ 66.250780] LNet: Added LNI 192.168.204.138@tcp [8/256/0/180] [ 68.224901] Key type lgssc registered [ 70.714134] Lustre: Echo OBD driver; http://www.lustre.org/ [ 95.191379] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 147.516511] Lustre: DEBUG MARKER: oleg438-server.virtnet: executing load_modules_local [ 162.165696] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 162.227403] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 163.718767] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 163.782995] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 164.022840] Lustre: lustre-MDT0000: new disk, initializing [ 164.192810] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 164.221759] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 165.711176] hrtimer: interrupt took 5248892 ns [ 169.977218] Lustre: DEBUG MARKER: oleg438-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 186.085649] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 186.204584] Lustre: 6516:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 186.307714] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 186.311722] Lustre: Skipped 1 previous similar message [ 186.442914] Lustre: lustre-MDT0001: new disk, initializing [ 186.576737] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 186.666949] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 186.683080] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 192.794994] Lustre: DEBUG MARKER: oleg438-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 199.048495] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 210.528540] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 210.878217] Lustre: lustre-OST0000: new disk, initializing [ 210.887373] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 210.906947] Lustre: 8456:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 211.024747] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 212.014453] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 212.044835] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 212.171740] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 218.478954] Lustre: DEBUG MARKER: oleg438-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 232.803225] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 233.039942] Lustre: lustre-OST0001: new disk, initializing [ 233.049706] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 233.059486] Lustre: 9529:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 233.153590] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 240.654491] Lustre: DEBUG MARKER: oleg438-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 243.317637] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 243.342112] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 243.432414] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 254.472580] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 264.643711] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 273.798384] Lustre: DEBUG MARKER: oleg438-server.virtnet: executing check_logdir /tmp/testlogs/ [ 278.834498] Lustre: DEBUG MARKER: oleg438-server.virtnet: executing yml_node [ 282.972813] Lustre: DEBUG MARKER: Client: 2.17.56.4 [ 286.345133] Lustre: DEBUG MARKER: MDS: 2.17.56.4 [ 289.286202] Lustre: DEBUG MARKER: OSS: 2.17.56.4 [ 290.837177] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity ============----- Wed Aug 19 00:58:07 EDT 2026 [ 309.945414] Lustre: DEBUG MARKER: - need MDS1_VERSION <= 2.16.61-1-g89cf292a8c2 (34682884 <= 34618625) for LU-18938, skip 360 [ 311.724255] Lustre: DEBUG MARKER: - need MDS1_VERSION < v2_14_55-100-g8a84c7f9c7 (34682884 < 34486116) for LU-14927, skip 0f [ 313.873717] Lustre: DEBUG MARKER: - need OST1_VERSION < v2_17_50-410-gbd8e7b9555 (34682884 < 34681754) for LU-12550, skip 216 [ 315.779962] Lustre: DEBUG MARKER: excepting tests: 42a 42c 42b 118c 118d 407 119i 216 817 411a [ 317.313461] Lustre: DEBUG MARKER: skipping tests SLOW=no: 27m 60i 64b 68 71 135 136 230d 300o 842 51c 51e 834 [ 319.013210] Lustre: DEBUG MARKER: === sanity: start setup 00:58:35 (1787115515) === [ 325.381439] Lustre: DEBUG MARKER: oleg438-client.virtnet: executing check_config_client /mnt/lustre [ 347.887995] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 352.011585] Lustre: 13536:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 356.284697] Lustre: DEBUG MARKER: oleg438-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 363.407175] Lustre: DEBUG MARKER: === sanity: finish setup 00:59:19 (1787115559) === [ 371.389655] Lustre: DEBUG MARKER: == sanity test 60a: llog_test run from kernel module and test llog_reader ========================================================== 00:59:27 (1787115567) [ 375.620268] Lustre: DEBUG MARKER: SKIP: sanity test_60a missing subtest run-llog.sh [ 378.321490] Lustre: DEBUG MARKER: == sanity test 60b: limit repeated messages from CERROR/CWARN ========================================================== 00:59:33 (1787115573) [ 389.952212] Lustre: DEBUG MARKER: == sanity test 60c: unlink file when mds full ============ 00:59:45 (1787115585) [ 608.069648] Lustre: DEBUG MARKER: == sanity test 60d: test printk console message masking == 01:03:24 (1787115804) [ 615.552365] Lustre: DEBUG MARKER: == sanity test 60e: no space while new llog is being created ========================================================== 01:03:31 (1787115811) [ 617.128562] Lustre: *** cfs_fail_loc=15b, val=0*** [ 617.133423] Lustre: *** cfs_fail_loc=15b, val=0*** [ 617.143452] LustreError: 10107:0:(llog_cat_server.c:483:llog_cat_add_rec()) lustre-OST0000-osc-MDT0000: initialization error: rc = -28 [ 624.230592] Lustre: DEBUG MARKER: == sanity test 60f: change debug_path works ============== 01:03:40 (1787115820) [ 632.207455] Lustre: DEBUG MARKER: == sanity test 60g: transaction abort won't cause MDT hung ========================================================== 01:03:48 (1787115828) [ 633.501271] Lustre: *** cfs_fail_loc=19a, val=0*** [ 634.582983] Lustre: *** cfs_fail_loc=19a, val=0*** [ 634.584862] ------------[ cut here ]------------ [ 634.594569] do not call blocking ops when !TASK_RUNNING; state=402 set at [<0000000055d26c75>] distribute_txn_commit_thread+0x95/0x1000 [ptlrpc] [ 634.601319] WARNING: CPU: 3 PID: 7478 at kernel/sched/core.c:7471 __might_sleep+0x9d/0xc0 [ 634.607475] Modules linked in: zfs(O) spl(O) lustre(O) osp(O) ofd(O) lod(O) mdt(O) mdd(O) mgs(O) osd_ldiskfs(O) ldiskfs(O) lquota(O) lfsck(O) obdecho(O) mgc(O) mdc(O) lov(O) osc(O) lmv(O) ec(O) fid(O) fld(O) ptlrpc_gss(O) ptlrpc(O) obdclass(O) ksocklnd(O) lnet(O) libcfs(O) dm_flakey rpcsec_gss_krb5 auth_rpcgss nfsv4 dns_resolver intel_rapl_msr intel_rapl_common sb_edac rapl pcspkr i2c_piix4 squashfs ata_generic crct10dif_pclmul crc32_pclmul crc32c_intel ghash_clmulni_intel ata_piix serio_raw libata dm_mirror dm_region_hash dm_log dm_mod sha512_ssse3 sha512_generic [ 634.655555] CPU: 3 PID: 7478 Comm: dist_txn-1 Kdump: loaded Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 634.670076] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.17.0-10.fc44 06/10/2025 [ 634.681593] RIP: 0010:__might_sleep+0x9d/0xc0 [ 634.689944] Code: a8 12 00 00 48 c7 c7 a8 56 78 b0 48 83 05 ba 89 df 02 01 c6 05 2f 83 52 02 01 48 89 d1 e8 a7 50 fb ff 48 83 05 ab 89 df 02 01 <0f> 0b 48 83 05 a9 89 df 02 01 48 83 05 a9 89 df 02 01 eb 9b 66 66 [ 634.706243] RSP: 0000:ffffbe8881c6fd78 EFLAGS: 00010202 [ 634.710388] RAX: 0000000000000000 RBX: ffffffffb07add7d RCX: 0000000000000000 [ 634.722630] RDX: ffff9a7a821ae640 RSI: ffff9a7a8219e5a8 RDI: ffff9a7a8219e5a8 [ 634.730841] RBP: 00000000000000e2 R08: 0000000000000000 R09: c0000000ffff7fff [ 634.735317] R10: 0000000000000001 R11: ffffbe8881c6fb68 R12: 0000000000000000 [ 634.741316] R13: 0000000000000001 R14: 0000000000000058 R15: ffffffffc0f00ce8 [ 634.744992] FS: 0000000000000000(0000) GS:ffff9a7a82180000(0000) knlGS:0000000000000000 [ 634.751871] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [ 634.756198] CR2: 00007f2f27016aa8 CR3: 0000000075e16003 CR4: 0000000000170ee0 [ 634.765558] Call Trace: [ 634.768963] ? show_regs.cold.9+0x22/0x2f [ 634.771543] ? __warn+0xc8/0x150 [ 634.774688] ? __might_sleep+0x9d/0xc0 [ 634.779301] ? report_bug+0x113/0x140 [ 634.783238] ? do_error_trap+0xb6/0x130 [ 634.790295] ? do_invalid_op+0x46/0x60 [ 634.793136] ? __might_sleep+0x9d/0xc0 [ 634.794370] ? invalid_op+0x14/0x20 [ 634.798285] ? distribute_txn_commit_batchid_update+0x68/0x8f0 [ptlrpc] [ 634.805481] ? __might_sleep+0x9d/0xc0 [ 634.807293] ? __might_sleep+0x95/0xc0 [ 634.811372] slab_pre_alloc_hook.constprop.64+0x11f/0x1d0 [ 634.813694] kmem_cache_alloc_trace+0x5b/0x440 [ 634.817072] ? top_multiple_thandle_destroy+0x3a2/0x420 [ptlrpc] [ 634.823778] distribute_txn_commit_batchid_update+0x68/0x8f0 [ptlrpc] [ 634.834332] distribute_txn_commit_thread+0xa97/0x1000 [ptlrpc] [ 634.840013] ? distribute_txn_commit_batchid_update+0x8f0/0x8f0 [ptlrpc] [ 634.848269] kthread+0x1d1/0x200 [ 634.849758] ? set_kthread_struct+0x70/0x70 [ 634.852311] ret_from_fork+0x1f/0x30 [ 634.854327] ---[ end trace aa96cd10527bfb55 ]--- [ 635.786379] Lustre: *** cfs_fail_loc=19a, val=0*** [ 638.911438] Lustre: *** cfs_fail_loc=19a, val=0*** [ 638.913235] Lustre: Skipped 2 previous similar messages [ 643.879037] Lustre: *** cfs_fail_loc=19a, val=0*** [ 643.880782] Lustre: Skipped 3 previous similar messages [ 653.019910] Lustre: *** cfs_fail_loc=19a, val=0*** [ 653.023627] Lustre: Skipped 8 previous similar messages [ 669.275556] Lustre: *** cfs_fail_loc=19a, val=0*** [ 669.281910] Lustre: Skipped 15 previous similar messages [ 701.647469] Lustre: *** cfs_fail_loc=19a, val=0*** [ 701.660258] Lustre: Skipped 31 previous similar messages [ 752.242334] Lustre: DEBUG MARKER: == sanity test 60h: striped directory with missing stripes can be accessed ========================================================== 01:05:47 (1787115947) [ 753.414986] Lustre: *** cfs_fail_loc=188, val=0*** [ 757.159847] Lustre: *** cfs_fail_loc=189, val=0*** [ 768.951963] Lustre: DEBUG MARKER: SKIP: sanity test_60i skipping SLOW test 60i [ 771.666443] Lustre: DEBUG MARKER: == sanity test 60j: llog_reader reports corruptions ====== 01:06:07 (1787115967) [ 778.978423] Lustre: lustre-MDD0000: changelog on [ 781.929078] Lustre: lustre-MDD0001: changelog on [ 791.503416] Lustre: DEBUG MARKER: SKIP: sanity test_60j path oi.1/0x1:0xc:0x0 is not in 'O/1/d/' format [ 794.940580] Lustre: lustre-MDD0001: changelog off [ 798.016650] Lustre: lustre-MDD0000: changelog off [ 800.745126] Lustre: DEBUG MARKER: == sanity test 61a: mmap() writes don't make sync hang ========================================================================== 01:06:36 (1787115996) [ 808.483288] Lustre: DEBUG MARKER: == sanity test 61b: mmap() of unstriped file is successful ========================================================== 01:06:44 (1787116004) [ 816.673045] Lustre: DEBUG MARKER: == sanity test 63a: Verify oig_wait interruption does not crash ================================================================= 01:06:52 (1787116012) [ 889.785276] Lustre: DEBUG MARKER: == sanity test 63b: async write errors should be returned to fsync ============================================================= 01:08:05 (1787116085) [ 906.189545] Lustre: DEBUG MARKER: == sanity test 63c: test sync_on_close=1 ================= 01:08:21 (1787116101) [ 926.000553] Lustre: DEBUG MARKER: == sanity test 64a: verify filter grant calculations (in kernel) =============================================================== 01:08:42 (1787116122) [ 936.963387] Lustre: DEBUG MARKER: SKIP: sanity test_64b skipping SLOW test 64b [ 939.192863] Lustre: DEBUG MARKER: == sanity test 64c: verify grant shrink ================== 01:08:55 (1787116135) [ 951.182459] Lustre: DEBUG MARKER: == sanity test 64d: check grant limit exceed ============= 01:09:06 (1787116146) [ 1022.667654] Lustre: DEBUG MARKER: == sanity test 64e: check grant consumption (no grant allocation) ========================================================== 01:10:18 (1787116218) [ 1028.933941] Lustre: *** cfs_fail_loc=725, val=0*** [ 1041.783089] Lustre: *** cfs_fail_loc=725, val=0*** [ 1053.092953] Lustre: DEBUG MARKER: == sanity test 64f: check grant consumption (with grant allocation) ========================================================== 01:10:48 (1787116248) [ 1069.965048] Lustre: DEBUG MARKER: == sanity test 64g: grant shrink on MDT ================== 01:11:05 (1787116265) [ 1101.039930] Lustre: DEBUG MARKER: == sanity test 64h: grant shrink on read ================= 01:11:37 (1787116297) [ 1125.302259] Lustre: DEBUG MARKER: == sanity test 64i: shrink on reconnect ================== 01:12:00 (1787116320) [ 1139.465820] Lustre: *** cfs_fail_loc=513, val=17*** [ 1139.470740] LustreError: 8438:0:(service.c:2341:ptlrpc_server_handle_req_in()) drop incoming rpc opc 17, x1873926160447104 [ 1141.759598] Lustre: Failing over lustre-OST0000 [ 1142.262826] Lustre: server umount lustre-OST0000 complete [ 1144.289831] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 1144.291915] Lustre: lustre-OST0000-osc-MDT0001: Connection to lustre-OST0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 1144.301231] LustreError: Skipped 1 previous similar message [ 1147.261697] LustreError: 14683:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.204.38@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1147.291586] LustreError: 14683:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 4 previous similar messages [ 1149.929634] LustreError: 14677: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. [ 1149.958682] LustreError: 14677:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 1 previous similar message [ 1152.372090] LustreError: 8439:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.204.38@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1155.044042] LustreError: 14683: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. [ 1155.073771] LustreError: 14683:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 1 previous similar message [ 1160.168295] LustreError: 14677: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. [ 1160.182218] LustreError: 14677:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 2 previous similar messages [ 1162.331142] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 1162.602083] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [ 1162.623135] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 1163.690333] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 1164.766362] Lustre: lustre-OST0000: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [ 1164.769388] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 1169.610937] Lustre: DEBUG MARKER: oleg438-server.virtnet: executing set_default_debug all all [ 1179.529948] Lustre: DEBUG MARKER: oleg438-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 1181.160192] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 1193.044842] Lustre: DEBUG MARKER: == sanity test 64j: check grants on re-done rpc ========== 01:13:09 (1787116389) [ 1194.769800] Lustre: *** cfs_fail_loc=256, val=0*** [ 1205.228237] Lustre: DEBUG MARKER: == sanity test 65a: directory with no stripe info ======== 01:13:21 (1787116401) [ 1214.199550] Lustre: DEBUG MARKER: == sanity test 65b: directory setstripe -S stripe_size*2 -i 0 -c 1 ========================================================== 01:13:30 (1787116410) [ 1223.284739] Lustre: DEBUG MARKER: == sanity test 65c: directory setstripe -S stripe_size*4 -i 1 -c 1 ========================================================== 01:13:39 (1787116419) [ 1231.873964] Lustre: DEBUG MARKER: == sanity test 65d: directory setstripe -S stripe_size -c stripe_count ========================================================== 01:13:47 (1787116427) [ 1240.108209] Lustre: DEBUG MARKER: == sanity test 65e: directory setstripe defaults ========= 01:13:56 (1787116436) [ 1246.861271] Lustre: DEBUG MARKER: == sanity test 65f: dir setstripe permission (should return error) ============================================================= 01:14:03 (1787116443) [ 1254.601280] Lustre: DEBUG MARKER: == sanity test 65g: directory setstripe -d =============== 01:14:10 (1787116450) [ 1261.796454] Lustre: DEBUG MARKER: == sanity test 65h: directory stripe info inherit ============================================================================== 01:14:17 (1787116457) [ 1270.117740] Lustre: DEBUG MARKER: == sanity test 65i: various tests to set root directory striping ========================================================== 01:14:26 (1787116466) [ 1279.223702] Lustre: DEBUG MARKER: == sanity test 65j: set default striping on root directory (bug 6367)=========================================================== 01:14:35 (1787116475) [ 1287.754916] Lustre: DEBUG MARKER: == sanity test 65k: validate manual striping works properly with deactivated OSCs ========================================================== 01:14:43 (1787116483) [ 1289.956415] Lustre: lustre-OST0000-osc-MDT0001: Connection to lustre-OST0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 1289.972143] Lustre: Skipped 1 previous similar message [ 1289.981034] Lustre: lustre-OST0000: Client lustre-MDT0001-mdtlov_UUID (at 0@lo) reconnecting [ 1290.000872] Lustre: lustre-OST0000-osc-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1290.006965] Lustre: Skipped 1 previous similar message [ 1290.745327] Lustre: lustre-OST0000: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnecting [ 1291.531446] Lustre: lustre-OST0001-osc-MDT0001: Connection to lustre-OST0001 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 1291.549832] Lustre: Skipped 1 previous similar message [ 1291.554337] Lustre: lustre-OST0001-osc-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1291.567914] Lustre: Skipped 1 previous similar message [ 1292.429184] Lustre: lustre-OST0001: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnecting [ 1292.433833] Lustre: Skipped 1 previous similar message [ 1313.632069] Lustre: setting import lustre-OST0000_UUID INACTIVE by administrator request [ 1332.469980] Lustre: lustre-OST0000-osc-MDT0001: Connection to lustre-OST0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 1332.485565] Lustre: Skipped 1 previous similar message [ 1332.494536] Lustre: lustre-OST0000: Client lustre-MDT0001-mdtlov_UUID (at 0@lo) reconnecting [ 1332.506539] LustreError: lustre-OST0000-osc-MDT0001: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 1332.534135] Lustre: lustre-OST0000-osc-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1332.544663] Lustre: Skipped 1 previous similar message [ 1337.355387] Lustre: DEBUG MARKER: oleg438-server.virtnet: executing wait_import_state FULL os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid 50 [ 1337.600899] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid in FULL state after 0 sec [ 1342.226570] Lustre: DEBUG MARKER: oleg438-server.virtnet: executing wait_import_state FULL os[cp].lustre-OST0000-osc-MDT0001.ost_server_uuid 50 [ 1342.385403] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0001.ost_server_uuid in FULL state after 0 sec [ 1365.439378] Lustre: setting import lustre-OST0000_UUID INACTIVE by administrator request [ 1385.530912] 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 [ 1385.550169] Lustre: lustre-OST0000: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnecting [ 1385.565694] LustreError: lustre-OST0000-osc-MDT0000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 1385.593586] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 1390.465128] Lustre: DEBUG MARKER: oleg438-server.virtnet: executing wait_import_state FULL os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid 50 [ 1390.709683] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid in FULL state after 0 sec [ 1396.481786] Lustre: DEBUG MARKER: oleg438-server.virtnet: executing wait_import_state FULL os[cp].lustre-OST0000-osc-MDT0001.ost_server_uuid 50 [ 1396.694665] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0001.ost_server_uuid in FULL state after 0 sec [ 1418.877711] Lustre: setting import lustre-OST0001_UUID INACTIVE by administrator request [ 1437.332343] Lustre: lustre-OST0001-osc-MDT0001: Connection to lustre-OST0001 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 1437.341735] Lustre: lustre-OST0001: Client lustre-MDT0001-mdtlov_UUID (at 0@lo) reconnecting [ 1437.347709] LustreError: lustre-OST0001-osc-MDT0001: This client was evicted by lustre-OST0001; in progress operations using this service will fail. [ 1437.354682] Lustre: lustre-OST0001-osc-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1443.134856] Lustre: DEBUG MARKER: oleg438-server.virtnet: executing wait_import_state FULL os[cp].lustre-OST0001-osc-MDT0000.ost_server_uuid 50 [ 1443.409586] Lustre: DEBUG MARKER: os[cp].lustre-OST0001-osc-MDT0000.ost_server_uuid in FULL state after 0 sec [ 1448.156537] Lustre: DEBUG MARKER: oleg438-server.virtnet: executing wait_import_state FULL os[cp].lustre-OST0001-osc-MDT0001.ost_server_uuid 50 [ 1448.377415] Lustre: DEBUG MARKER: os[cp].lustre-OST0001-osc-MDT0001.ost_server_uuid in FULL state after 0 sec [ 1469.971197] Lustre: setting import lustre-OST0001_UUID INACTIVE by administrator request [ 1487.980179] 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 [ 1487.993536] Lustre: lustre-OST0001: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnecting [ 1487.998530] LustreError: lustre-OST0001-osc-MDT0000: This client was evicted by lustre-OST0001; in progress operations using this service will fail. [ 1488.007951] Lustre: lustre-OST0001-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 1492.740872] Lustre: DEBUG MARKER: oleg438-server.virtnet: executing wait_import_state FULL os[cp].lustre-OST0001-osc-MDT0000.ost_server_uuid 50 [ 1492.959131] Lustre: DEBUG MARKER: os[cp].lustre-OST0001-osc-MDT0000.ost_server_uuid in FULL state after 0 sec [ 1497.510625] Lustre: DEBUG MARKER: oleg438-server.virtnet: executing wait_import_state FULL os[cp].lustre-OST0001-osc-MDT0001.ost_server_uuid 50 [ 1497.719808] Lustre: DEBUG MARKER: os[cp].lustre-OST0001-osc-MDT0001.ost_server_uuid in FULL state after 0 sec [ 1505.044571] Lustre: DEBUG MARKER: == sanity test 65l: lfs find on -1 stripe dir ================================================================================== 01:18:21 (1787116701) [ 1512.805459] Lustre: DEBUG MARKER: == sanity test 65m: normal user can't set filesystem default stripe ========================================================== 01:18:29 (1787116709) [ 1518.702765] Lustre: DEBUG MARKER: == sanity test 65n: don't inherit default layout from root for new subdirectories ========================================================== 01:18:35 (1787116715) [ 1550.209679] Lustre: DEBUG MARKER: == sanity test 65o: pool inheritance for mdt component === 01:19:06 (1787116746) [ 1578.353888] Lustre: DEBUG MARKER: == sanity test 65p: setstripe with yaml file and huge number ========================================================== 01:19:34 (1787116774) [ 1586.880572] Lustre: DEBUG MARKER: == sanity test 65q: setstripe with >=8E offset should fail ========================================================== 01:19:42 (1787116782) [ 1593.838025] Lustre: DEBUG MARKER: == sanity test 65r: prevent all-zero offsets ============= 01:19:50 (1787116790) [ 1602.663685] Lustre: DEBUG MARKER: == sanity test 66: update inode blocks count on client ========================================================================= 01:19:58 (1787116798) [ 1622.455415] Lustre: DEBUG MARKER: == sanity test 69: verify oa2dentry return -ENOENT doesn't LBUG ================================================================ 01:20:18 (1787116818) [ 1624.905163] Lustre: *** cfs_fail_loc=217, val=0*** [ 1628.561123] Lustre: *** cfs_fail_loc=217, val=0*** [ 1628.566483] Lustre: Skipped 1 previous similar message [ 1636.410286] Lustre: DEBUG MARKER: == sanity test 70a: verify health_check, health_write don't explode (on OST) ========================================================== 01:20:32 (1787116832) [ 1650.510099] Lustre: DEBUG MARKER: SKIP: sanity test_71 skipping SLOW test 71 [ 1652.511242] Lustre: DEBUG MARKER: == sanity test 72a: Test that remove suid works properly (bug5695) ============================================================== 01:20:48 (1787116848) [ 1659.972316] Lustre: DEBUG MARKER: == sanity test 72b: Test that we keep mode setting if without file data changed (bug 24226) ========================================================== 01:20:56 (1787116856) [ 1669.659189] Lustre: DEBUG MARKER: == sanity test 73: multiple MDC requests (should not deadlock) ========================================================== 01:21:05 (1787116865) [ 1704.427252] Lustre: DEBUG MARKER: == sanity test 74a: ldlm_enqueue freed-export error path, ls (shouldn't LBUG) ========================================================== 01:21:40 (1787116900) [ 1710.740933] Lustre: DEBUG MARKER: == sanity test 74b: ldlm_enqueue freed-export error path, touch (shouldn't LBUG) ========================================================== 01:21:46 (1787116906) [ 1717.941753] Lustre: DEBUG MARKER: == sanity test 74c: ldlm_lock_create error path, (shouldn't LBUG) ========================================================== 01:21:54 (1787116914) [ 1725.452040] Lustre: DEBUG MARKER: == sanity test 76a: confirm clients recycle inodes properly ============================================================== 01:22:01 (1787116921) [ 1813.605241] Lustre: DEBUG MARKER: == sanity test 76b: confirm clients recycle directory inodes properly ============================================================== 01:23:29 (1787117009) [ 1874.491602] Lustre: DEBUG MARKER: == sanity test 77a: normal checksum read/write operation ========================================================== 01:24:30 (1787117070) [ 1883.923402] Lustre: DEBUG MARKER: == sanity test 77b: checksum error on client write, read ========================================================== 01:24:40 (1787117080) [ 1884.833281] LustreError: lustre-OST0000: BAD WRITE CHECKSUM: from 12345-192.168.204.38@tcp inode [0x200000407:0xc1c:0x0] object 0x280000401:3837 extent [0-4194303]: client csum 78457042, server csum 78457041 [ 1887.851143] Lustre: DEBUG MARKER: set checksum type to crc32, rc = 0 [ 1889.466182] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.204.38@tcp inode [0x200000407:0xc1c:0x0] object 0x280000401:3837 extent [0-4194303], client returned csum 16cfb384 (type 1), server csum 9b73652e (type 1) [ 1892.460638] Lustre: DEBUG MARKER: set checksum type to adler, rc = 0 [ 1894.013340] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.204.38@tcp inode [0x200000407:0xc1c:0x0] object 0x280000401:3837 extent [0-4194303], client returned csum 1a3edb6b (type 2), server csum 6bf2dd1b (type 2) [ 1897.371969] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 1899.137603] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.204.38@tcp inode [0x200000407:0xc1c:0x0] object 0x280000401:3837 extent [0-4194303], client returned csum 6ee4d309 (type 4), server csum 78457041 (type 4) [ 1902.488326] Lustre: DEBUG MARKER: set checksum type to t10ip512, rc = 0 [ 1904.187178] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.204.38@tcp inode [0x200000407:0xc1c:0x0] object 0x280000401:3837 extent [0-4194303], client returned csum 13c4006e (type 10), server csum d143ffae (type 10) [ 1907.015353] Lustre: DEBUG MARKER: set checksum type to t10ip4K, rc = 0 [ 1908.484164] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.204.38@tcp inode [0x200000407:0xc1c:0x0] object 0x280000401:3837 extent [0-4194303], client returned csum 104ff9dc (type 20), server csum 8090fa2a (type 20) [ 1911.179948] Lustre: DEBUG MARKER: set checksum type to t10crc512, rc = 0 [ 1915.751659] Lustre: DEBUG MARKER: set checksum type to t10crc4K, rc = 0 [ 1917.382350] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.204.38@tcp inode [0x200000407:0xc1c:0x0] object 0x280000401:3837 extent [0-4194303], client returned csum 22acfdb9 (type 80), server csum 2a89fdda (type 80) [ 1917.427269] LustreError: Skipped 1 previous similar message [ 1920.379448] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 1929.330311] Lustre: DEBUG MARKER: == sanity test 77c: checksum error on client read with debug ========================================================== 01:25:24 (1787117124) [ 1940.465937] Lustre: 8445:0:(tgt_handler.c:2012:dump_all_bulk_pages()) dumping checksum data to /tmp/lustre-log-checksum_dump-ost-[0x200000407:0xc1d:0x0]:[0-1048575]-4575c66-65dbe856 [ 1940.490413] LustreError: dumping log to /tmp/lustre-log.1787117138.8445 [ 1940.694747] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.204.38@tcp inode [0x200000407:0xc1d:0x0] object 0x280000401:3838 extent [0-1048575], client returned csum 4575c66 (type 4), server csum 65dbe856 (type 4) [ 1975.633212] Lustre: DEBUG MARKER: == sanity test 77d: checksum error on OST direct write, read ========================================================== 01:26:10 (1787117170) [ 1976.138384] LustreError: lustre-OST0001: BAD WRITE CHECKSUM: from 12345-192.168.204.38@tcp inode [0x200000407:0xc1f:0x0] object 0x2c0000401:3830 extent [0-4194303]: client csum de2bf73f, server csum de2bf73e [ 1979.326837] LustreError: lustre-OST0001: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.204.38@tcp inode [0x200000407:0xc1f:0x0] object 0x2c0000401:3830 extent [0-4194303], client returned csum f5a99216 (type 4), server csum de2bf73e (type 4) [ 1988.624203] Lustre: DEBUG MARKER: == sanity test 77f: repeat checksum error on write (expect error) ========================================================== 01:26:24 (1787117184) [ 1990.584870] Lustre: DEBUG MARKER: set checksum type to crc32, rc = 0 [ 1991.033271] LustreError: lustre-OST0000: BAD WRITE CHECKSUM: from 12345-192.168.204.38@tcp inode [0x200000407:0xc20:0x0] object 0x280000401:3839 extent [0-4194303]: client csum 8b19b060, server csum 8b19b05f [ 1994.570818] Lustre: DEBUG MARKER: set checksum type to adler, rc = 0 [ 1994.960840] LustreError: lustre-OST0001: BAD WRITE CHECKSUM: from 12345-192.168.204.38@tcp inode [0x200000407:0xc21:0x0] object 0x2c0000401:3831 extent [0-4194303]: client csum 7d33b9a0, server csum 7d33b99f [ 1994.973936] LustreError: Skipped 3 previous similar messages [ 1998.450764] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 2000.148853] LustreError: lustre-OST0000: BAD WRITE CHECKSUM: from 12345-192.168.204.38@tcp inode [0x200000407:0xc22:0x0] object 0x280000401:3840 extent [4194304-8388607]: client csum de2bf73f, server csum de2bf73e [ 2000.163635] LustreError: Skipped 5 previous similar messages [ 2002.015474] Lustre: DEBUG MARKER: set checksum type to t10ip512, rc = 0 [ 2005.284913] Lustre: DEBUG MARKER: set checksum type to t10ip4K, rc = 0 [ 2008.919643] Lustre: DEBUG MARKER: set checksum type to t10crc512, rc = 0 [ 2009.321080] LustreError: lustre-OST0001: BAD WRITE CHECKSUM: from 12345-192.168.204.38@tcp inode [0x200000407:0xc25:0x0] object 0x2c0000401:3833 extent [0-4194303]: client csum a30822f0, server csum a30822ef [ 2009.349812] LustreError: Skipped 9 previous similar messages [ 2012.327964] Lustre: DEBUG MARKER: set checksum type to t10crc4K, rc = 0 [ 2021.745919] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 2023.678692] Lustre: DEBUG MARKER: == sanity test 77g: checksum error on OST write, read ==== 01:26:59 (1787117219) [ 2025.330115] Lustre: *** cfs_fail_loc=21a, val=0*** [ 2025.332327] LustreError: lustre-OST0000: BAD WRITE CHECKSUM: from 12345-192.168.204.38@tcp inode [0x200000407:0xc27:0x0] object 0x280000401:3843 extent [0-1048575]: client csum 65dbe856, server csum 938dd80e [ 2025.346985] LustreError: Skipped 6 previous similar messages [ 2030.242826] Lustre: *** cfs_fail_loc=21b, val=0*** [ 2044.305576] Lustre: DEBUG MARKER: == sanity test 77k: enable/disable checksum correctly ==== 01:27:19 (1787117239) [ 2045.359880] Lustre: Setting parameter lustre.osc.lustre*.checksums=0 in log params [ 2052.561296] Lustre: Modifying parameter lustre.osc.lustre*.checksums=1 in log params [ 2061.006690] Lustre: Disabling parameter lustre.osc.lustre*.checksums= in log params [ 2078.371198] Lustre: Setting parameter lustre.osc.lustre*.checksums=0 in log params [ 2082.600038] Lustre: DEBUG MARKER: == sanity test 77l: preferred checksum type is remembered after reconnected ========================================================== 01:27:58 (1787117278) [ 2084.433572] Lustre: DEBUG MARKER: set checksum type to invalid, rc = 22 [ 2086.267940] Lustre: DEBUG MARKER: set checksum type to crc32, rc = 0 [ 2093.119752] Lustre: DEBUG MARKER: oleg438-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff9b9298320800.ost_server_uuid 50 [ 2094.812583] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9b9298320800.ost_server_uuid in IDLE state after 0 sec [ 2100.326811] Lustre: DEBUG MARKER: oleg438-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9b9298320800.ost_server_uuid 50 [ 2101.805518] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9b9298320800.ost_server_uuid in FULL state after 0 sec [ 2103.347610] Lustre: DEBUG MARKER: set checksum type to adler, rc = 0 [ 2109.211770] Lustre: DEBUG MARKER: oleg438-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff9b9298320800.ost_server_uuid 50 [ 2119.842872] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9b9298320800.ost_server_uuid in IDLE state after 8 sec [ 2126.982663] Lustre: DEBUG MARKER: oleg438-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9b9298320800.ost_server_uuid 50 [ 2128.762102] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9b9298320800.ost_server_uuid in FULL state after 0 sec [ 2130.890607] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 2138.711480] Lustre: DEBUG MARKER: oleg438-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff9b9298320800.ost_server_uuid 50 [ 2145.267995] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9b9298320800.ost_server_uuid in IDLE state after 4 sec [ 2152.466615] Lustre: DEBUG MARKER: oleg438-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9b9298320800.ost_server_uuid 50 [ 2155.370181] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9b9298320800.ost_server_uuid in FULL state after 0 sec [ 2158.424265] Lustre: DEBUG MARKER: set checksum type to t10ip512, rc = 0 [ 2166.172745] Lustre: DEBUG MARKER: oleg438-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff9b9298320800.ost_server_uuid 50 [ 2171.353229] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9b9298320800.ost_server_uuid in IDLE state after 3 sec [ 2177.733770] Lustre: DEBUG MARKER: oleg438-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9b9298320800.ost_server_uuid 50 [ 2179.606928] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9b9298320800.ost_server_uuid in FULL state after 0 sec [ 2181.667917] Lustre: DEBUG MARKER: set checksum type to t10ip4K, rc = 0 [ 2189.017083] Lustre: DEBUG MARKER: oleg438-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff9b9298320800.ost_server_uuid 50 [ 2196.615972] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9b9298320800.ost_server_uuid in IDLE state after 5 sec [ 2204.333692] Lustre: DEBUG MARKER: oleg438-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9b9298320800.ost_server_uuid 50 [ 2206.797790] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9b9298320800.ost_server_uuid in FULL state after 0 sec [ 2208.766893] Lustre: DEBUG MARKER: set checksum type to t10crc512, rc = 0 [ 2216.152910] Lustre: DEBUG MARKER: oleg438-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff9b9298320800.ost_server_uuid 50 [ 2222.754516] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9b9298320800.ost_server_uuid in IDLE state after 4 sec [ 2230.880235] Lustre: DEBUG MARKER: oleg438-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9b9298320800.ost_server_uuid 50 [ 2232.791421] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9b9298320800.ost_server_uuid in FULL state after 0 sec [ 2234.905322] Lustre: DEBUG MARKER: set checksum type to t10crc4K, rc = 0 [ 2242.056298] Lustre: DEBUG MARKER: oleg438-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff9b9298320800.ost_server_uuid 50 [ 2248.492683] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9b9298320800.ost_server_uuid in IDLE state after 4 sec [ 2256.640785] Lustre: DEBUG MARKER: oleg438-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9b9298320800.ost_server_uuid 50 [ 2258.619732] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9b9298320800.ost_server_uuid in FULL state after 0 sec [ 2269.280765] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 2271.661787] Lustre: DEBUG MARKER: == sanity test 77m: Verify checksum_speed is correctly read ========================================================== 01:31:07 (1787117467) [ 2279.259617] Lustre: DEBUG MARKER: == sanity test 77n: Verify read from a hole inside contiguous blocks with T10PI ========================================================== 01:31:15 (1787117475) [ 2281.795767] Lustre: DEBUG MARKER: set checksum type to t10ip512, rc = 0 [ 2283.688764] Lustre: DEBUG MARKER: set checksum type to t10ip4K, rc = 0 [ 2285.705622] Lustre: DEBUG MARKER: set checksum type to t10crc512, rc = 0 [ 2288.003563] Lustre: DEBUG MARKER: set checksum type to t10crc4K, rc = 0 [ 2295.913957] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 2298.273210] Lustre: DEBUG MARKER: == sanity test 77o: Verify checksum_type for server (mdt and ofd(obdfilter)) ========================================================== 01:31:34 (1787117494) [ 2316.757434] Lustre: DEBUG MARKER: == sanity test 78: handle large O_DIRECT writes correctly ====================================================================== 01:31:52 (1787117512) [ 2329.351037] Lustre: DEBUG MARKER: == sanity test 79: df report consistency check =========== 01:32:05 (1787117525) [ 2350.015995] Lustre: DEBUG MARKER: == sanity test 80: Page eviction is equally fast at high offsets too ========================================================== 01:32:25 (1787117545) [ 2361.996792] Lustre: DEBUG MARKER: == sanity test 81a: OST should retry write when get -ENOSPC ========================================================================= 01:32:37 (1787117557) [ 2363.593771] Lustre: *** cfs_fail_loc=228, val=0*** [ 2371.130327] Lustre: DEBUG MARKER: == sanity test 81b: OST should return -ENOSPC when retry still fails ================================================================= 01:32:47 (1787117567) [ 2372.807663] Lustre: *** cfs_fail_loc=228, val=0*** [ 2380.690509] Lustre: DEBUG MARKER: == sanity test 99: cvs strange file/directory operations ========================================================== 01:32:56 (1787117576) [ 2407.925394] Lustre: DEBUG MARKER: == sanity test 100: check local port using privileged port ========================================================== 01:33:23 (1787117603) [ 2417.027220] Lustre: DEBUG MARKER: == sanity test 101a: check read-ahead for random reads === 01:33:33 (1787117613) [ 2626.389875] Lustre: DEBUG MARKER: == sanity test 101b: check stride-io mode read-ahead =========================================================================== 01:37:02 (1787117822) [ 2663.587230] Lustre: DEBUG MARKER: == sanity test 101c: check stripe_size aligned read-ahead ========================================================== 01:37:39 (1787117859) [ 2764.689693] Lustre: DEBUG MARKER: == sanity test 101d: file read with and without read-ahead enabled ========================================================== 01:39:20 (1787117960) [ 3081.740921] Lustre: DEBUG MARKER: == sanity test 101e: check read-ahead for small read(1k) for small files(500k) ========================================================== 01:44:37 (1787118277) [ 3174.504976] Lustre: DEBUG MARKER: == sanity test 101f: check mmap read performance ========= 01:46:10 (1787118370) [ 3185.136313] Lustre: DEBUG MARKER: == sanity test 101g: Big bulk(4/16 MiB) readahead ======== 01:46:21 (1787118381) [ 3264.174380] Lustre: DEBUG MARKER: == sanity test 101h: Readahead should cover current read window ========================================================== 01:47:40 (1787118460) [ 3290.467637] Lustre: DEBUG MARKER: == sanity test 101i: allow current readahead to exceed reservation ========================================================== 01:48:06 (1787118486) [ 3306.705691] Lustre: DEBUG MARKER: == sanity test 101j: A complete read block should be submitted when no RA ========================================================== 01:48:22 (1787118502) [ 3378.780580] Lustre: DEBUG MARKER: == sanity test 101m: read ahead for small file and last stripe of the file ========================================================== 01:49:34 (1787118574) [ 3396.971272] Lustre: DEBUG MARKER: == sanity test 102a: user xattr test ============================================================================================ 01:49:52 (1787118592) [ 3406.646390] Lustre: DEBUG MARKER: == sanity test 102b: getfattr/setfattr for trusted.lov EAs ========================================================== 01:50:02 (1787118602) [ 3420.832510] Lustre: DEBUG MARKER: == sanity test 102c: non-root getfattr/setfattr for lustre.lov EAs ===================================================================== 01:50:16 (1787118616) [ 3430.104462] Lustre: DEBUG MARKER: == sanity test 102d: tar restore stripe info from tarfile,not keep osts ========================================================== 01:50:25 (1787118625) [ 3452.128740] Lustre: DEBUG MARKER: == sanity test 102f: tar copy files, not keep osts ======= 01:50:48 (1787118648) [ 3475.690679] Lustre: DEBUG MARKER: == sanity test 102h: grow xattr from inside inode to external block ========================================================== 01:51:11 (1787118671) [ 3478.606909] Lustre: DEBUG MARKER: save trusted.big on /mnt/lustre/f102h.sanity [ 3480.029329] Lustre: DEBUG MARKER: save trusted.sml on /mnt/lustre/f102h.sanity [ 3481.786758] Lustre: DEBUG MARKER: grow trusted.sml on /mnt/lustre/f102h.sanity [ 3483.480958] Lustre: DEBUG MARKER: trusted.big still valid after growing trusted.sml [ 3491.255197] Lustre: DEBUG MARKER: == sanity test 102ha: grow xattr from inside inode to external inode ========================================================== 01:51:27 (1787118687) [ 3494.759435] Lustre: DEBUG MARKER: save trusted.big on /mnt/lustre/f102ha.sanity [ 3496.462600] Lustre: DEBUG MARKER: save trusted.sml on /mnt/lustre/f102ha.sanity [ 3498.277026] Lustre: DEBUG MARKER: grow trusted.sml on /mnt/lustre/f102ha.sanity [ 3499.969675] Lustre: DEBUG MARKER: trusted.big still valid after growing trusted.sml [ 3502.451478] Lustre: DEBUG MARKER: save trusted.big on /mnt/lustre/f102ha.sanity [ 3508.780441] Lustre: DEBUG MARKER: == sanity test 102i: lgetxattr test on symbolic link ====================================================================== 01:51:45 (1787118705) [ 3516.249773] Lustre: DEBUG MARKER: == sanity test 102j: non-root tar restore stripe info from tarfile, not keep osts ============================================================= 01:51:52 (1787118712) [ 3539.395549] Lustre: DEBUG MARKER: == sanity test 102k: setfattr without parameter of value shouldn't cause a crash ========================================================== 01:52:15 (1787118735) [ 3548.825365] Lustre: DEBUG MARKER: == sanity test 102l: listxattr size test ============================================================================================ 01:52:24 (1787118744) [ 3557.304933] Lustre: DEBUG MARKER: == sanity test 102m: Ensure listxattr fails on small bufffer ================================================================== 01:52:33 (1787118753) [ 3565.691045] Lustre: DEBUG MARKER: == sanity test 102n: silently ignore setxattr on internal trusted xattrs ========================================================== 01:52:41 (1787118761) [ 3575.349781] Lustre: DEBUG MARKER: == sanity test 102p: check setxattr(2) correctly fails without permission ========================================================== 01:52:51 (1787118771) [ 3585.427282] Lustre: DEBUG MARKER: == sanity test 102q: flistxattr should not return trusted.link EAs for orphans ========================================================== 01:53:01 (1787118781) [ 3595.406709] Lustre: DEBUG MARKER: == sanity test 102r: set EAs with empty values =========== 01:53:11 (1787118791) [ 3604.872828] Lustre: DEBUG MARKER: == sanity test 102s: getting nonexistent xattrs should fail ========================================================== 01:53:20 (1787118800) [ 3614.237776] Lustre: DEBUG MARKER: == sanity test 102t: zero length xattr values handled correctly ========================================================== 01:53:29 (1787118809) [ 3623.473770] Lustre: DEBUG MARKER: == sanity test 103a: acl test ============================ 01:53:39 (1787118819) [ 3966.046818] Lustre: DEBUG MARKER: == sanity test 103b: umask lfs setstripe ================= 01:59:21 (1787119161) [ 4185.519343] Lustre: DEBUG MARKER: == sanity test 103c: 'cp -rp' won't set empty acl ======== 02:03:00 (1787119380) [ 4194.702928] Lustre: DEBUG MARKER: == sanity test 103e: inheritance of big amount of default ACLs ========================================================== 02:03:10 (1787119390) [ 4216.141362] Lustre: 6524:0:(osd_handler.c:2191:osd_trans_start()) lustre-MDT0000: credits 30549 > trans_max 3200 [ 4216.147567] Lustre: 6524:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 4/16/0, destroy: 1/4/0 [ 4216.158619] Lustre: 6524:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 2003/2003/0, xattr_set: 3004/28292/0 [ 4216.167141] Lustre: 6524:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 20/142/0, punch: 0/0/0, quota 0/0/0 [ 4216.182468] Lustre: 6524:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 5/84/0, delete: 2/5/0 [ 4216.193604] Lustre: 6524:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 1/1/0, ref_del: 2/2/0 [ 4216.206081] CPU: 0 PID: 6524 Comm: mdt00_000 Kdump: loaded Tainted: G W O -------- - - 4.18.0rh8.10-debug #2 [ 4216.216134] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.17.0-10.fc44 06/10/2025 [ 4216.220868] Call Trace: [ 4216.222309] ? dump_stack+0xbb/0x10e [ 4216.223896] ? osd_trans_start+0x8db/0x9d0 [osd_ldiskfs] [ 4216.226900] ? dt_trans_start+0x1c/0x70 [obdclass] [ 4216.229356] ? top_trans_start+0x4fd/0xd00 [ptlrpc] [ 4216.231685] ? lod_declare_ref_add+0x1a/0x30 [lod] [ 4216.234656] ? dt_declare_ref_add+0x6c/0x200 [obdclass] [ 4216.242717] ? lod_trans_start+0x109/0x4c0 [lod] [ 4216.255140] ? mdd_declare_links_add+0x60/0x90 [mdd] [ 4216.264624] ? mdd_trans_start+0x18/0x30 [mdd] [ 4216.266561] ? mdd_unlink+0x7a4/0x13c0 [mdd] [ 4216.272295] ? mdt_reint_unlink+0x14aa/0x1a30 [mdt] [ 4216.274364] ? mdt_reint_rec+0x139/0x2b0 [mdt] [ 4216.283874] ? mdt_reint_internal+0x693/0xdc0 [mdt] [ 4216.292644] ? mdt_reint+0x163/0x190 [mdt] [ 4216.297888] ? tgt_handle_request0+0x137/0xaf0 [ptlrpc] [ 4216.303928] ? tgt_request_handle+0x575/0x1f70 [ptlrpc] [ 4216.307626] ? ptlrpc_server_handle_request+0x443/0x13b0 [ptlrpc] [ 4216.312015] ? lprocfs_counter_add+0x15b/0x210 [obdclass] [ 4216.315930] ? ptlrpc_main+0xce8/0x1400 [ptlrpc] [ 4216.325257] ? ptlrpc_wait_event+0x690/0x690 [ptlrpc] [ 4216.333143] ? kthread+0x1d1/0x200 [ 4216.337975] ? set_kthread_struct+0x70/0x70 [ 4216.342395] ? ret_from_fork+0x1f/0x30 [ 4224.343533] Lustre: DEBUG MARKER: == sanity test 103f: changelog doesn't interfere with default ACLs buffers ========================================================== 02:03:40 (1787119420) [ 4228.428815] Lustre: lustre-MDD0000: changelog on [ 4232.567384] Lustre: lustre-MDD0001: changelog on [ 4240.200094] Lustre: lustre-MDD0001: changelog off [ 4243.943662] Lustre: lustre-MDD0000: changelog off [ 4247.447096] Lustre: DEBUG MARKER: == sanity test 103g: no MDS_GETXATTR storm for inodes without ACL_ACCESS (LU-17238) ========================================================== 02:04:03 (1787119443) [ 4259.793686] Lustre: DEBUG MARKER: == sanity test 104a: lfs df [-ih] [path] test =================================================================================== 02:04:14 (1787119454) [ 4260.457961] Lustre: lustre-OST0000: Client f40f1a0e-4293-428e-aae0-d6eadf656c0f (at 192.168.204.38@tcp) reconnecting [ 4265.774784] Lustre: DEBUG MARKER: oleg438-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0000-osc-ffff9b9298325000.ost_server_uuid 50 [ 4267.402456] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9b9298325000.ost_server_uuid in FULL state after 0 sec [ 4277.995379] Lustre: DEBUG MARKER: == sanity test 104b: runas -u 500 -g 500 lfs check servers test ============================================================================== 02:04:33 (1787119473) [ 4287.771107] Lustre: DEBUG MARKER: == sanity test 104c: Verify df vs lfs_df stays same after recordsize change ========================================================== 02:04:43 (1787119483) [ 4290.243031] Lustre: DEBUG MARKER: SKIP: sanity test_104c zfs only test [ 4292.375961] Lustre: DEBUG MARKER: == sanity test 104d: runas -u 500 -g 500 lctl dl test ==== 02:04:48 (1787119488) [ 4300.040386] Lustre: DEBUG MARKER: == sanity test 105a: flock when mounted without -o flock test ================================================================== 02:04:56 (1787119496) [ 4307.610530] Lustre: DEBUG MARKER: == sanity test 105b: fcntl when mounted without -o flock test ================================================================== 02:05:03 (1787119503) [ 4315.803147] Lustre: DEBUG MARKER: == sanity test 105c: lockf when mounted without -o flock test ========================================================== 02:05:11 (1787119511) [ 4324.360810] Lustre: DEBUG MARKER: == sanity test 105d: flock race (should not freeze) ================================================================== 02:05:20 (1787119520) [ 4343.440546] Lustre: DEBUG MARKER: == sanity test 105e: Two conflicting flocks from same process ========================================================== 02:05:39 (1787119539) [ 4350.902697] Lustre: DEBUG MARKER: == sanity test 105f: Enqueue same range flocks =========== 02:05:47 (1787119547) [ 4361.277941] Lustre: DEBUG MARKER: == sanity test 105g: ldlm_lock_debug stack test ========== 02:05:57 (1787119557) [ 4370.897688] Lustre: DEBUG MARKER: == sanity test 105h: Flock functional verify ============= 02:06:07 (1787119567) [ 4378.247198] Lustre: DEBUG MARKER: == sanity test 105i: Flock deadlock verify =============== 02:06:14 (1787119574) [ 4392.195138] Lustre: DEBUG MARKER: == sanity test 106: attempt exec of dir followed by chown of that dir ========================================================== 02:06:28 (1787119588) [ 4400.004725] Lustre: DEBUG MARKER: == sanity test 107: Coredump on SIG ====================== 02:06:35 (1787119595) [ 4409.452700] Lustre: DEBUG MARKER: == sanity test 110: filename length checking ============= 02:06:45 (1787119605) [ 4417.896405] Lustre: DEBUG MARKER: == sanity test 116a: stripe QOS: free space balance ============================================================================= 02:06:54 (1787119614) [ 4600.624301] Lustre: DEBUG MARKER: == sanity test 116b: QoS shouldn't LBUG if not enough OSTs found on the 2nd pass ========================================================== 02:09:56 (1787119796) [ 4603.815908] Lustre: *** cfs_fail_loc=147, val=0*** [ 4604.329149] Lustre: *** cfs_fail_loc=147, val=0*** [ 4604.341260] Lustre: Skipped 31 previous similar messages [ 4613.756961] Lustre: DEBUG MARKER: == sanity test 117: verify osd extend ==================== 02:10:09 (1787119809) [ 4622.849586] Lustre: DEBUG MARKER: == sanity test 118a: verify O_SYNC works ================= 02:10:18 (1787119818) [ 4630.815965] Lustre: DEBUG MARKER: == sanity test 118b: Reclaim dirty pages on fatal error ==================================================================== 02:10:26 (1787119826) [ 4633.344055] Lustre: *** cfs_fail_loc=217, val=0*** [ 4633.357477] Lustre: Skipped 34 previous similar messages [ 4642.842603] Lustre: DEBUG MARKER: SKIP: sanity test_118c skipping ALWAYS excluded test 118c [ 4644.920943] Lustre: DEBUG MARKER: SKIP: sanity test_118d skipping ALWAYS excluded test 118d [ 4646.814332] Lustre: DEBUG MARKER: == sanity test 118f: Simulate unrecoverable OSC side error ==================================================================== 02:10:42 (1787119842) [ 4654.317975] Lustre: DEBUG MARKER: == sanity test 118g: Don't stay in wait if we got local -ENOMEM ==================================================================== 02:10:50 (1787119850) [ 4662.322722] Lustre: DEBUG MARKER: == sanity test 118h: Verify timeout in handling recoverables errors ==================================================================== 02:10:58 (1787119858) [ 4664.260453] Lustre: *** cfs_fail_loc=20e, val=0*** [ 4665.709790] Lustre: *** cfs_fail_loc=20e, val=0*** [ 4667.886959] Lustre: *** cfs_fail_loc=20e, val=0*** [ 4670.831746] Lustre: *** cfs_fail_loc=20e, val=0*** [ 4674.862928] Lustre: *** cfs_fail_loc=20e, val=0*** [ 4684.921404] Lustre: DEBUG MARKER: == sanity test 118i: Fix error before timeout in recoverable error ==================================================================== 02:11:20 (1787119880) [ 4687.406294] Lustre: *** cfs_fail_loc=20e, val=0*** [ 4701.150399] Lustre: DEBUG MARKER: == sanity test 118j: Simulate unrecoverable OST side error ==================================================================== 02:11:37 (1787119897) [ 4711.667451] Lustre: DEBUG MARKER: == sanity test 118k: bio alloc -ENOMEM and IO TERM handling =================================================================== 02:11:47 (1787119907) [ 4713.696290] Lustre: *** cfs_fail_loc=20e, val=0*** [ 4713.705792] Lustre: Skipped 3 previous similar messages [ 4735.981336] Lustre: DEBUG MARKER: == sanity test 118l: fsync dir =========================== 02:12:11 (1787119931) [ 4745.104187] Lustre: DEBUG MARKER: == sanity test 118m: fdatasync dir ======================= 02:12:20 (1787119940) [ 4753.195399] Lustre: DEBUG MARKER: == sanity test 118n: statfs() sends OST_STATFS requests in parallel ========================================================== 02:12:29 (1787119949) [ 4758.001156] LustreError: 8442:0:(ofd_dev.c:1917:ofd_statfs_hdl()) cfs_fail_timeout id 242 sleeping for 10000ms [ 4758.433107] LustreError: 8442:0:(ofd_dev.c:1917:ofd_statfs_hdl()) cfs_fail_timeout interrupted [ 4765.652000] Lustre: DEBUG MARKER: == sanity test 119a: Short directIO read must return actual read amount ========================================================== 02:12:41 (1787119961) [ 4773.002724] Lustre: DEBUG MARKER: == sanity test 119b: Sparse directIO read must return actual read amount ========================================================== 02:12:49 (1787119969) [ 4780.813733] Lustre: DEBUG MARKER: == sanity test 119c: Testing for direct read hitting hole ========================================================== 02:12:57 (1787119977) [ 4788.302614] Lustre: DEBUG MARKER: == sanity test 119e: Basic tests of dio read and write at various sizes ========================================================== 02:13:04 (1787119984) [ 4828.793714] Lustre: DEBUG MARKER: == sanity test 119f: dio vs dio race ===================== 02:13:45 (1787120025) [ 4871.577839] Lustre: DEBUG MARKER: == sanity test 119g: dio vs buffered I/O race ============ 02:14:27 (1787120067) [ 4914.394922] Lustre: DEBUG MARKER: == sanity test 119h: basic tests of memory unaligned dio ========================================================== 02:15:10 (1787120110) [ 4944.222800] Lustre: DEBUG MARKER: SKIP: sanity test_119i skipping ALWAYS excluded test 119i [ 4945.941843] Lustre: DEBUG MARKER: == sanity test 119j: basic tests of hybrid IO switching == 02:15:42 (1787120142) [ 4951.948357] Lustre: DEBUG MARKER: == sanity test 119k: hybrid IO counting with stats and disabling ========================================================== 02:15:48 (1787120148) [ 4968.558752] Lustre: DEBUG MARKER: == sanity test 119m: Test DIO readv/writev: exercise iter duplication ========================================================== 02:16:04 (1787120164) [ 4975.836602] Lustre: DEBUG MARKER: == sanity test 119n: Test Unaligned DIO readv() and writev() with unpatched ZFS ========================================================== 02:16:12 (1787120172) [ 4977.413228] Lustre: DEBUG MARKER: SKIP: sanity test_119n need ZFS server without unaligned_dio support [ 4979.185666] Lustre: DEBUG MARKER: == sanity test 119o: Test Unaligned DIO readv() and writev() with unpatched servers ========================================================== 02:16:15 (1787120175) [ 4980.832252] Lustre: DEBUG MARKER: SKIP: sanity test_119o need ldiskfs without unaligned_dio support. [ 4982.441623] Lustre: DEBUG MARKER: == sanity test 119p: Test Unaligned DIO readv() and writev() with patched servers ========================================================== 02:16:18 (1787120178) [ 4991.361866] Lustre: DEBUG MARKER: == sanity test 119q: Test patchded Unaligned DIO readv() and writev() ========================================================== 02:16:27 (1787120187) [ 5008.336735] Lustre: DEBUG MARKER: == sanity test 119r: Test error handling in unaligned DIO user copy ========================================================== 02:16:44 (1787120204) [ 5015.967569] Lustre: DEBUG MARKER: == sanity test 120a: Early Lock Cancel: mkdir test ======= 02:16:52 (1787120212) [ 5025.637768] Lustre: DEBUG MARKER: == sanity test 120b: Early Lock Cancel: create test ====== 02:17:02 (1787120222) [ 5034.811457] Lustre: DEBUG MARKER: == sanity test 120c: Early Lock Cancel: link test ======== 02:17:11 (1787120231) [ 5044.903820] Lustre: DEBUG MARKER: == sanity test 120d: Early Lock Cancel: setattr test ===== 02:17:21 (1787120241) [ 5054.546768] Lustre: DEBUG MARKER: == sanity test 120e: Early Lock Cancel: unlink test ====== 02:17:30 (1787120250) [ 5072.764462] Lustre: DEBUG MARKER: == sanity test 120f: Early Lock Cancel: rename test ====== 02:17:48 (1787120268) [ 5090.735787] Lustre: DEBUG MARKER: == sanity test 120g: Early Lock Cancel: performance test ========================================================== 02:18:06 (1787120286) [ 5581.976708] Lustre: DEBUG MARKER: == sanity test 121: read cancel race ===================== 02:26:17 (1787120777) [ 5590.832774] Lustre: DEBUG MARKER: == sanity test 123aa: verify statahead work ============== 02:26:27 (1787120787) [ 5602.325650] Lustre: DEBUG MARKER: 'ls -l' 100 files without statahead: 3 sec [ 5605.976772] Lustre: DEBUG MARKER: 'ls -l' 100 files with statahead: 1 sec [ 5653.212582] Lustre: DEBUG MARKER: 'ls -l' 1000 files without statahead: 27 sec [ 5662.965460] Lustre: DEBUG MARKER: 'ls -l' 1000 files with statahead: 7 sec [ 5664.527172] Lustre: DEBUG MARKER: 'ls -l' done [ 5688.558568] Lustre: DEBUG MARKER: unlink + rm -r /mnt/lustre/d123aa.sanity: 21 seconds [ 5700.428798] Lustre: DEBUG MARKER: == sanity test 123ab: verify statahead work by using statx ========================================================== 02:28:16 (1787120896) [ 5711.022465] Lustre: DEBUG MARKER: 'statx -l' 100 files without statahead: 3 sec [ 5714.097419] Lustre: DEBUG MARKER: 'statx -l' 100 files with statahead: 1 sec [ 5760.875853] Lustre: DEBUG MARKER: 'statx -l' 1000 files without statahead: 25 sec [ 5772.457676] Lustre: DEBUG MARKER: 'statx -l' 1000 files with statahead: 7 sec [ 5774.236806] Lustre: DEBUG MARKER: 'statx -l' done [ 5800.493337] Lustre: DEBUG MARKER: unlink + rm -r /mnt/lustre/d123ab.sanity: 23 seconds [ 5814.363301] Lustre: DEBUG MARKER: == sanity test 123ac: verify statahead work by using statx without glimpse RPCs ========================================================== 02:30:10 (1787121010) [ 5826.755704] Lustre: DEBUG MARKER: 'statx -c 1 [ 5830.233793] Lustre: DEBUG MARKER: 'statx -c 1 [ 5873.832656] Lustre: DEBUG MARKER: 'statx -c 1 [ 5883.790159] Lustre: DEBUG MARKER: 'statx -c 1 [ 5886.420363] Lustre: DEBUG MARKER: 'statx -c 1 [ 5911.949062] Lustre: DEBUG MARKER: unlink + rm -r /mnt/lustre/d123ac.sanity: 22 seconds [ 5919.302726] Lustre: DEBUG MARKER: 'statx --cached=always -D' 100 files without statahead: 0 sec [ 5921.537572] Lustre: DEBUG MARKER: 'statx --cached=always -D' 100 files with statahead: 0 sec [ 5946.371462] Lustre: DEBUG MARKER: 'statx --cached=always -D' 1000 files without statahead: 1 sec [ 5949.144652] Lustre: DEBUG MARKER: 'statx --cached=always -D' 1000 files with statahead: 0 sec [ 6098.717625] Lustre: DEBUG MARKER: 'statx --cached=always -D' 10000 files without statahead: 0 sec [ 6101.020448] Lustre: DEBUG MARKER: 'statx --cached=always -D' 10000 files with statahead: 1 sec [ 6102.999816] Lustre: DEBUG MARKER: 'statx --cached=always -D' done [ 6450.746954] Lustre: DEBUG MARKER: unlink + rm -r /mnt/lustre/d123ac.sanity: 346 seconds [ 6471.556303] Lustre: DEBUG MARKER: == sanity test 123ad: Verify batching statahead works correctly ========================================================== 02:41:07 (1787121667) [ 6484.998559] Lustre: DEBUG MARKER: 'ls -l' 100 files without statahead: 4 sec [ 6488.340376] Lustre: DEBUG MARKER: 'ls -l' 100 files with statahead: 1 sec [ 6537.099929] Lustre: DEBUG MARKER: 'ls -l' 1000 files without statahead: 27 sec [ 6551.034879] Lustre: DEBUG MARKER: 'ls -l' 1000 files with statahead: 10 sec [ 6553.075457] Lustre: DEBUG MARKER: 'ls -l' done [ 6577.780807] Lustre: DEBUG MARKER: unlink + rm -r /mnt/lustre/d123ad.sanity: 23 seconds [ 7320.504705] Lustre: DEBUG MARKER: 'ls -l' 100 files without statahead: 4 sec [ 7324.627236] Lustre: DEBUG MARKER: 'ls -l' 100 files with statahead: 2 sec [ 7375.106942] Lustre: DEBUG MARKER: 'ls -l' 1000 files without statahead: 26 sec [ 7389.271224] Lustre: DEBUG MARKER: 'ls -l' 1000 files with statahead: 9 sec [ 7391.991269] Lustre: DEBUG MARKER: 'ls -l' done [ 7423.385511] Lustre: DEBUG MARKER: unlink + rm -r /mnt/lustre/d123ad.sanity: 29 seconds [ 8033.005167] Lustre: DEBUG MARKER: == sanity test 123b: not panic with network error in statahead enqueue (bug 15027) ========================================================== 03:07:09 (1787123229) [ 8064.302637] Lustre: DEBUG MARKER: ls done [ 8096.189968] Lustre: DEBUG MARKER: == sanity test 123c: Can not initialize inode warning on DNE statahead ========================================================== 03:08:12 (1787123292) [ 8107.784044] Lustre: DEBUG MARKER: == sanity test 123d: Statahead on striped directories works correctly ========================================================== 03:08:23 (1787123303) [ 8133.736653] Lustre: DEBUG MARKER: == sanity test 123e: statahead with large wide striping == 03:08:49 (1787123329) [ 8313.793923] Lustre: 6529:0:(mdt_handler.c:4704:mdt_unpack_req_pack_rep()) lustre-MDT0000: cannot pack response: rc = -75 [ 8501.407496] Lustre: DEBUG MARKER: == sanity test 123f: Retry mechanism with large wide striping files ========================================================== 03:14:53 (1787123693) [ 8659.523715] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x2c0000401 to 0x2c0000402 [ 8661.991634] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x280000401 to 0x280000402 [ 8969.147118] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x2c0000402 to 0x2c0000403 [ 8970.253039] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x280000402 to 0x280000403 [ 9571.270148] Lustre: 60503:0:(osd_handler.c:2191:osd_trans_start()) lustre-MDT0000: credits 30573 > trans_max 3200 [ 9571.291774] Lustre: 60503:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 4/16/0, destroy: 1/4/0 [ 9571.302233] Lustre: 60503:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 2003/2003/0, xattr_set: 3004/28292/0 [ 9571.317833] Lustre: 60503:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 20/166/0, punch: 0/0/0, quota 0/0/0 [ 9571.329117] Lustre: 60503:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 5/84/0, delete: 2/5/0 [ 9571.335555] Lustre: 60503:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 1/1/0, ref_del: 2/2/0 [ 9571.347188] CPU: 3 PID: 60503 Comm: mdt00_006 Kdump: loaded Tainted: G W O -------- - - 4.18.0rh8.10-debug #2 [ 9571.359160] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.17.0-10.fc44 06/10/2025 [ 9571.369196] Call Trace: [ 9571.373077] ? dump_stack+0xbb/0x10e [ 9571.375342] ? osd_trans_start+0x8db/0x9d0 [osd_ldiskfs] [ 9571.377875] ? dt_trans_start+0x1c/0x70 [obdclass] [ 9571.380779] ? top_trans_start+0x4fd/0xd00 [ptlrpc] [ 9571.383737] ? lod_declare_ref_add+0x1a/0x30 [lod] [ 9571.387237] ? dt_declare_ref_add+0x6c/0x200 [obdclass] [ 9571.389799] ? lod_trans_start+0x109/0x4c0 [lod] [ 9571.393255] ? mdd_declare_links_add+0x60/0x90 [mdd] [ 9571.395562] ? mdd_trans_start+0x18/0x30 [mdd] [ 9571.397554] ? mdd_unlink+0x7a4/0x13c0 [mdd] [ 9571.399556] ? mdt_reint_unlink+0x14aa/0x1a30 [mdt] [ 9571.402590] ? mdt_reint_rec+0x139/0x2b0 [mdt] [ 9571.404675] ? mdt_reint_internal+0x693/0xdc0 [mdt] [ 9571.406899] ? mdt_reint+0x163/0x190 [mdt] [ 9571.409732] ? tgt_handle_request0+0x137/0xaf0 [ptlrpc] [ 9571.412709] ? tgt_request_handle+0x575/0x1f70 [ptlrpc] [ 9571.416088] ? ptlrpc_server_handle_request+0x443/0x13b0 [ptlrpc] [ 9571.419449] ? lprocfs_counter_add+0x15b/0x210 [obdclass] [ 9571.422086] ? ptlrpc_main+0xce8/0x1400 [ptlrpc] [ 9571.425505] ? ptlrpc_wait_event+0x690/0x690 [ptlrpc] [ 9571.428335] ? kthread+0x1d1/0x200 [ 9571.429519] ? set_kthread_struct+0x70/0x70 [ 9571.431452] ? ret_from_fork+0x1f/0x30 [ 9632.583967] Lustre: 60506:0:(osd_handler.c:2191:osd_trans_start()) lustre-MDT0000: credits 30549 > trans_max 3200 [ 9632.611507] Lustre: 60506:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 4/16/0, destroy: 1/4/0 [ 9632.624106] Lustre: 60506:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 2003/2003/0, xattr_set: 3004/28292/0 [ 9632.646134] Lustre: 60506:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 20/142/0, punch: 0/0/0, quota 0/0/0 [ 9632.666516] Lustre: 60506:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 5/84/0, delete: 2/5/0 [ 9632.680048] Lustre: 60506:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 1/1/0, ref_del: 2/2/0 [ 9632.695596] CPU: 2 PID: 60506 Comm: mdt00_009 Kdump: loaded Tainted: G W O -------- - - 4.18.0rh8.10-debug #2 [ 9632.702158] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.17.0-10.fc44 06/10/2025 [ 9632.706635] Call Trace: [ 9632.710390] ? dump_stack+0xbb/0x10e [ 9632.714001] ? osd_trans_start+0x8db/0x9d0 [osd_ldiskfs] [ 9632.720758] ? dt_trans_start+0x1c/0x70 [obdclass] [ 9632.724125] ? top_trans_start+0x4fd/0xd00 [ptlrpc] [ 9632.729029] ? lod_declare_ref_add+0x1a/0x30 [lod] [ 9632.732561] ? dt_declare_ref_add+0x6c/0x200 [obdclass] [ 9632.743163] ? lod_trans_start+0x109/0x4c0 [lod] [ 9632.750145] ? mdd_declare_links_add+0x60/0x90 [mdd] [ 9632.757587] ? mdd_trans_start+0x18/0x30 [mdd] [ 9632.763459] ? mdd_unlink+0x7a4/0x13c0 [mdd] [ 9632.767207] ? mdt_reint_unlink+0x14aa/0x1a30 [mdt] [ 9632.771598] ? mdt_reint_rec+0x139/0x2b0 [mdt] [ 9632.775197] ? mdt_reint_internal+0x693/0xdc0 [mdt] [ 9632.786050] ? mdt_reint+0x163/0x190 [mdt] [ 9632.792672] ? tgt_handle_request0+0x137/0xaf0 [ptlrpc] [ 9632.800865] ? tgt_request_handle+0x575/0x1f70 [ptlrpc] [ 9632.812123] ? ptlrpc_server_handle_request+0x443/0x13b0 [ptlrpc] [ 9632.817971] ? lprocfs_counter_add+0x15b/0x210 [obdclass] [ 9632.826504] ? ptlrpc_main+0xce8/0x1400 [ptlrpc] [ 9632.839208] ? ptlrpc_wait_event+0x690/0x690 [ptlrpc] [ 9632.841558] ? kthread+0x1d1/0x200 [ 9632.851050] ? set_kthread_struct+0x70/0x70 [ 9632.854078] ? ret_from_fork+0x1f/0x30 [ 9697.783266] Lustre: 8983:0:(osd_handler.c:2191:osd_trans_start()) lustre-MDT0000: credits 30573 > trans_max 3200 [ 9697.790844] Lustre: 8983:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 4/16/0, destroy: 1/4/0 [ 9697.798208] Lustre: 8983:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 2003/2003/0, xattr_set: 3004/28292/0 [ 9697.813730] Lustre: 8983:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 20/166/0, punch: 0/0/0, quota 0/0/0 [ 9697.828224] Lustre: 8983:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 5/84/0, delete: 2/5/0 [ 9697.837735] Lustre: 8983:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 1/1/0, ref_del: 2/2/0 [ 9697.852640] CPU: 3 PID: 8983 Comm: mdt00_003 Kdump: loaded Tainted: G W O -------- - - 4.18.0rh8.10-debug #2 [ 9697.862427] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.17.0-10.fc44 06/10/2025 [ 9697.868309] Call Trace: [ 9697.869422] ? dump_stack+0xbb/0x10e [ 9697.871168] ? osd_trans_start+0x8db/0x9d0 [osd_ldiskfs] [ 9697.878280] ? dt_trans_start+0x1c/0x70 [obdclass] [ 9697.886459] ? top_trans_start+0x4fd/0xd00 [ptlrpc] [ 9697.891936] ? lod_declare_ref_add+0x1a/0x30 [lod] [ 9697.897889] ? dt_declare_ref_add+0x6c/0x200 [obdclass] [ 9697.909999] ? lod_trans_start+0x109/0x4c0 [lod] [ 9697.919693] ? mdd_declare_links_add+0x60/0x90 [mdd] [ 9697.931381] ? mdd_trans_start+0x18/0x30 [mdd] [ 9697.935825] ? mdd_unlink+0x7a4/0x13c0 [mdd] [ 9697.951014] ? mdt_reint_unlink+0x14aa/0x1a30 [mdt] [ 9697.955109] ? mdt_reint_rec+0x139/0x2b0 [mdt] [ 9697.958645] ? mdt_reint_internal+0x693/0xdc0 [mdt] [ 9697.965954] ? mdt_reint+0x163/0x190 [mdt] [ 9697.970451] ? tgt_handle_request0+0x137/0xaf0 [ptlrpc] [ 9697.981387] ? tgt_request_handle+0x575/0x1f70 [ptlrpc] [ 9697.987160] ? ptlrpc_server_handle_request+0x443/0x13b0 [ptlrpc] [ 9698.003328] ? lprocfs_counter_add+0x15b/0x210 [obdclass] [ 9698.014276] ? ptlrpc_main+0xce8/0x1400 [ptlrpc] [ 9698.026095] ? ptlrpc_wait_event+0x690/0x690 [ptlrpc] [ 9698.038664] ? kthread+0x1d1/0x200 [ 9698.049802] ? set_kthread_struct+0x70/0x70 [ 9698.058811] ? ret_from_fork+0x1f/0x30 [ 9758.612433] Lustre: 6525:0:(osd_handler.c:2191:osd_trans_start()) lustre-MDT0000: credits 30549 > trans_max 3200 [ 9758.631334] Lustre: 6525:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 4/16/0, destroy: 1/4/0 [ 9758.647889] Lustre: 6525:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 2003/2003/0, xattr_set: 3004/28292/0 [ 9758.674931] Lustre: 6525:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 20/142/0, punch: 0/0/0, quota 0/0/0 [ 9758.689893] Lustre: 6525:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 5/84/0, delete: 2/5/0 [ 9758.710453] Lustre: 6525:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 1/1/0, ref_del: 2/2/0 [ 9758.715881] CPU: 3 PID: 6525 Comm: mdt00_001 Kdump: loaded Tainted: G W O -------- - - 4.18.0rh8.10-debug #2 [ 9758.739437] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.17.0-10.fc44 06/10/2025 [ 9758.762588] Call Trace: [ 9758.763506] ? dump_stack+0xbb/0x10e [ 9758.769488] ? osd_trans_start+0x8db/0x9d0 [osd_ldiskfs] [ 9758.783483] ? dt_trans_start+0x1c/0x70 [obdclass] [ 9758.794285] ? top_trans_start+0x4fd/0xd00 [ptlrpc] [ 9758.806710] ? lod_declare_ref_add+0x1a/0x30 [lod] [ 9758.813195] ? dt_declare_ref_add+0x6c/0x200 [obdclass] [ 9758.819936] ? lod_trans_start+0x109/0x4c0 [lod] [ 9758.832931] ? mdd_declare_links_add+0x60/0x90 [mdd] [ 9758.839418] ? mdd_trans_start+0x18/0x30 [mdd] [ 9758.841177] ? mdd_unlink+0x7a4/0x13c0 [mdd] [ 9758.857095] ? mdt_reint_unlink+0x14aa/0x1a30 [mdt] [ 9758.862868] ? mdt_reint_rec+0x139/0x2b0 [mdt] [ 9758.870488] ? mdt_reint_internal+0x693/0xdc0 [mdt] [ 9758.883189] ? mdt_reint+0x163/0x190 [mdt] [ 9758.887981] ? tgt_handle_request0+0x137/0xaf0 [ptlrpc] [ 9758.899057] ? tgt_request_handle+0x575/0x1f70 [ptlrpc] [ 9758.904659] ? ptlrpc_server_handle_request+0x443/0x13b0 [ptlrpc] [ 9758.921298] ? lprocfs_counter_add+0x15b/0x210 [obdclass] [ 9758.943817] ? ptlrpc_main+0xce8/0x1400 [ptlrpc] [ 9758.967627] ? ptlrpc_wait_event+0x690/0x690 [ptlrpc] [ 9758.969436] ? kthread+0x1d1/0x200 [ 9758.970391] ? set_kthread_struct+0x70/0x70 [ 9758.992938] ? ret_from_fork+0x1f/0x30 [ 9830.330096] Lustre: DEBUG MARKER: == sanity test 123g: Test for stat-ahead advise ========== 03:37:02 (1787125022) [ 9943.920625] Lustre: DEBUG MARKER: == sanity test 123h: Verify statahead work with the fname pattern via du ========================================================== 03:38:58 (1787125138) [11943.374379] Lustre: DEBUG MARKER: == sanity test 123i: Verify statahead work with the fname indexing pattern ========================================================== 04:12:19 (1787127139) [12094.628820] Lustre: DEBUG MARKER: == sanity test 123j: -ENOENT error from batched statahead be handled correctly ========================================================== 04:14:50 (1787127290) [12105.742662] Lustre: DEBUG MARKER: == sanity test 123k: Verify statahead work with mdtest shared stat() mode ========================================================== 04:15:01 (1787127301) [12107.963929] Lustre: DEBUG MARKER: SKIP: sanity test_123k mdtest not found [12110.018127] Lustre: DEBUG MARKER: == sanity test 123l: Avoid panic when revalidate a local cached entry ========================================================== 04:15:05 (1787127305) [12195.019366] Lustre: DEBUG MARKER: == sanity test 124a: lru resize ================================================================================================= 04:16:30 (1787127390) [12197.494425] Lustre: DEBUG MARKER: create 2000 files at /mnt/lustre/d124a.sanity [12253.482639] Lustre: DEBUG MARKER: NSDIR=ldlm.namespaces.lustre-MDT0000-mdc-ffff9b918b752800 [12255.553840] Lustre: DEBUG MARKER: NS=ldlm.namespaces.lustre-MDT0000-mdc-ffff9b918b752800 [12257.341430] Lustre: DEBUG MARKER: LRU=1015 [12259.005578] Lustre: DEBUG MARKER: LIMIT=46162 [12260.929721] Lustre: DEBUG MARKER: LVF=5457500 [12262.808949] Lustre: DEBUG MARKER: OLD_LVF=100 [12264.840078] Lustre: DEBUG MARKER: Sleep 50 sec [12318.277742] Lustre: DEBUG MARKER: Dropped 547 locks in 50s [12319.948249] Lustre: DEBUG MARKER: unlink 2000 files at /mnt/lustre/d124a.sanity [12359.497486] Lustre: DEBUG MARKER: == sanity test 124b: lru resize (performance test) ================================================================================= 04:19:15 (1787127555) [12510.204531] Lustre: DEBUG MARKER: doing ls -la /mnt/lustre/d124b.sanity/disable_lru_resize 3 times [12700.442559] Lustre: DEBUG MARKER: ls -la time: 188 seconds [12702.248436] Lustre: DEBUG MARKER: lru_size = 400 [12972.659209] Lustre: DEBUG MARKER: doing ls -la /mnt/lustre/d124b.sanity/enable_lru_resize 3 times [13079.339915] Lustre: DEBUG MARKER: ls -la time: 99 seconds [13081.324899] Lustre: DEBUG MARKER: lru_size = 4052 [13083.258692] Lustre: DEBUG MARKER: ls -la is 47% faster with lru resize enabled [13169.757471] Lustre: DEBUG MARKER: == sanity test 124c: LRUR cancel very aged locks ========= 04:32:45 (1787128365) [13204.727493] Lustre: DEBUG MARKER: == sanity test 124d: cancel very aged locks if lru-resize disabled ========================================================== 04:33:20 (1787128400) [13239.388390] Lustre: DEBUG MARKER: == sanity test 124e: LFRU keep priv locks from eviction == 04:33:55 (1787128435) [13295.949184] Lustre: DEBUG MARKER: == sanity test 124f: LFRU priv threshold inc/dec adjustment ========================================================== 04:34:52 (1787128492) [13396.021346] Lustre: DEBUG MARKER: == sanity test 124g: LFRU performance test =============== 04:36:31 (1787128591) [14519.475232] Lustre: DEBUG MARKER: == sanity test 125: don't return EPROTO when a dir has a non-default striping and ACLs ========================================================== 04:55:15 (1787129715) [14529.576328] Lustre: DEBUG MARKER: == sanity test 126: check that the fsgid provided by the client is taken into account ========================================================== 04:55:25 (1787129725) [14539.308653] Lustre: DEBUG MARKER: == sanity test 127a: verify the client stats are sane ==== 04:55:34 (1787129734) [14550.572827] Lustre: DEBUG MARKER: == sanity test 127b: verify the llite client stats are sane ========================================================== 04:55:46 (1787129746) [14560.789922] Lustre: DEBUG MARKER: == sanity test 127c: test llite extent stats with regular [14599.894889] Lustre: DEBUG MARKER: == sanity test 127d: OSC RPC latency histograms for read and write latency ========================================================== 04:56:35 (1787129795) [14614.403836] Lustre: DEBUG MARKER: == sanity test 127e: client IO latency histograms by size ========================================================== 04:56:49 (1787129809) [14635.536919] Lustre: DEBUG MARKER: == sanity test 127f: OST IO latency histograms by size === 04:57:11 (1787129831) [14663.816373] Lustre: DEBUG MARKER: == sanity test 128: interactive lfs for 2 consecutive find's ========================================================== 04:57:39 (1787129859) [14672.335277] Lustre: DEBUG MARKER: == sanity test 129: test directory size limit ================================================================================== 04:57:48 (1787129868) [14698.997768] Lustre: 60504:0:(osd_handler.c:613:osd_ldiskfs_add_entry()) lustre-MDT0000: directory (inode: 513253, FID: [0x20000040c:0x907a:0x0]) is approaching max size limit [14726.213734] Lustre: 6526:0:(osd_handler.c:609:osd_ldiskfs_add_entry()) lustre-MDT0000: directory (inode: 513253, FID: [0x20000040c:0x907a:0x0]) has reached max size limit [14771.396222] Lustre: DEBUG MARKER: == sanity test 130a: FIEMAP (1-stripe file) ============== 04:59:26 (1787129966) [14780.156785] Lustre: DEBUG MARKER: == sanity test 130b: FIEMAP (2-stripe file) ============== 04:59:36 (1787129976) [14790.401434] Lustre: DEBUG MARKER: == sanity test 130c: FIEMAP (2-stripe file with hole) ==== 04:59:46 (1787129986) [14801.828791] Lustre: DEBUG MARKER: == sanity test 130d: FIEMAP (N-stripe file) ============== 04:59:57 (1787129997) [14804.140407] Lustre: DEBUG MARKER: SKIP: sanity test_130d needs >= 3 OSTs [14806.599510] Lustre: DEBUG MARKER: == sanity test 130e: FIEMAP (test continuation FIEMAP calls) ========================================================== 05:00:02 (1787130002) [14896.812827] Lustre: DEBUG MARKER: == sanity test 130f: FIEMAP (unstriped file) ============= 05:01:32 (1787130092) [14905.847302] Lustre: DEBUG MARKER: == sanity test 130g: FIEMAP (overstripe file) ============ 05:01:41 (1787130101) [14952.440761] Lustre: 10107:0:(osd_handler.c:2191:osd_trans_start()) lustre-MDT0000: credits 6549 > trans_max 3200 [14952.455706] Lustre: 10107:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 4/16/0, destroy: 1/4/0 [14952.469109] Lustre: 10107:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 403/403/0, xattr_set: 604/5892/0 [14952.486868] Lustre: 10107:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 20/142/0, punch: 0/0/0, quota 0/0/0 [14952.502829] Lustre: 10107:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 5/84/0, delete: 2/5/0 [14952.514539] Lustre: 10107:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 1/1/0, ref_del: 2/2/0 [14952.521476] CPU: 0 PID: 10107 Comm: mdt00_004 Kdump: loaded Tainted: G W O -------- - - 4.18.0rh8.10-debug #2 [14952.534722] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.17.0-10.fc44 06/10/2025 [14952.542749] Call Trace: [14952.544128] ? dump_stack+0xbb/0x10e [14952.546159] ? osd_trans_start+0x8db/0x9d0 [osd_ldiskfs] [14952.551649] ? dt_trans_start+0x1c/0x70 [obdclass] [14952.563049] ? top_trans_start+0x4fd/0xd00 [ptlrpc] [14952.571321] ? lod_declare_ref_add+0x1a/0x30 [lod] [14952.574741] ? dt_declare_ref_add+0x6c/0x200 [obdclass] [14952.578543] ? lod_trans_start+0x109/0x4c0 [lod] [14952.582505] ? mdd_declare_links_add+0x60/0x90 [mdd] [14952.586243] ? mdd_trans_start+0x18/0x30 [mdd] [14952.595198] ? mdd_unlink+0x7a4/0x13c0 [mdd] [14952.600228] ? mdt_reint_unlink+0x14aa/0x1a30 [mdt] [14952.602849] ? mdt_reint_rec+0x139/0x2b0 [mdt] [14952.606740] ? mdt_reint_internal+0x693/0xdc0 [mdt] [14952.610957] ? mdt_reint+0x163/0x190 [mdt] [14952.614067] ? tgt_handle_request0+0x137/0xaf0 [ptlrpc] [14952.619186] ? tgt_request_handle+0x575/0x1f70 [ptlrpc] [14952.626877] ? ptlrpc_server_handle_request+0x443/0x13b0 [ptlrpc] [14952.632700] ? lprocfs_counter_add+0x15b/0x210 [obdclass] [14952.641742] ? ptlrpc_main+0xce8/0x1400 [ptlrpc] [14952.648944] ? ptlrpc_wait_event+0x690/0x690 [ptlrpc] [14952.656785] ? kthread+0x1d1/0x200 [14952.659699] ? set_kthread_struct+0x70/0x70 [14952.664198] ? ret_from_fork+0x1f/0x30 [14961.447454] Lustre: DEBUG MARKER: == sanity test 130h: FIEMAP deadlock ===================== 05:02:37 (1787130157) [14977.598975] Lustre: DEBUG MARKER: == sanity test 130i: FIEMAP (DoM file) =================== 05:02:53 (1787130173) [15036.702260] Lustre: DEBUG MARKER: == sanity test 131a: test iov's crossing stripe boundary for writev/readv ========================================================== 05:03:52 (1787130232) [15046.315234] Lustre: DEBUG MARKER: == sanity test 131b: test append writev ================== 05:04:02 (1787130242) [15055.534265] Lustre: DEBUG MARKER: == sanity test 131c: test read/write on file w/o objects ========================================================== 05:04:11 (1787130251) [15064.366298] Lustre: DEBUG MARKER: == sanity test 131d: test short read ===================== 05:04:20 (1787130260) [15074.343889] Lustre: DEBUG MARKER: == sanity test 131e: test read hitting hole ============== 05:04:29 (1787130269) [15083.717041] Lustre: DEBUG MARKER: == sanity test 133a: Verifying MDT stats ================================================================================================== 05:04:39 (1787130279) [15108.096370] Lustre: DEBUG MARKER: == sanity test 133b: Verifying extra MDT stats ============================================================================================ 05:05:03 (1787130303) [15121.820481] Lustre: DEBUG MARKER: == sanity test 133c: Verifying OST stats ================================================================================================== 05:05:18 (1787130318) [15162.224886] Lustre: DEBUG MARKER: == sanity test 133d: Verifying rename_stats ================================================================================================== 05:05:58 (1787130358) [15210.639632] Lustre: DEBUG MARKER: == sanity test 133e: Verifying OST read_bytes write_bytes nid stats =========================================================================== 05:06:46 (1787130406) [15222.745811] Lustre: DEBUG MARKER: == sanity test 133f: Check reads/writes of client lustre proc files with bad area io ========================================================== 05:06:59 (1787130419) [15251.941670] 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 [15251.947042] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [15251.976880] Lustre: Skipped 2 previous similar messages [15251.983646] Lustre: Skipped 1 previous similar message [15257.064455] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [15257.071917] Lustre: Skipped 3 previous similar messages [15258.358067] Lustre: server umount lustre-MDT0000 complete [15262.190825] LustreError: 6525:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: 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. [15262.205336] LustreError: 6525:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 3 previous similar messages [15267.105819] LustreError: 6510:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787130464 with bad export cookie 2256252640701240652 [15267.116103] LustreError: MGC192.168.204.138@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [15267.121648] LustreError: 6510:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [15267.297581] Lustre: lustre-MDT0001-lwp-OST0001: Connection to lustre-MDT0001 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [15267.299568] LustreError: 8983:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: 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. [15267.314589] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [15267.324148] Lustre: Skipped 2 previous similar messages [15267.357924] LustreError: 8983:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 1 previous similar message [15267.709279] Lustre: server umount lustre-MDT0001 complete [15277.710355] Lustre: server umount lustre-OST0000 complete [15288.397768] Lustre: server umount lustre-OST0001 complete [15305.444579] Lustre: DEBUG MARKER: oleg438-server.virtnet: executing unload_modules_local [15308.735534] Key type lgssc unregistered [15309.090927] LNet: 107004:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [15309.103702] LNetError: 107004:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [15309.134931] LNet: Removed LNI 192.168.204.138@tcp [15310.166179] Key type .llcrypt unregistered [15310.168036] Key type ._llcrypt unregistered [15325.097637] Key type ._llcrypt registered [15325.099350] Key type .llcrypt registered [15325.286502] Lustre: DEBUG MARKER: oleg438-server.virtnet: executing load_modules_local [15326.420292] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [15326.485390] alg: No test for adler32 (adler32-zlib) [15327.590470] Lustre: Lustre: Build Version: 2.17.56_4_gb718cad [15327.924950] LNet: Added LNI 192.168.204.138@tcp [8/256/0/180] [15329.752462] Key type lgssc registered [15330.980972] Lustre: Echo OBD driver; http://www.lustre.org/ [15350.078543] Lustre: DEBUG MARKER: oleg438-server.virtnet: executing load_modules_local [15365.307976] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [15365.353856] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [15367.104652] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [15372.815502] Lustre: DEBUG MARKER: oleg438-server.virtnet: executing set_default_debug all all [15376.361951] LustreError: 109061:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0001: 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. [15376.394611] LustreError: 109061:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 2 previous similar messages [15381.483945] LustreError: 109060:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0001: 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. [15386.597151] LustreError: 109061:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0001: 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. [15387.107478] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [15387.780200] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [15393.090476] Lustre: DEBUG MARKER: oleg438-server.virtnet: executing set_default_debug all all [15396.334348] Lustre: 110359:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [15407.925225] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [15408.450799] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [15411.512272] LustreError: 110866: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. [15411.549160] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000403:24905 to 0x280000403:24961) [15412.562704] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:12050 to 0x280000400:12065) [15415.321106] Lustre: DEBUG MARKER: oleg438-server.virtnet: executing set_default_debug all all [15417.840878] LustreError: 110866: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. [15417.864104] LustreError: 110866:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 3 previous similar messages [15428.073902] LustreError: 111040: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. [15428.096123] LustreError: 111040:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 3 previous similar messages [15428.676568] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [15429.259411] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [15434.257805] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000403:26112 to 0x2c0000403:26241) [15434.265315] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:12213 to 0x2c0000400:12257) [15436.775267] Lustre: DEBUG MARKER: oleg438-server.virtnet: executing set_default_debug all all [15446.181708] Lustre: DEBUG MARKER: Using TIMEOUT=20 [15450.797874] Lustre: 112542:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [15460.628180] Lustre: DEBUG MARKER: == sanity test 133g: Check reads/writes of server lustre proc files with bad area io ========================================================== 05:10:56 (1787130656) [15469.518690] LNet: 113035:0:(debug.c:376:cfs_str2mask()) unknown mask ''. [15469.518690] mask usage: [+|-] ... [15470.251272] LNet: 113079:0:(debug.c:376:cfs_str2mask()) unknown mask ''. [15470.251272] mask usage: [+|-] ... [15470.268993] LNet: 113079:0:(debug.c:376:cfs_str2mask()) Skipped 5 previous similar messages [15470.333840] Lustre: DEBUG MARKER:  [15470.336127] Lustre: DEBUG MARKER:  [15471.349300] LNet: 113180:0:(debug.c:376:cfs_str2mask()) unknown mask ''. [15471.349300] mask usage: [+|-] ... [15471.357549] LNet: 113180:0:(debug.c:376:cfs_str2mask()) Skipped 1 previous similar message [15535.096052] LNet: 114730:0:(debug.c:376:cfs_str2mask()) unknown mask ''. [15535.096052] mask usage: [+|-] ... [15535.114446] LNet: 114730:0:(debug.c:376:cfs_str2mask()) Skipped 1 previous similar message [15535.855473] Lustre: DEBUG MARKER:  [15535.860854] Lustre: DEBUG MARKER:  [15602.658089] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [15602.675272] Lustre: lustre-MDT0000-osp-MDT0001: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [15602.705576] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [15603.181234] 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 [15603.194455] Lustre: Skipped 2 previous similar messages [15608.144097] Lustre: server umount lustre-MDT0000 complete [15608.301263] LustreError: 109947:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: 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. [15608.329314] LustreError: 109947:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 3 previous similar messages [15617.568738] LustreError: 109039:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787130815 with bad export cookie 13029649085516071137 [15617.570457] LustreError: MGC192.168.204.138@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [15617.588223] LustreError: 109039:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [15618.141713] Lustre: server umount lustre-MDT0001 complete [15634.721741] Lustre: 107456:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787130816/real 1787130816] req@ffff9a7972a51500 x1873942177519488/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787130832 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'' uid:0 gid:0 projid:4294967295 [15634.768269] Lustre: lustre-MDT0001-lwp-OST0001: Connection to lustre-MDT0001 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [15638.194995] Lustre: server umount lustre-OST0000 complete [15639.011694] Lustre: 107458:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787130820/real 1787130820] req@ffff9a7955355500 x1873942177519744/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787130836 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'' uid:0 gid:0 projid:4294967295 [15640.032172] Lustre: 107457:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787130821/real 1787130821] req@ffff9a79545dca80 x1873942177520000/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787130837 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'' uid:0 gid:0 projid:4294967295 [15644.129638] Lustre: 107459:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787130825/real 1787130825] req@ffff9a7955354700 x1873942177520384/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787130841 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'' uid:0 gid:0 projid:4294967295 [15647.450710] Lustre: server umount lustre-OST0001 complete [15665.732674] Lustre: DEBUG MARKER: oleg438-server.virtnet: executing unload_modules_local [15669.882898] Key type lgssc unregistered [15670.284217] LNet: 118526:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [15670.299956] LNetError: 118526:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [15670.328078] LNet: Removed LNI 192.168.204.138@tcp [15671.733317] Key type .llcrypt unregistered [15671.736701] Key type ._llcrypt unregistered [15687.001580] Key type ._llcrypt registered [15687.013885] Key type .llcrypt registered [15687.134041] Lustre: DEBUG MARKER: oleg438-server.virtnet: executing load_modules_local [15688.467243] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [15688.522350] alg: No test for adler32 (adler32-zlib) [15689.578306] Lustre: Lustre: Build Version: 2.17.56_4_gb718cad [15689.835083] LNet: Added LNI 192.168.204.138@tcp [8/256/0/180] [15691.528312] Key type lgssc registered [15692.771743] Lustre: Echo OBD driver; http://www.lustre.org/ [15710.195366] Lustre: DEBUG MARKER: oleg438-server.virtnet: executing load_modules_local [15723.016090] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [15723.049754] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [15724.635622] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [15729.574576] Lustre: DEBUG MARKER: oleg438-server.virtnet: executing set_default_debug all all [15734.760847] LustreError: 120596:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0001: 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. [15734.782338] LustreError: 120596:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 2 previous similar messages [15739.875987] LustreError: 120597:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0001: 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. [15742.698363] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [15743.446515] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [15749.440365] Lustre: DEBUG MARKER: oleg438-server.virtnet: executing set_default_debug all all [15753.375141] Lustre: 121894:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [15766.045725] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [15766.533637] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [15768.548211] LustreError: 122403: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. [15768.607685] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:12050 to 0x280000400:12097) [15769.634272] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000403:24905 to 0x280000403:24993) [15773.568038] Lustre: DEBUG MARKER: oleg438-server.virtnet: executing set_default_debug all all [15774.699189] LustreError: 122402: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. [15774.719435] LustreError: 122402:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 2 previous similar messages [15779.816525] LustreError: 122501: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. [15779.838902] LustreError: 122501:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 1 previous similar message [15786.965845] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [15787.516037] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [15792.657467] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:12213 to 0x2c0000400:12289) [15792.683173] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000403:26112 to 0x2c0000403:26273) [15794.587895] Lustre: DEBUG MARKER: oleg438-server.virtnet: executing set_default_debug all all [15803.776422] Lustre: DEBUG MARKER: Using TIMEOUT=20 [15807.419036] Lustre: 124077:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [15815.502506] Lustre: DEBUG MARKER: == sanity test 133h: Proc files should end with newlines ========================================================== 05:16:51 (1787131011) [17169.723813] Lustre: DEBUG MARKER: == sanity test 134a: Server reclaims locks when reaching lock_reclaim_threshold ========================================================== 05:39:25 (1787132365) [17196.248143] Lustre: *** cfs_fail_loc=327, val=500*** [17198.479048] Lustre: *** cfs_fail_loc=327, val=500*** [17198.486058] Lustre: Skipped 512 previous similar messages [17248.031677] Lustre: DEBUG MARKER: == sanity test 134b: Server rejects lock request when reaching lock_limit_mb ========================================================== 05:40:43 (1787132443) [17256.530881] Lustre: *** cfs_fail_loc=328, val=500*** [17258.536554] Lustre: *** cfs_fail_loc=328, val=500*** [17258.542206] Lustre: Skipped 81 previous similar messages [17261.160268] Lustre: 120592:0:(ldlm_lockd.c:1326:ldlm_handle_enqueue()) @@@ Too many granted locks, reject current enqueue request and let the client retry later req@ffff9a7a7ebb0e00 x1873942543437568/t0(0) o101->6152aa83-3ff2-4426-a9d9-b1e7f6055290@192.168.204.38@tcp:660/0 lens 648/0 e 0 to 0 dl 1787132470 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [17262.553396] Lustre: *** cfs_fail_loc=328, val=500*** [17262.558400] Lustre: Skipped 186 previous similar messages [17264.313345] Lustre: 120592:0:(ldlm_lockd.c:1326:ldlm_handle_enqueue()) @@@ Too many granted locks, reject current enqueue request and let the client retry later req@ffff9a794f6ece00 x1873942543502080/t0(0) o101->6152aa83-3ff2-4426-a9d9-b1e7f6055290@192.168.204.38@tcp:663/0 lens 648/0 e 0 to 0 dl 1787132473 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [17265.414453] Lustre: 124291:0:(ldlm_lockd.c:1326:ldlm_handle_enqueue()) @@@ Too many granted locks, reject current enqueue request and let the client retry later req@ffff9a7983b5f480 x1873942543502848/t0(0) o101->6152aa83-3ff2-4426-a9d9-b1e7f6055290@192.168.204.38@tcp:664/0 lens 648/0 e 0 to 0 dl 1787132474 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [17268.688127] Lustre: 124291:0:(ldlm_lockd.c:1326:ldlm_handle_enqueue()) @@@ Too many granted locks, reject current enqueue request and let the client retry later req@ffff9a7a7fa0ea00 x1873942543535872/t0(0) o101->6152aa83-3ff2-4426-a9d9-b1e7f6055290@192.168.204.38@tcp:667/0 lens 648/0 e 0 to 0 dl 1787132477 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [17268.715993] Lustre: 124291:0:(ldlm_lockd.c:1326:ldlm_handle_enqueue()) Skipped 1 previous similar message [17270.862403] Lustre: *** cfs_fail_loc=328, val=500*** [17270.879335] Lustre: Skipped 173 previous similar messages [17273.486447] Lustre: 120592:0:(ldlm_lockd.c:1326:ldlm_handle_enqueue()) @@@ Too many granted locks, reject current enqueue request and let the client retry later req@ffff9a7972a50700 x1873942543553536/t0(0) o101->6152aa83-3ff2-4426-a9d9-b1e7f6055290@192.168.204.38@tcp:672/0 lens 648/0 e 0 to 0 dl 1787132482 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [17273.526488] Lustre: 120592:0:(ldlm_lockd.c:1326:ldlm_handle_enqueue()) Skipped 3 previous similar messages [17277.936670] LustreError: 187744:0:(ldlm_lockd.c:3246:lock_reclaim_threshold_mb_store()) Failed to set lock_reclaim_threshold_mb, rc = -22. [17299.583448] Lustre: DEBUG MARKER: == sanity test 134c: Lock memory accounting includes associated structures ========================================================== 05:41:34 (1787132494) [17320.868087] Lustre: DEBUG MARKER: SKIP: sanity test_135 skipping SLOW test 135 [17323.600882] Lustre: DEBUG MARKER: SKIP: sanity test_136 skipping SLOW test 136 [17325.904800] Lustre: DEBUG MARKER: == sanity test 140: Check reasonable stack depth (shouldn't LBUG) ============================================================== 05:42:01 (1787132521) [17391.922974] Lustre: DEBUG MARKER: == sanity test 150a: truncate/append tests =============== 05:43:07 (1787132587) [17427.046828] Lustre: DEBUG MARKER: == sanity test 150b: Verify fallocate (prealloc) functionality ========================================================== 05:43:42 (1787132622) [17468.263411] Lustre: DEBUG MARKER: == sanity test 150bb: Verify fallocate modes both zero space ========================================================== 05:44:23 (1787132663) [17514.663622] Lustre: DEBUG MARKER: == sanity test 150c: Verify fallocate Size and Blocks ==== 05:45:10 (1787132710) [17539.038859] Lustre: DEBUG MARKER: == sanity test 150d: Verify fallocate Size and Blocks - Non zero start ========================================================== 05:45:34 (1787132734) [17569.472529] Lustre: DEBUG MARKER: == sanity test 150e: Verify 60% of available OST space consumed by fallocate ========================================================== 05:46:04 (1787132764) [17606.599110] Lustre: DEBUG MARKER: == sanity test 150f: Verify fallocate punch functionality ========================================================== 05:46:41 (1787132801) [17637.284929] Lustre: DEBUG MARKER: == sanity test 150g: Verify fallocate punch on large range ========================================================== 05:47:13 (1787132833) [17673.412333] Lustre: DEBUG MARKER: == sanity test 150h: Verify extend fallocate updates the file size ========================================================== 05:47:49 (1787132869) [17684.680977] Lustre: DEBUG MARKER: == sanity test 150ia: Verify fallocate zero-range ZERO functionality ========================================================== 05:48:00 (1787132880) [17709.371224] Lustre: DEBUG MARKER: == sanity test 150ib: Verify fallocate zero-range PREALLOC functionality ========================================================== 05:48:25 (1787132905) [17740.848979] Lustre: DEBUG MARKER: == sanity test 150ic: Verify fallocate LARGE zero PREALLOC functionality ========================================================== 05:48:56 (1787132936) [17743.021414] Lustre: DEBUG MARKER: SKIP: sanity test_150ic only check on DoM component [17745.674362] Lustre: DEBUG MARKER: == sanity test 151: test cache on oss and controls ========================================================================================= 05:49:01 (1787132941) [17771.063956] bash (197231): drop_caches: 1 [17788.083915] Lustre: DEBUG MARKER: == sanity test 152: test read/write with enomem ====================================================================================== 05:49:44 (1787132984) [17797.693254] Lustre: DEBUG MARKER: == sanity test 153: test if fdatasync does not crash ================================================================================= 05:49:53 (1787132993) [17806.524905] Lustre: DEBUG MARKER: == sanity test 154A: lfs path2fid and fid2path basic checks ========================================================== 05:50:02 (1787133002) [17816.342541] Lustre: DEBUG MARKER: == sanity test 154B: verify the ll_decode_linkea tool ==== 05:50:11 (1787133011) [17825.355506] Lustre: DEBUG MARKER: == sanity test 154C: lfs fid2path on OST FID ============= 05:50:21 (1787133021) [17854.603904] Lustre: DEBUG MARKER: == sanity test 154a: Open-by-FID ========================= 05:50:48 (1787133048) [17860.240539] LustreError: 120603:0:(fld_handler.c:268:fld_server_lookup()) srv-lustre-MDT0000: Cannot find sequence 0xf00000400: rc = -2 [17875.089642] Lustre: DEBUG MARKER: == sanity test 154b: Open-by-FID for remote directory ==== 05:51:10 (1787133070) [17877.735834] LustreError: 120603:0:(fld_handler.c:268:fld_server_lookup()) srv-lustre-MDT0000: Cannot find sequence 0xf00000400: rc = -2 [17877.746517] LustreError: 120603:0:(fld_handler.c:268:fld_server_lookup()) Skipped 3 previous similar messages [17889.244985] Lustre: DEBUG MARKER: == sanity test 154c: lfs path2fid and fid2path multiple arguments ========================================================== 05:51:24 (1787133084) [17901.535613] Lustre: DEBUG MARKER: == sanity test 154d: Verify open file fid ================ 05:51:36 (1787133096) [17915.282963] Lustre: DEBUG MARKER: == sanity test 154db: fid is stored in dir entries ======= 05:51:50 (1787133110) [17937.801632] Lustre: DEBUG MARKER: == sanity test 154e: .lustre is not returned by readdir == 05:52:13 (1787133133) [17948.668107] Lustre: DEBUG MARKER: == sanity test 154ea: .lustre is not returned by readdir (2) ========================================================== 05:52:24 (1787133144) [18029.160812] Lustre: DEBUG MARKER: == sanity test 154f: get parent fids by reading link ea == 05:53:44 (1787133224) [18039.441477] Lustre: DEBUG MARKER: == sanity test 154g: various llapi FID tests ============= 05:53:55 (1787133235) [19434.088592] Lustre: DEBUG MARKER: == sanity test 154h: Verify interactive path2fid ========= 06:17:10 (1787134630) [19442.161262] Lustre: DEBUG MARKER: == sanity test 154i: fid2path for path longer than PATH_MAX ========================================================== 06:17:18 (1787134638) [19493.629552] Lustre: DEBUG MARKER: == sanity test 154j: fid2path for long path crossing MDT boundary ========================================================== 06:18:09 (1787134689) [19522.732904] Lustre: DEBUG MARKER: == sanity test 155a: Verify small file correctness: read cache:on write_cache:on ========================================================== 06:18:38 (1787134718) [19540.357377] Lustre: DEBUG MARKER: == sanity test 155b: Verify small file correctness: read cache:on write_cache:off ========================================================== 06:18:56 (1787134736) [19559.522649] Lustre: DEBUG MARKER: == sanity test 155c: Verify small file correctness: read cache:off write_cache:on ========================================================== 06:19:14 (1787134754) [19578.084551] Lustre: DEBUG MARKER: == sanity test 155d: Verify small file correctness: read cache:off write_cache:off ========================================================== 06:19:33 (1787134773) [19594.342364] Lustre: DEBUG MARKER: == sanity test 155e: Verify big file correctness: read cache:on write_cache:on ========================================================== 06:19:50 (1787134790) [19646.139499] Lustre: DEBUG MARKER: == sanity test 155f: Verify big file correctness: read cache:on write_cache:off ========================================================== 06:20:41 (1787134841) [19699.769865] Lustre: DEBUG MARKER: == sanity test 155g: Verify big file correctness: read cache:off write_cache:on ========================================================== 06:21:35 (1787134895) [19756.028276] Lustre: DEBUG MARKER: == sanity test 155h: Verify big file correctness: read cache:off write_cache:off ========================================================== 06:22:31 (1787134951) [19807.949770] Lustre: DEBUG MARKER: == sanity test 156: Verification of tunables ============= 06:23:23 (1787135003) [19819.965126] Lustre: DEBUG MARKER: Turn on read and write cache [19824.363884] Lustre: DEBUG MARKER: Write data and read it back. [19826.367333] Lustre: DEBUG MARKER: Read should be satisfied from the cache. [19830.978934] Lustre: DEBUG MARKER: cache hits: before: 28718, after: 28721 [19832.696754] Lustre: DEBUG MARKER: Read again; it should be satisfied from the cache. [19835.972855] Lustre: DEBUG MARKER: cache hits:: before: 28721, after: 28724 [19837.674351] Lustre: DEBUG MARKER: Turn off the read cache and turn on the write cache [19841.802270] Lustre: DEBUG MARKER: Read again; it should be satisfied from the cache. [19846.274318] Lustre: DEBUG MARKER: cache hits:: before: 28724, after: 28727 [19848.650117] Lustre: DEBUG MARKER: Write data and read it back. [19850.556614] Lustre: DEBUG MARKER: Read should be satisfied from the cache. [19855.259291] Lustre: DEBUG MARKER: cache hits:: before: 28727, after: 28730 [19857.066487] Lustre: DEBUG MARKER: Turn off read and write cache [19861.509629] Lustre: DEBUG MARKER: Write data and read it back [19863.333484] Lustre: DEBUG MARKER: It should not be satisfied from the cache. [19868.007728] Lustre: DEBUG MARKER: cache hits:: before: 28730, after: 28730 [19870.074660] Lustre: DEBUG MARKER: Turn on the read cache and turn off the write cache [19875.480761] Lustre: DEBUG MARKER: Write data and read it back [19877.410544] Lustre: DEBUG MARKER: It should not be satisfied from the cache. [19882.463323] Lustre: DEBUG MARKER: cache hits:: before: 28730, after: 28730 [19884.307767] Lustre: DEBUG MARKER: Read again; it should be satisfied from the cache. [19888.507918] Lustre: DEBUG MARKER: cache hits:: before: 28730, after: 28733 [19898.990862] Lustre: DEBUG MARKER: == sanity test 157a: llapi pool pinning API tests ======== 06:24:54 (1787135094) [19907.738335] Lustre: DEBUG MARKER: == sanity test 157b: lustre.pin inheritance on create ==== 06:25:04 (1787135104) [19915.972312] Lustre: DEBUG MARKER: == sanity test 160a: changelog sanity ==================== 06:25:12 (1787135112) [19919.186597] Lustre: lustre-MDD0000: changelog on [19921.814590] Lustre: lustre-MDD0001: changelog on [19940.187303] Lustre: Failing over lustre-MDT0000 [19940.622171] Lustre: server umount lustre-MDT0000 complete [19941.290801] LustreError: 120592:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.204.38@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [19941.305502] LustreError: 120592:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 2 previous similar messages [19941.857228] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [19941.863566] Lustre: lustre-MDT0000-osp-MDT0001: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [19944.932295] Lustre: lustre-MDT0000-lwp-MDT0001: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [19944.935400] LustreError: 120593:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: 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. [19944.946283] Lustre: Skipped 1 previous similar message [19944.976872] LustreError: 120593:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 4 previous similar messages [19949.985505] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [19950.053598] LustreError: 200888:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: 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. [19950.068035] LustreError: 200888:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 4 previous similar messages [19950.138592] LustreError: MGC192.168.204.138@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [19950.425864] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [19950.471816] Lustre: lustre-MDD0000: changelog on [19950.512339] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [19951.479167] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [19955.212164] Lustre: DEBUG MARKER: oleg438-server.virtnet: executing set_default_debug all all [19955.710091] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [19956.349585] Lustre: lustre-MDT0000: Recovery over after 0:05, of 2 clients 2 recovered and 0 were evicted. [19956.350204] Lustre: lustre-MDT0000-osp-MDT0001: Connection restored to 0@lo (at 0@lo) [19956.375267] Lustre: Skipped 2 previous similar messages [19956.391321] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000403:27164 to 0x2c0000403:27201) [19956.399142] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000403:25886 to 0x280000403:25921) [19959.926764] Lustre: lustre-MDD0000: changelog off [19961.734482] Lustre: lustre-MDD0001: changelog off [19978.094443] Lustre: DEBUG MARKER: == sanity test 160b: Verify that very long rename doesn't crash in changelog ========================================================== 06:26:14 (1787135174) [19981.633898] Lustre: lustre-MDD0000: changelog on [19995.081522] Lustre: lustre-MDD0001: changelog off [19997.925327] Lustre: lustre-MDD0000: changelog off [20001.356110] Lustre: DEBUG MARKER: == sanity test 160c: verify that changelog log catch the truncate event ========================================================== 06:26:37 (1787135197) [20005.173919] Lustre: lustre-MDD0000: changelog on [20005.179722] Lustre: Skipped 1 previous similar message [20021.759136] Lustre: lustre-MDD0001: changelog off [20028.949399] Lustre: DEBUG MARKER: == sanity test 160d: verify that changelog log catch the migrate event ========================================================== 06:27:04 (1787135224) [20032.726522] Lustre: lustre-MDD0000: changelog on [20032.735144] Lustre: Skipped 1 previous similar message [20045.534887] Lustre: lustre-MDD0001: changelog off [20045.538290] Lustre: Skipped 1 previous similar message [20052.008985] Lustre: DEBUG MARKER: == sanity test 160e: changelog negative testing (should return errors) ========================================================== 06:27:27 (1787135247) [20055.999309] Lustre: lustre-MDD0000: changelog on [20056.003721] Lustre: Skipped 1 previous similar message [20069.058726] Lustre: lustre-MDD0001: changelog off [20069.061734] Lustre: Skipped 1 previous similar message [20075.352513] Lustre: DEBUG MARKER: == sanity test 160f: changelog garbage collect (timestamped users) ========================================================== 06:27:51 (1787135271) [20091.277314] Lustre: DEBUG MARKER: 1787135287: creating first dirs [20117.782247] Lustre: *** cfs_fail_loc=1313, val=3*** [20117.793138] Lustre: 122500:0:(mdd_dir.c:995:mdd_changelog_emrg_cleanup()) lustre-MDD0000: changelog has only 3 free catalog entries [20117.803243] Lustre: 122500:0:(mdd_dir.c:1082:mdd_changelog_store()) lustre-MDD0000: starting changelog garbage collection [20117.818192] Lustre: 217222:0:(mdd_trans.c:163:mdd_chlg_garbage_collect()) lustre-MDD0000: force deregister of changelog user cl7 idle for 32s with 4 unprocessed records [20147.619584] Lustre: lustre-MDD0001: changelog off [20147.623878] Lustre: Skipped 1 previous similar message [20154.586838] Lustre: DEBUG MARKER: == sanity test 160g: changelog garbage collect on idle records ========================================================== 06:29:10 (1787135350) [20159.205867] Lustre: lustre-MDD0000: changelog on [20159.213100] Lustre: Skipped 3 previous similar messages [20189.900846] Lustre: 200856:0:(mdd_dir.c:1082:mdd_changelog_store()) lustre-MDD0000: starting changelog garbage collection [20189.912117] Lustre: 200856:0:(mdd_dir.c:1082:mdd_changelog_store()) Skipped 1 previous similar message [20189.944226] Lustre: 219691:0:(mdd_trans.c:163:mdd_chlg_garbage_collect()) lustre-MDD0000: force deregister of changelog user cl9 idle for 24s with 4 unprocessed records [20189.979711] Lustre: 219691:0:(mdd_trans.c:163:mdd_chlg_garbage_collect()) Skipped 1 previous similar message [20217.592197] Lustre: lustre-MDD0001: changelog off [20217.596686] Lustre: Skipped 1 previous similar message [20224.438215] Lustre: DEBUG MARKER: == sanity test 160h: changelog gc thread stop upon umount, orphan records delete ========================================================== 06:30:19 (1787135419) [20228.633477] Lustre: lustre-MDD0000: changelog on [20228.638373] Lustre: Skipped 1 previous similar message [20267.356784] Lustre: *** cfs_fail_loc=1316, val=0*** [20267.359328] Lustre: 120593:0:(mdd_dir.c:1082:mdd_changelog_store()) lustre-MDD0001: simulate starting changelog garbage collection [20267.368877] Lustre: 120593:0:(mdd_dir.c:1082:mdd_changelog_store()) Skipped 1 previous similar message [20267.386851] Lustre: 222149:0:(mdd_trans.c:163:mdd_chlg_garbage_collect()) lustre-MDD0001: force deregister of changelog user cl11 idle for 30s with 3 unprocessed records [20267.406966] Lustre: 222149:0:(mdd_trans.c:163:mdd_chlg_garbage_collect()) Skipped 1 previous similar message [20271.441350] Lustre: Failing over lustre-MDT0000 [20271.452230] Lustre: Failing over lustre-MDT0001 [20273.140342] 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 [20273.183259] Lustre: Skipped 1 previous similar message [20273.191559] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [20273.857079] LustreError: 222393:0:(osp_dev.c:625:osp_shutdown()) lustre-MDT0001-osp-MDT0000: can't disconnect: rc = -19 [20273.881541] LustreError: 222393:0:(lod_dev.c:249:lod_sub_process_config()) lustre-MDT0000-mdtlov: error cleaning up LOD index 1: cmd 0xcf004 : rc = -19 [20274.082305] Lustre: lustre-MDT0000: Not available for connect from 192.168.204.38@tcp (stopping) [20274.102405] Lustre: Skipped 3 previous similar messages [20278.276258] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [20278.285565] Lustre: Skipped 1 previous similar message [20283.368899] LustreError: 200856:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: 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. [20283.382498] LustreError: 200856:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 3 previous similar messages [20283.416760] Lustre: server umount lustre-MDT0001 complete [20283.583251] Lustre: server umount lustre-MDT0000 complete [20295.288175] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [20295.546690] LustreError: MGC192.168.204.138@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [20295.837995] LustreError: 201206:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0001: 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. [20295.980618] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [20296.016129] Lustre: 223334:0:(mdd_device.c:626:mdd_changelog_llog_init()) lustre-MDD0000 : orphan changelog records found, starting from index 29 to index 30, being cleared now [20296.037653] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [20301.975450] Lustre: DEBUG MARKER: oleg438-server.virtnet: executing set_default_debug all all [20304.825725] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [20313.015592] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [20313.485556] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_connect to node 0@lo failed: rc = -114 [20313.680291] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [20313.726601] Lustre: 224082:0:(mdd_device.c:626:mdd_changelog_llog_init()) lustre-MDD0001 : orphan changelog records found, starting from index 17 to index 18, being cleared now [20313.762565] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [20314.761767] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 2 clients reconnect [20314.766388] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [20315.803926] Lustre: lustre-MDT0000: Recovery over after 0:11, of 2 clients 2 recovered and 0 were evicted. [20315.907857] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000403:27203 to 0x2c0000403:27233) [20315.910387] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000403:25886 to 0x280000403:25953) [20316.824723] Lustre: lustre-MDT0001-osp-MDT0000: Connection restored to 0@lo (at 0@lo) [20316.826750] Lustre: lustre-MDT0001: Recovery over after 0:02, of 2 clients 2 recovered and 0 were evicted. [20316.847512] Lustre: Skipped 4 previous similar messages [20316.904218] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:12296 to 0x2c0000400:12321) [20316.904293] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:12103 to 0x280000400:12129) [20318.937791] Lustre: DEBUG MARKER: oleg438-server.virtnet: executing set_default_debug all all [20347.895355] Lustre: lustre-MDD0001: changelog off [20347.907779] Lustre: Skipped 1 previous similar message [20355.508454] Lustre: DEBUG MARKER: == sanity test 160i: changelog user register/unregister race ========================================================== 06:32:30 (1787135550) [20359.440666] Lustre: lustre-MDD0000: changelog on [20359.443450] Lustre: Skipped 3 previous similar messages [20368.668913] LustreError: 226051:0:(mdd_device.c:2065:mdd_changelog_user_purge()) cfs_race id 1315 sleeping [20371.342918] LustreError: 226184:0:(mdd_device.c:1780:mdd_changelog_user_register()) cfs_fail_race id 1315 waking [20371.367234] LustreError: 226051:0:(mdd_device.c:2065:mdd_changelog_user_purge()) cfs_fail_race id 1315 awake: rc=2317 [20373.854749] LustreError: 226376:0:(mdd_device.c:2065:mdd_changelog_user_purge()) cfs_fail_race id 1315 waking [20375.127864] LustreError: 226435:0:(mdd_device.c:1780:mdd_changelog_user_register()) cfs_fail_race id 1315 waking [20398.406253] Lustre: DEBUG MARKER: == sanity test 160j: client can be umounted while its chanangelog is being used ========================================================== 06:33:14 (1787135594) [20429.294945] Lustre: DEBUG MARKER: == sanity test 160k: Verify that changelog records are not lost ========================================================== 06:33:45 (1787135625) [20438.546521] LustreError: 225780:0:(mdd_dir.c:1050:mdd_changelog_store()) cfs_fail_timeout id 15d sleeping for 3000ms [20441.576091] LustreError: 225780:0:(mdd_dir.c:1050:mdd_changelog_store()) cfs_fail_timeout id 15d awake [20461.384641] Lustre: DEBUG MARKER: == sanity test 160l: Verify that MTIME changelog records contain the parent FID ========================================================== 06:34:17 (1787135657) [20486.684449] Lustre: DEBUG MARKER: == sanity test 160m: Changelog clear race ================ 06:34:42 (1787135682) [20503.940206] LustreError: 223346:0:(mdd_device.c:398:llog_changelog_cancel_cb()) cfs_race id 15f sleeping [20505.969314] LustreError: 223348:0:(mdd_device.c:398:llog_changelog_cancel_cb()) cfs_fail_race id 15f waking [20505.978810] LustreError: 223346:0:(mdd_device.c:398:llog_changelog_cancel_cb()) cfs_fail_race id 15f awake: rc=2975 [20528.531623] Lustre: DEBUG MARKER: == sanity test 160n: Changelog destroy race ============== 06:35:24 (1787135724) [23074.550578] LustreError: 223346:0:(mdd_device.c:412:llog_changelog_cancel_cb()) cfs_race id 16c sleeping [23076.617646] LustreError: 225780:0:(llog_osd.c:1130:llog_osd_next_block()) cfs_fail_race id 16c waking [23076.631627] LustreError: 223346:0:(mdd_device.c:412:llog_changelog_cancel_cb()) cfs_fail_race id 16c awake: rc=2938 [23089.599681] Lustre: lustre-MDD0001: changelog off [23089.604466] Lustre: Skipped 13 previous similar messages [23096.813339] Lustre: DEBUG MARKER: == sanity test 160o: changelog user name and mask ======== 07:18:12 (1787138292) [23100.470601] Lustre: lustre-MDD0000: changelog on [23100.477826] Lustre: Skipped 13 previous similar messages [23104.994498] LustreError: 234358:0:(mdd_device.c:1734:mdd_changelog_name_check()) lustre-MDD0000: wrong char '#' in name 'Tt3_-#': rc = -22 [23106.081687] Lustre: 234406:0:(mdd_device.c:1751:mdd_changelog_name_check()) lustre-MDD0000: changelog name test_160o exists already: rc = -17 [23107.198429] LustreError: 234454:0:(mdd_device.c:1743:mdd_changelog_name_check()) lustre-MDD0000: name 'test_160toolongname' is over 16 symbols limit: rc = -36 [23140.253187] Lustre: lustre-MDD0000: changelog off [23140.259162] Lustre: Skipped 1 previous similar message [23151.320851] Lustre: DEBUG MARKER: == sanity test 160p: Changelog orphan cleanup with no users ========================================================== 07:19:06 (1787138346) [23155.402077] Lustre: lustre-MDD0000: changelog on [23155.414146] Lustre: Skipped 1 previous similar message [23163.338032] Lustre: Failing over lustre-MDT0000 [23163.931353] Lustre: server umount lustre-MDT0000 complete [23164.901072] 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 [23164.928333] LustreError: 223347:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: 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. [23164.950048] Lustre: Skipped 5 previous similar messages [23164.979914] LustreError: 223347:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 7 previous similar messages [23170.024718] LustreError: 223348:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: 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. [23170.049431] LustreError: 223348:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 6 previous similar messages [23175.137973] LustreError: 225780:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: 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. [23175.176628] LustreError: 225780:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 4 previous similar messages [23176.616459] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [23176.790985] LustreError: MGC192.168.204.138@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [23177.257880] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [23177.429254] Lustre: 236791:0:(mdd_device.c:626:mdd_changelog_llog_init()) lustre-MDD0000 : orphan changelog records found, starting from index 90153 to index 18446744073709551615, being cleared now [23177.505671] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [23179.179022] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [23182.332167] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [23182.416322] Lustre: lustre-MDT0000: Recovery over after 0:03, of 2 clients 2 recovered and 0 were evicted. [23182.494291] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000403:27235 to 0x2c0000403:27265) [23182.496287] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000403:25955 to 0x280000403:25985) [23183.529397] Lustre: DEBUG MARKER: oleg438-server.virtnet: executing set_default_debug all all [23202.257615] Lustre: DEBUG MARKER: == sanity test 160q: changelog effective mask is DEFMASK if not set ========================================================== 07:19:57 (1787138397) [23207.700347] Lustre: lustre-MDD0000: changelog off [23207.704544] Lustre: Skipped 2 previous similar messages [23216.760806] Lustre: DEBUG MARKER: == sanity test 160s: changelog garbage collect on idle records * time ========================================================== 07:20:12 (1787138412) [23222.533407] Lustre: lustre-MDD0000: changelog on [23222.535429] Lustre: Skipped 2 previous similar messages [23241.418689] Lustre: 232698:0:(mdd_dir.c:1082:mdd_changelog_store()) lustre-MDD0000: starting changelog garbage collection [23241.441821] Lustre: 232698:0:(mdd_dir.c:1082:mdd_changelog_store()) Skipped 1 previous similar message [23241.489734] Lustre: 238790:0:(mdd_trans.c:163:mdd_chlg_garbage_collect()) lustre-MDD0000: force deregister of changelog user cl2 idle for 864019s with 500000004 unprocessed records [23241.516808] Lustre: 238790:0:(mdd_trans.c:163:mdd_chlg_garbage_collect()) Skipped 1 previous similar message [23267.081164] Lustre: DEBUG MARKER: == sanity test 160t: changelog garbage collect on lack of space ========================================================== 07:21:03 (1787138463) [23349.224367] Lustre: *** cfs_fail_loc=18c, val=1210732*** [23349.228567] Lustre: Skipped 1 previous similar message [23349.235122] Lustre: 225780:0:(mdd_dir.c:1082:mdd_changelog_store()) lustre-MDD0000: starting changelog garbage collection [23349.245996] Lustre: 225780:0:(mdd_dir.c:1082:mdd_changelog_store()) Skipped 1 previous similar message [23349.257544] Lustre: 240795:0:(mdd_dir.c:966:mdd_changelog_is_space_safe()) lustre-MDD0000: changelog size 1MB with 1MB space limit [23349.272250] Lustre: 240795:0:(mdd_trans.c:163:mdd_chlg_garbage_collect()) lustre-MDD0000: force deregister of changelog user cl3-user1 idle for 79s with 7506 unprocessed records [23349.291198] Lustre: 240795:0:(mdd_trans.c:163:mdd_chlg_garbage_collect()) Skipped 1 previous similar message [23371.850417] Lustre: lustre-MDD0000: changelog off [23371.856465] Lustre: Skipped 2 previous similar messages [23415.435212] Lustre: DEBUG MARKER: == sanity test 160u: changelog rename record type name and sname strings are correct ========================================================== 07:23:31 (1787138611) [23420.184259] Lustre: lustre-MDD0000: changelog on [23420.186858] Lustre: Skipped 3 previous similar messages [23442.636245] Lustre: DEBUG MARKER: == sanity test 160v: setattr preserves mtime update despite inter-client clock skew ========================================================== 07:23:58 (1787138638) [23444.845411] Lustre: DEBUG MARKER: SKIP: sanity test_160v need >= 2 clients [23447.265513] Lustre: DEBUG MARKER: == sanity test 160w: lfs changelog --user --mask ========= 07:24:02 (1787138642) [23491.960764] Lustre: DEBUG MARKER: == sanity test 161a: link ea sanity ====================== 07:24:47 (1787138687) [23541.325255] Lustre: DEBUG MARKER: == sanity test 161b: link ea sanity under remote directory ========================================================== 07:25:37 (1787138737) [23587.980293] Lustre: DEBUG MARKER: == sanity test 161c: check CL_RENME[UNLINK] changelog record flags ========================================================== 07:26:24 (1787138784) [23613.576785] Lustre: DEBUG MARKER: == sanity test 161d: create with concurrent .lustre/fid access ========================================================== 07:26:49 (1787138809) [23633.283580] Lustre: lustre-MDD0001: changelog off [23633.286804] Lustre: Skipped 7 previous similar messages [23639.510506] Lustre: DEBUG MARKER: == sanity test 162a: path lookup sanity ================== 07:27:15 (1787138835) [23648.899625] Lustre: DEBUG MARKER: == sanity test 162b: striped directory path lookup sanity ========================================================== 07:27:24 (1787138844) [23659.081369] Lustre: DEBUG MARKER: == sanity test 162c: fid2path works with paths 100 or more directories deep ========================================================== 07:27:35 (1787138855) [23794.881541] Lustre: DEBUG MARKER: == sanity test 165a: ofd access log discovery ============ 07:29:50 (1787138990) [23803.426708] Lustre: Failing over lustre-OST0000 [23803.800980] Lustre: lustre-OST0000: Not available for connect from 192.168.204.38@tcp (stopping) [23803.808180] Lustre: Skipped 3 previous similar messages [23805.429715] LustreError: lustre-OST0000-osc-MDT0001: operation ost_statfs to node 0@lo failed: rc = -107 [23805.446062] Lustre: lustre-OST0000-osc-MDT0001: Connection to lustre-OST0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [23805.460264] Lustre: Skipped 1 previous similar message [23805.469209] Lustre: lustre-OST0000: Not available for connect from 0@lo (stopping) [23805.713665] Lustre: server umount lustre-OST0000 complete [23806.948080] LustreError: 200144: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. [23806.956381] 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 [23808.879334] LustreError: 200140:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.204.38@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [23808.896793] LustreError: 200140:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 1 previous similar message [23812.086900] LustreError: 200137: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. [23812.108836] LustreError: 200137:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 1 previous similar message [23817.201668] LustreError: 200146: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. [23817.217381] LustreError: 200146:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 2 previous similar messages [23824.268164] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [23824.610147] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [23824.636171] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [23826.281949] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [23826.683856] Lustre: lustre-OST0000-osc-MDT0001: Connection restored to 0@lo (at 0@lo) [23826.688380] Lustre: lustre-OST0000: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [23826.694205] Lustre: Skipped 3 previous similar messages [23830.909938] Lustre: DEBUG MARKER: oleg438-server.virtnet: executing set_default_debug all all [23834.817600] Lustre: DEBUG MARKER: == sanity test 165b: ofd access log entries are produced and consumed ========================================================== 07:30:30 (1787139030) [23866.123126] Lustre: Failing over lustre-OST0000 [23867.876412] LustreError: lustre-OST0000-osc-MDT0001: operation ost_statfs to node 0@lo failed: rc = -107 [23867.880454] 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 [23867.888690] LustreError: Skipped 1 previous similar message [23867.889908] Lustre: lustre-OST0000: Not available for connect from 0@lo (stopping) [23867.922334] Lustre: Skipped 1 previous similar message [23868.321767] Lustre: server umount lustre-OST0000 complete [23870.350258] LustreError: 122501:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.204.38@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [23870.362267] LustreError: 122501:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 4 previous similar messages [23875.740898] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [23876.106555] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [23876.126928] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [23877.613115] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [23878.005254] Lustre: lustre-OST0000: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [23878.012596] Lustre: lustre-OST0000-osc-MDT0001: Connection restored to 0@lo (at 0@lo) [23878.018892] Lustre: Skipped 1 previous similar message [23881.773595] Lustre: DEBUG MARKER: oleg438-server.virtnet: executing set_default_debug all all [23886.448849] Lustre: DEBUG MARKER: == sanity test 165c: full ofd access logs do not block IOs ========================================================== 07:31:22 (1787139082) [23920.420823] Lustre: Failing over lustre-OST0000 [23920.548291] Lustre: server umount lustre-OST0000 complete [23921.571012] LustreError: 122402:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.204.38@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [23921.591617] LustreError: 122402:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 3 previous similar messages [23922.155312] 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 [23930.158231] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [23930.536273] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [23930.564353] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [23931.797824] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [23932.528984] Lustre: lustre-OST0000: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [23932.529432] Lustre: lustre-OST0000-osc-MDT0001: Connection restored to 0@lo (at 0@lo) [23932.539447] Lustre: Skipped 1 previous similar message [23938.524537] Lustre: DEBUG MARKER: oleg438-server.virtnet: executing set_default_debug all all [23942.790443] Lustre: DEBUG MARKER: == sanity test 165d: ofd_access_log mask works =========== 07:32:18 (1787139138) [23990.042762] Lustre: Failing over lustre-OST0000 [23990.339940] Lustre: server umount lustre-OST0000 complete [23992.294030] Lustre: lustre-OST0000-osc-MDT0001: Connection to lustre-OST0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [23992.322894] Lustre: Skipped 1 previous similar message [23992.330112] LustreError: 200144: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. [23992.353409] LustreError: 200144:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 6 previous similar messages [23999.460978] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [23999.827372] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [23999.843764] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [24000.968699] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [24001.525433] Lustre: lustre-OST0000: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [24001.527216] Lustre: lustre-OST0000-osc-MDT0001: Connection restored to 0@lo (at 0@lo) [24001.554498] Lustre: Skipped 1 previous similar message [24006.201554] Lustre: DEBUG MARKER: oleg438-server.virtnet: executing set_default_debug all all [24010.347105] Lustre: DEBUG MARKER: == sanity test 165e: ofd_access_log MDT index filter works ========================================================== 07:33:26 (1787139206) [24035.658450] Lustre: Failing over lustre-OST0000 [24035.818424] Lustre: lustre-OST0000-osc-MDT0001: Connection to lustre-OST0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [24035.857861] Lustre: Skipped 1 previous similar message [24036.057434] Lustre: server umount lustre-OST0000 complete [24045.202801] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [24045.507842] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [24045.523711] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [24046.921294] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [24047.000763] Lustre: lustre-OST0000: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [24047.000838] Lustre: lustre-OST0000-osc-MDT0001: Connection restored to 0@lo (at 0@lo) [24047.013308] Lustre: Skipped 1 previous similar message [24053.179430] Lustre: DEBUG MARKER: oleg438-server.virtnet: executing set_default_debug all all [24057.071468] Lustre: DEBUG MARKER: == sanity test 165f: ofd_access_log_reader --exit-on-close works ========================================================== 07:34:13 (1787139253) [24065.045878] Lustre: Failing over lustre-OST0000 [24065.055337] LustreError: 256631:0:(ldlm_resource.c:1207:ldlm_resource_complain()) filter-lustre-OST0000_UUID: namespace resource [0x280000403:0x8ca4:0x0].0x0 (ffff9a7a43e7bd00) refcount nonzero (2) after lock cleanup; forcing cleanup. [24066.023453] Lustre: lustre-OST0000-osc-MDT0001: Connection to lustre-OST0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [24066.040521] Lustre: Skipped 1 previous similar message [24066.050450] Lustre: lustre-OST0000: Not available for connect from 0@lo (stopping) [24066.055735] Lustre: Skipped 2 previous similar messages [24067.252949] Lustre: server umount lustre-OST0000 complete [24070.040345] LustreError: 122403:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.204.38@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [24070.064297] LustreError: 122403:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 10 previous similar messages [24085.201363] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [24085.572594] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [24085.596841] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [24086.725393] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [24087.397445] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [24087.397657] Lustre: lustre-OST0000: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [24087.406808] Lustre: Skipped 1 previous similar message [24091.846619] Lustre: DEBUG MARKER: oleg438-server.virtnet: executing set_default_debug all all [24095.795241] Lustre: DEBUG MARKER: == sanity test 165g: ofd_access_log_reader --keepalive works ========================================================== 07:34:51 (1787139291) [24139.879679] Lustre: Failing over lustre-OST0000 [24139.890212] LustreError: 258199:0:(ldlm_resource.c:1207:ldlm_resource_complain()) filter-lustre-OST0000_UUID: namespace resource [0x280000403:0x8ca4:0x0].0x0 (ffff9a7a46510700) refcount nonzero (2) after lock cleanup; forcing cleanup. [24141.724525] Lustre: lustre-OST0000: Not available for connect from 192.168.204.38@tcp (stopping) [24141.804835] Lustre: lustre-OST0000-osc-MDT0001: Connection to lustre-OST0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [24141.814664] Lustre: Skipped 1 previous similar message [24142.070685] Lustre: server umount lustre-OST0000 complete [24161.831745] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [24162.175581] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [24162.201405] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [24164.054867] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [24164.138422] Lustre: lustre-OST0000: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [24164.140930] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [24164.151148] Lustre: Skipped 1 previous similar message [24169.411847] Lustre: DEBUG MARKER: oleg438-server.virtnet: executing set_default_debug all all [24173.618092] Lustre: DEBUG MARKER: == sanity test 169: parallel read and truncate should not deadlock ========================================================== 07:36:09 (1787139369) [24175.413792] Lustre: DEBUG MARKER: creating a 10 Mb file [24239.116788] Lustre: DEBUG MARKER: starting reads [24241.143322] Lustre: DEBUG MARKER: truncating the file [24243.326309] Lustre: DEBUG MARKER: killing dd [24245.131867] Lustre: DEBUG MARKER: removing the temporary file [24252.069308] Lustre: DEBUG MARKER: == sanity test 170a: test lctl df to handle corrupted log ========================================================== 07:37:28 (1787139448) [24262.808807] Lustre: DEBUG MARKER: == sanity test 170b: check filename encoding ============= 07:37:37 (1787139457) [24296.161711] Lustre: DEBUG MARKER: == sanity test 171: test libcfs_debug_dumplog_thread stuck in do_exit() ================================================================ 07:38:12 (1787139492) [24307.056448] Lustre: DEBUG MARKER: == sanity test 172: manual device removal with lctl cleanup/detach ================================================================ 07:38:23 (1787139503) [24316.541047] Lustre: DEBUG MARKER: == sanity test 180a: test obdecho on osc ================= 07:38:32 (1787139512) [24318.018377] Lustre: DEBUG MARKER: SKIP: sanity test_180a obdecho on osc is no longer supported [24320.001115] Lustre: DEBUG MARKER: == sanity test 180b: test obdecho directly on obdfilter == 07:38:36 (1787139516) [24324.575706] Lustre: DEBUG MARKER: oleg438-server.virtnet: executing load_module obdecho/obdecho [24344.241347] Lustre: DEBUG MARKER: == sanity test 180c: test huge bulk I/O size on obdfilter, don't LASSERT ========================================================== 07:39:00 (1787139540) [24348.096081] Lustre: DEBUG MARKER: oleg438-server.virtnet: executing load_module obdecho/obdecho [24348.303582] Lustre: Echo OBD driver; http://www.lustre.org/ [24371.174612] Lustre: DEBUG MARKER: == sanity test 181: Test open-unlinked dir ================================================================================== 07:39:26 (1787139566) [24497.159991] Lustre: DEBUG MARKER: == sanity test 182a: Test parallel modify metadata operations from mdc ========================================================== 07:41:32 (1787139692) [24607.908511] Lustre: DEBUG MARKER: == sanity test 182b: Test parallel modify metadata operations from osp ========================================================== 07:43:23 (1787139803) [25497.583472] Lustre: DEBUG MARKER: == sanity test 183: No crash or request leak in case of strange dispositions ================================================================== 07:58:13 (1787140693) [25499.266736] Lustre: *** cfs_fail_loc=148, val=0*** [25509.198750] Lustre: DEBUG MARKER: == sanity test 184a: Basic layout swap =================== 07:58:24 (1787140704) [25523.295121] Lustre: DEBUG MARKER: == sanity test 184b: Forbidden layout swap (will generate errors) ========================================================== 07:58:39 (1787140719) [25533.274734] Lustre: DEBUG MARKER: == sanity test 184c: Concurrent write and layout swap ==== 07:58:49 (1787140729) [25591.277372] Lustre: DEBUG MARKER: == sanity test 184d: allow stripeless layouts swap ======= 07:59:47 (1787140787) [25604.571494] Lustre: DEBUG MARKER: == sanity test 184e: Recreate layout after stripeless layout swaps ========================================================== 08:00:00 (1787140800) [25616.026722] Lustre: DEBUG MARKER: == sanity test 184f: IOC_MDC_GETFILEINFO for files with long names but no striping ========================================================== 08:00:11 (1787140811) [25624.215689] Lustre: DEBUG MARKER: == sanity test 185: Volatile file support ================ 08:00:19 (1787140819) [25634.861775] Lustre: DEBUG MARKER: == sanity test 185a: Volatile file creation in .lustre/fid/ ========================================================== 08:00:30 (1787140830) [25648.071574] Lustre: DEBUG MARKER: == sanity test 187a: Test data version change ============ 08:00:43 (1787140843) [25659.967451] Lustre: DEBUG MARKER: == sanity test 187b: Test data version change on volatile file ========================================================== 08:00:55 (1787140855) [25671.806967] Lustre: DEBUG MARKER: == sanity test 190a: check lfs project -p works with project name ========================================================== 08:01:06 (1787140866) [25682.924172] Lustre: DEBUG MARKER: == sanity test 190b: check lfs find --project works with project name ========================================================== 08:01:18 (1787140878) [25730.557510] Lustre: DEBUG MARKER: == sanity test 190c: check lfs project -p works with u:USERNAME ========================================================== 08:02:06 (1787140926) [25754.101255] Lustre: DEBUG MARKER: == sanity test complete, duration 25461 sec ============== 08:02:29 (1787140949) [25756.987615] Lustre: DEBUG MARKER: === sanity: start cleanup 08:02:32 (1787140952) === [25829.363479] Lustre: DEBUG MARKER: === sanity: finish cleanup 08:03:44 (1787141024) === [25836.522526] 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 [25836.533275] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [25836.565473] Lustre: Skipped 4 previous similar messages [25836.583682] Lustre: Skipped 5 previous similar messages [25837.782501] Lustre: server umount lustre-MDT0000 complete [25841.639775] LustreError: 225780:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: 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. [25841.659407] LustreError: 225780:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 21 previous similar messages [25847.948731] LustreError: 120578:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787141045 with bad export cookie 2947354668207788359 [25847.951789] LustreError: MGC192.168.204.138@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [25847.967557] LustreError: 120578:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 3 previous similar messages [25848.560066] Lustre: server umount lustre-MDT0001 complete [25867.232258] Lustre: 118995:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787141049/real 1787141049] req@ffff9a7a712ed880 x1873942568289664/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787141065 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [25867.269154] Lustre: lustre-MDT0001-lwp-OST0001: Connection to lustre-MDT0001 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [25868.528668] Lustre: server umount lustre-OST0000 complete [25868.772434] Lustre: 118994:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787141050/real 1787141050] req@ffff9a796ed6d880 x1873942568290048/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787141066 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [25872.416646] Lustre: 118995:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787141054/real 1787141054] req@ffff9a7a77e22300 x1873942568290304/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787141070 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [25874.978346] Lustre: 118994:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787141056/real 1787141056] req@ffff9a7a7f95d880 x1873942568290816/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787141072 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [25879.211838] Lustre: server umount lustre-OST0001 complete [25898.880625] Lustre: DEBUG MARKER: oleg438-server.virtnet: executing unload_modules_local [25901.339591] Key type lgssc unregistered [25901.597583] LNet: 279511:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [25901.606355] LNetError: 279511:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [25902.652385] LNet: Removed LNI 192.168.204.138@tcp [25903.614164] Key type .llcrypt unregistered [25903.624839] Key type ._llcrypt unregistered