[ 0.000000] Linux version 4.18.0rh8.10-debug (green@maintenance) (gcc version 8.5.0 20210514 (Red Hat 8.5.0-26) (GCC)) #2 SMP Mon Jul 14 01:24:22 EDT 2025 [ 0.000000] Command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers' [ 0.000000] x86/fpu: xstate_offset[2]: 576, xstate_sizes[2]: 256 [ 0.000000] x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'standard' format. [ 0.000000] signal: max sigframe size: 1776 [ 0.000000] BIOS-provided physical RAM map: [ 0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable [ 0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000000100000-0x00000000bffcdfff] usable [ 0.000000] BIOS-e820: [mem 0x00000000bffce000-0x00000000bfffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000100000000-0x0000000146dfffff] usable [ 0.000000] NX (Execute Disable) protection: active [ 0.000000] SMBIOS 2.8 present. [ 0.000000] DMI: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.17.0-8.fc42 06/10/2025 [ 0.000000] Hypervisor detected: KVM [ 0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00 [ 0.000000] kvm-clock: using sched offset of 511213324 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2400.032 MHz processor [ 0.000000] last_pfn = 0x146e00 max_arch_pfn = 0x400000000 [ 0.000000] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT [ 0.000000] last_pfn = 0xbffce max_arch_pfn = 0x400000000 [ 0.000000] found SMP MP-table at [mem 0x000f54b0-0x000f54bf] [ 0.000000] RAMDISK: [mem 0xbcc54000-0xbffbffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F52D0 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE2439 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE22D5 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 002295 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE2349 000090 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE23D9 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE2411 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe22d5-0xbffe2348] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe22d4] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe2349-0xbffe23d8] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe23d9-0xbffe2410] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe2411-0xbffe2438] [ 0.000000] No NUMA configuration found [ 0.000000] Faking a node at [mem 0x0000000000000000-0x0000000146dfffff] [ 0.000000] NODE_DATA(0) allocated [mem 0x1465a3000-0x1465cdfff] [ 0.000000] Reserving 256MB of memory at 2752MB for crashkernel (System RAM: 4205MB) [ 0.000000] Zone ranges: [ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.000000] DMA32 [mem 0x0000000001000000-0x00000000ffffffff] [ 0.000000] Normal [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Device empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff] [ 0.000000] node 0: [mem 0x0000000000100000-0x00000000bffcdfff] [ 0.000000] node 0: [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Zeroed struct page in unavailable ranges: 4756 pages [ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x0000000146dfffff] [ 0.000000] ACPI: PM-Timer IO Port: 0x608 [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) [ 0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) [ 0.000000] Using ACPI (MADT) for SMP configuration information [ 0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000] TSC deadline timer available [ 0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs [ 0.000000] kvm-guest: KVM setup pv remote TLB flush [ 0.000000] kvm-guest: setup PV sched yield [ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff] [ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff] [ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff] [ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff] [ 0.000000] PM: Registered nosave memory: [mem 0xbffce000-0xbfffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xc0000000-0xfeffbfff] [ 0.000000] PM: Registered nosave memory: [mem 0xfeffc000-0xfeffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xff000000-0xfffbffff] [ 0.000000] PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff] [ 0.000000] [mem 0xc0000000-0xfeffbfff] available for PCI devices [ 0.000000] Booting paravirtualized kernel on KVM [ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns [ 0.000000] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1 [ 0.000000] percpu: Embedded 63 pages/cpu s221184 r8192 d28672 u524288 [ 0.000000] kvm-guest: PV spinlocks enabled [ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1059606 [ 0.000000] Policy zone: Normal [ 0.000000] Kernel command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] Specific versions of hardware are certified with Red Hat Enterprise Linux 8. Please see the list of hardware certified with Red Hat Enterprise Linux 8 at https://catalog.redhat.com. [ 0.000000] audit: disabled (until reboot) [ 0.000000] software IO TLB: area num 4. [ 0.000000] Memory: 2829652K/4306352K available (18435K kernel code, 11221K rwdata, 7248K rodata, 2908K init, 18040K bss, 524580K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] ftrace: allocating 41240 entries in 162 pages [ 0.000000] ftrace: allocated 162 pages with 3 groups [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] rcu: RCU event tracing is enabled. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ 0.000000] rcu: RCU callback double-/use-after-free debug enabled. [ 0.000000] Rude variant of Tasks RCU enabled. [ 0.000000] Tracing variant of Tasks RCU enabled. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 0.000000] NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16 [ 0.000000] random: get_random_bytes called from start_kernel+0x622/0x9a8 with crng_init=0 [ 0.001000] Console: colour *CGA 80x25 [ 0.001000] printk: console [ttyS1] enabled [ 0.001000] ACPI: Core revision 20220331 [ 0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.001010] APIC: Switch to symmetric I/O mode setup [ 0.003126] x2apic enabled [ 0.004007] Switched APIC routing to physical x2apic. [ 0.005014] kvm-guest: setup PV IPIs [ 0.008000] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.008000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229855db145, max_idle_ns: 440795257019 ns [ 0.008021] Calibrating delay loop (skipped) preset value.. 4800.06 BogoMIPS (lpj=2400032) [ 0.009010] pid_max: default: 32768 minimum: 301 [ 0.010128] LSM: Security Framework initializing [ 0.011052] Yama: becoming mindful. [ 0.012034] SELinux: Initializing. [ 0.014047] *** VALIDATE selinux *** [ 0.022768] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.027590] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.028163] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.029114] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.031024] *** VALIDATE tmpfs *** [ 0.032425] *** VALIDATE proc *** [ 0.034245] *** VALIDATE cgroup *** [ 0.035010] *** VALIDATE cgroup2 *** [ 0.036219] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.038047] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.039009] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.040032] Spectre V2 : User space: Vulnerable [ 0.041010] Speculative Store Bypass: Vulnerable [ 0.044342] debug: unmapping init [mem 0xffffffffaee59000-0xffffffffaee60fff] [ 0.047229] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.048722] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.049025] ... version: 2 [ 0.050015] ... bit width: 48 [ 0.051016] ... generic registers: 4 [ 0.052015] ... value mask: 0000ffffffffffff [ 0.053017] ... max period: 00007fffffffffff [ 0.054017] ... fixed-purpose events: 3 [ 0.055015] ... event mask: 000000070000000f [ 0.056300] rcu: Hierarchical SRCU implementation. [ 0.058415] smp: Bringing up secondary CPUs ... [ 0.059602] x86: Booting SMP configuration: [ 0.060030] .... node #0, CPUs: #1 #2 #3 [ 0.065021] smp: Brought up 1 node, 4 CPUs [ 0.067020] smpboot: Max logical packages: 1 [ 0.068014] smpboot: Total of 4 processors activated (19200.25 BogoMIPS) [ 0.235039] node 0 deferred pages initialised in 165ms [ 0.239131] devtmpfs: initialized [ 0.240300] x86/mm: Memory block size: 128MB [ 0.242932] gcov: version magic: 0x41383552 [ 0.244419] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.249096] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.252307] pinctrl core: initialized pinctrl subsystem [ 0.255198] [ 0.255992] ************************************************************* [ 0.258023] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.260014] ** ** [ 0.263018] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.265015] ** ** [ 0.267016] ** This means that this kernel is built to expose internal ** [ 0.270018] ** IOMMU data structures, which may compromise security on ** [ 0.272016] ** your system. ** [ 0.274017] ** ** [ 0.277017] ** If you see this message and you are not debugging the ** [ 0.279013] ** kernel, report this immediately to your vendor! ** [ 0.281015] ** ** [ 0.284017] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.286016] ************************************************************* [ 0.289624] NET: Registered protocol family 16 [ 0.292400] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.296070] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.299071] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.302155] cpuidle: using governor menu [ 0.303995] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.307032] PCI: Using configuration type 1 for base access [ 0.309150] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.318121] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.321036] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.324171] cryptd: max_cpu_qlen set to 1000 [ 0.327290] ACPI: Added _OSI(Module Device) [ 0.329021] ACPI: Added _OSI(Processor Device) [ 0.331022] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.332017] ACPI: Added _OSI(Processor Aggregator Device) [ 0.338500] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.344366] ACPI: Interpreter enabled [ 0.346085] ACPI: PM: (supports S0 S3 S4 S5) [ 0.347017] ACPI: Using IOAPIC for interrupt routing [ 0.349139] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.352451] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.362642] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.364057] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.367033] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.371109] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.376125] acpiphp: Slot [2] registered [ 0.378133] acpiphp: Slot [5] registered [ 0.379153] acpiphp: Slot [6] registered [ 0.381119] acpiphp: Slot [7] registered [ 0.382133] acpiphp: Slot [8] registered [ 0.383119] acpiphp: Slot [9] registered [ 0.384181] acpiphp: Slot [10] registered [ 0.386152] acpiphp: Slot [3] registered [ 0.388133] acpiphp: Slot [4] registered [ 0.389142] acpiphp: Slot [11] registered [ 0.392090] acpiphp: Slot [12] registered [ 0.395098] acpiphp: Slot [13] registered [ 0.396101] acpiphp: Slot [14] registered [ 0.398127] acpiphp: Slot [15] registered [ 0.400119] acpiphp: Slot [16] registered [ 0.401166] acpiphp: Slot [17] registered [ 0.403176] acpiphp: Slot [18] registered [ 0.405164] acpiphp: Slot [19] registered [ 0.407179] acpiphp: Slot [20] registered [ 0.409115] acpiphp: Slot [21] registered [ 0.412157] acpiphp: Slot [22] registered [ 0.413123] acpiphp: Slot [23] registered [ 0.415193] acpiphp: Slot [24] registered [ 0.417124] acpiphp: Slot [25] registered [ 0.418134] acpiphp: Slot [26] registered [ 0.420193] acpiphp: Slot [27] registered [ 0.422146] acpiphp: Slot [28] registered [ 0.426173] acpiphp: Slot [29] registered [ 0.428122] acpiphp: Slot [30] registered [ 0.429160] acpiphp: Slot [31] registered [ 0.431090] PCI host bridge to bus 0000:00 [ 0.432028] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.434041] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.437037] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.440034] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.442028] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.445032] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.448197] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.452118] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.455306] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.465920] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.471694] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.475024] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.477021] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.480023] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.485452] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.488937] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.492049] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.495885] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.500023] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.514026] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.518017] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.524393] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.530020] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.536018] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.556029] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.566883] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.574020] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.579022] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.596022] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.605059] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.611022] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.616017] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.633032] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.644230] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.651022] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.658020] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.675020] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.685738] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.693019] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.699020] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.725020] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 0.735489] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.742018] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.750019] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.771024] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 0.782319] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.785407] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.788411] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.791409] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.794258] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.800048] iommu: Default domain type: Passthrough [ 0.801583] SCSI subsystem initialized [ 0.804285] ACPI: bus type USB registered [ 0.806177] usbcore: registered new interface driver usbfs [ 0.808124] usbcore: registered new interface driver hub [ 0.810151] usbcore: registered new device driver usb [ 0.812305] pps_core: LinuxPPS API ver. 1 registered [ 0.814021] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.818089] PTP clock support registered [ 0.821042] EDAC MC: Ver: 3.0.0 [ 0.822203] PCI: Using ACPI for IRQ routing [ 0.825197] NetLabel: Initializing [ 0.827032] NetLabel: domain hash size = 128 [ 0.829017] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.831117] NetLabel: unlabeled traffic allowed by default [ 0.835096] vgaarb: loaded [ 0.837345] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.839018] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.847000] clocksource: Switched to clocksource kvm-clock [ 0.960945] VFS: Disk quotas dquot_6.6.0 [ 0.963098] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.964637] *** VALIDATE ramfs *** [ 0.965766] *** VALIDATE hugetlbfs *** [ 0.968512] pnp: PnP ACPI init [ 0.971391] pnp: PnP ACPI: found 6 devices [ 0.987524] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.992110] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.993832] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.995734] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.998463] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 1.001680] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 1.006250] NET: Registered protocol family 2 [ 1.008691] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 1.017901] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 1.022541] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 1.029102] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 1.034628] TCP: Hash tables configured (established 65536 bind 65536) [ 1.037887] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 1.041369] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 1.043971] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 1.046872] NET: Registered protocol family 1 [ 1.049491] RPC: Registered named UNIX socket transport module. [ 1.051742] RPC: Registered udp transport module. [ 1.053797] RPC: Registered tcp transport module. [ 1.055640] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 1.058379] NET: Registered protocol family 44 [ 1.059751] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 1.062042] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 1.064172] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 1.066523] PCI: CLS 0 bytes, default 64 [ 1.068516] Unpacking initramfs... [ 2.503585] debug: unmapping init [mem 0xffff92a1bcc54000-0xffff92a1bffbffff] [ 2.510526] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.512903] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.517694] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229855db145, max_idle_ns: 440795257019 ns [ 3.048422] Initialise system trusted keyrings [ 3.050595] Key type blacklist registered [ 3.055852] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 3.066492] zbud: loaded [ 3.070414] *** VALIDATE nfs *** [ 3.072157] *** VALIDATE nfs4 *** [ 3.074107] pstore: using deflate compression [ 3.077065] Platform Keyring initialized [ 3.183788] NET: Registered protocol family 38 [ 3.186584] Key type asymmetric registered [ 3.188678] Asymmetric key parser 'x509' registered [ 3.191320] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 3.195361] io scheduler mq-deadline registered [ 3.197208] io scheduler kyber registered [ 3.198822] io scheduler bfq registered [ 3.201083] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 3.204607] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 3.207622] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 3.210849] ACPI: Power Button [PWRF] [ 3.216704] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 3.223245] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 3.236638] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 3.243591] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 3.260036] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 3.286848] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.316853] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.322465] Non-volatile memory driver v1.3 [ 3.324994] Linux agpgart interface v0.103 [ 3.359156] virtio_blk virtio1: [vda] 68000 512-byte logical blocks (34.8 MB/33.2 MiB) [ 3.362552] vda: detected capacity change from 0 to 34816000 [ 3.381896] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.385657] vdb: detected capacity change from 0 to 1073741824 [ 3.404890] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.408715] vdc: detected capacity change from 0 to 2621440000 [ 3.428301] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.432330] vdd: detected capacity change from 0 to 2621440000 [ 3.447852] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.451789] vde: detected capacity change from 0 to 4294967296 [ 3.472756] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.476319] vdf: detected capacity change from 0 to 4294967296 [ 3.483676] libphy: Fixed MDIO Bus: probed [ 3.489490] usbcore: registered new interface driver usbserial_generic [ 3.491949] usbserial: USB Serial support registered for generic [ 3.494037] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.498703] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.500441] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.503317] mousedev: PS/2 mouse device common for all mice [ 3.506679] rtc_cmos 00:05: RTC can wake from S4 [ 3.509555] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.513019] rtc_cmos 00:05: registered as rtc0 [ 3.517508] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.519300] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.521363] intel_pstate: CPU model not supported [ 3.526498] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.531786] hid: raw HID events driver (C) Jiri Kosina [ 3.534380] usbcore: registered new interface driver usbhid [ 3.536751] usbhid: USB HID core driver [ 3.538432] drop_monitor: Initializing network drop monitor service [ 3.540319] Initializing XFRM netlink socket [ 3.542575] NET: Registered protocol family 10 [ 3.545472] Segment Routing with IPv6 [ 3.547236] NET: Registered protocol family 17 [ 3.549898] mpls_gso: MPLS GSO support [ 3.555778] RAS: Correctable Errors collector initialized. [ 3.558428] AVX version of gcm_enc/dec engaged. [ 3.559641] AES CTR mode by8 optimization enabled [ 3.633306] sched_clock: Marking stable (3633226209, 0)->(4585049907, -951823698) [ 3.637329] registered taskstats version 1 [ 3.639698] Loading compiled-in X.509 certificates [ 3.642453] zswap: loaded using pool lzo/zbud [ 3.667631] Key type big_key registered [ 3.679490] Key type encrypted registered [ 3.681480] ima: No TPM chip found, activating TPM-bypass! [ 3.684184] ima: Allocated hash algorithm: sha1 [ 3.686348] ima: No architecture policies found [ 3.688602] evm: Initialising EVM extended attributes: [ 3.690932] evm: security.selinux [ 3.692480] evm: security.ima [ 3.693890] evm: security.capability [ 3.695641] evm: HMAC attrs: 0x1 [ 3.698769] rtc_cmos 00:05: setting system clock to 2026-04-14 21:05:56 UTC (1776200756) [ 3.704843] debug: unmapping init [mem 0xffffffffafe03000-0xffffffffafffffff] [ 3.707828] debug: unmapping init [mem 0xffffffffaeb82000-0xffffffffaee58fff] [ 3.717069] Write protecting the kernel read-only data: 28672k [ 3.721276] debug: unmapping init [mem 0xffffffffad203000-0xffffffffad3fffff] [ 3.724693] debug: unmapping init [mem 0xffffffffadb14000-0xffffffffadbfffff] [ 3.760260] 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.769709] systemd[1]: Detected virtualization kvm. [ 3.772086] systemd[1]: Detected architecture x86-64. [ 3.774262] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.804085] systemd[1]: No hostname configured. [ 3.805316] systemd[1]: Set hostname to . [ 3.806811] random: systemd: uninitialized urandom read (16 bytes read) [ 3.809021] systemd[1]: Initializing machine ID from random generator. [ 3.858235] random: ln: uninitialized urandom read (6 bytes read) [ 3.935440] random: systemd: uninitialized urandom read (16 bytes read) [ 3.939254] systemd[1]: Started Dispatch Password Requests to Console Directory Watch. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ 3.947966] systemd[1]: Listening on Journal Socket. [ OK ] Listening on Journal Socket. [ 3.956334] systemd[1]: Starting Setup Virtual Console... Starting Setup Virtual Console... Starting Apply Kernel Variables... [ OK ] Reached target Swap. [ OK ] Listening on udev Kernel Socket. [ OK ] Reached target Local File Systems. [ OK ] Reached target Initrd Root Device. Starting Create Volatile Files and Directories... [ OK ] Started Memstrack Anylazing Service. [ OK ] Reached target Timers. [ OK ] Listening on udev Control Socket. [ OK ] Listening on Journal Socket (/dev/log). Starting Journal Service... [ OK ] Reached target Sockets. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Reached target Slices. [ OK ] Started Setup Virtual Console. [ OK ] Started Apply Kernel Variables. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Create list of required sta…vice nodes for the current kernel. Starting Create Static Device Nodes in /dev... Starting dracut cmdline hook... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started Journal Service. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 4.501281] device-mapper: uevent: version 1.0.3 [ 4.503723] 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.136768] virtio_net virtio0 ens2: renamed from eth0 [ 5.155909] random: fast init done [ 5.225228] scsi host0: ata_piix [ 5.232641] scsi host1: ata_piix [ 5.237950] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 5.240488] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 9.527320] dracut-initqueue[583]: RTNETLINK answers: File exists [ 10.201269] random: crng init done [ 10.202923] random: 7 urandom warning(s) missed due to ratelimiting Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. Mounting /sysroot... [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. [ 10.478690] 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 Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped target Timers. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Slices. [ OK ] Stopped target Paths. [ OK ] Stopped target System Initialization. [ 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. [ OK ] Stopped target Swap. Stopping udev Kernel Device Manager... [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped target Sockets. [ 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... [ 11.511767] printk: systemd: 26 output lines suppressed due to ratelimiting [ 11.776923] SELinux: Disabled at runtime. [ 11.840941] 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) [ 11.852234] systemd[1]: Detected virtualization kvm. [ 11.854443] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 12.298466] systemd[1]: initrd-switch-root.service: Succeeded. [ 12.301924] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 12.307813] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 12.312877] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 12.316173] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 12.322486] systemd[1]: Starting Journal Service... Starting Journal Service... [ 12.329750] systemd[1]: Stopped target Switch Root. [ OK ] Stopped target Switch Root. [ OK ] Created slice User and Session Slice. Mounting Huge Pages File System... [ OK ] Started Forward Password Requests to Wall Directory Watch. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Created slice system-sshd\x2dkeygen.slice. Activating swap /dev/disk/by-label/SWAP... Mounting POSIX Message Queue File System... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Paths. [ 12.387918] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS [ OK ] Listening on Process Core Dump Socket. [ OK ] Listening on udev Kernel Socket. [ OK ] Listening on udev Control Socket. Starting udev Coldplug all Devices... Starting Remount Root and Kernel File Systems... [ OK ] Stopped target Initrd File Systems. [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Reached target Slices. [ OK ] Stopped target Initrd Root File System. [ OK ] Created slice system-getty.slice. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Listening on initctl Compatibility Named Pipe. Mounting Kernel Debug File System... [ OK ] Reached target rpc_pipefs.target. Starting Apply Kernel Variables... [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Reached target RPC Port Mapper. [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Started Journal Service. [ OK ] Mounted Huge Pages 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. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Mounted Kernel Debug File System. [ OK ] Started Apply Kernel Variables. Starting Configure read-only root support... [ OK ] Reached target Swap. 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. [ 12.728383] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 13.040871] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 13.066450] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 13.157530] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 13.172698] EDAC sbridge: Ver: 1.1.2 [ 14.476666] Key type dns_resolver registered [ 14.772531] NFS: Registering the id_resolver key type [ 14.774847] Key type id_resolver registered [ 14.776465] 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 Load/Save Random Seed. [ OK ] Started Create Volatile Files and Directories. Starting RPC Bind... Starting Update UTMP about System Boot/Shutdown... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] 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 Network Manager... [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting Login Service... [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Reached target sshd-keygen.target. [ 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... [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Login Service. [ OK ] Started Network Manager. Starting Network Manager Wait Online... [ OK ] Reached target Network. Starting GSSAPI Proxy Daemon... Starting OpenSSH server daemon... Starting Dynamic System Tuning Daemon... Starting Hostname Service... [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... [ OK ] Started OpenSSH server daemon. [ OK ] Started Permit User Sessions. [ OK ] Started Getty on tty1. [ OK ] Started Serial Getty on ttyS1. [ OK ] Started Command Scheduler. [ OK ] Started Serial Getty on ttyS0. [ OK ] Reached target Login Prompts. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting System Logging Service... Starting Notify NFS peers of a restart... Starting Crash recovery kernel arming... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Starting Authorization Manager... [ OK ] Started Authorization Manager. [ OK ] Started Dynamic System Tuning Daemon. [ OK ] Reached target Multi-User System. [ OK ] Reached target Graphical Interface. Starting Update UTMP about System Runlevel Changes... [ OK ] Started Update UTMP about System Runlevel Changes. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg338-server login: [ 41.769898] libcfs: loading out-of-tree module taints kernel. [ 41.828503] alg: No test for adler32 (adler32-zlib) [ 42.590846] Key type ._llcrypt registered [ 42.599563] Key type .llcrypt registered [ 42.708325] Lustre: DEBUG MARKER: oleg338-server.virtnet: executing set_hostid [ 59.129987] Lustre: DEBUG MARKER: oleg338-server.virtnet: executing load_modules_local [ 60.375326] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 61.112227] Lustre: Lustre: Build Version: 2.15.8_1_g00e7d23 [ 62.062619] LNet: Added LNI 192.168.203.138@tcp [8/256/0/180] [ 62.071166] LNet: Accept secure, port 988 [ 63.887550] Key type lgssc registered [ 65.925312] Lustre: Echo OBD driver; http://www.lustre.org/ [ 67.484012] hrtimer: interrupt took 10003775 ns [ 90.417371] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 94.165716] LDISKFS-fs (vdc): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 106.187404] LDISKFS-fs (vdd): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 115.120547] LDISKFS-fs (vde): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 123.491640] LDISKFS-fs (vdf): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 138.911283] Lustre: DEBUG MARKER: oleg338-server.virtnet: executing load_modules_local [ 150.678540] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 150.775213] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 152.026914] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall in log lustre-MDT0000 [ 152.120439] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space: rc = -61 [ 152.266899] Lustre: lustre-MDT0000: new disk, initializing [ 152.422875] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 152.465668] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 157.323923] Lustre: DEBUG MARKER: oleg338-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 169.483802] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 169.585024] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 169.718760] Lustre: Setting parameter lustre-MDT0001.mdt.identity_upcall in log lustre-MDT0001 [ 169.744180] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space: rc = -61 [ 169.750554] Lustre: Skipped 1 previous similar message [ 169.849208] Lustre: lustre-MDT0001: new disk, initializing [ 169.906813] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 169.938872] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 169.953951] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 174.190884] Lustre: DEBUG MARKER: oleg338-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 188.165847] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 188.266824] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 188.288530] Lustre: lustre-OST0000-osd: enabled 'large_dir' feature on device /dev/mapper/ost1_flakey [ 188.900797] Lustre: lustre-OST0000: new disk, initializing [ 188.921105] Lustre: srv-lustre-OST0000: No data found on store. Initialize space: rc = -61 [ 188.992623] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 193.908645] Lustre: DEBUG MARKER: oleg338-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 197.170528] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 197.193792] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 207.441667] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 207.521431] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 207.539191] Lustre: lustre-OST0001-osd: enabled 'large_dir' feature on device /dev/mapper/ost2_flakey [ 207.686922] Lustre: lustre-OST0001: new disk, initializing [ 207.698244] Lustre: srv-lustre-OST0001: No data found on store. Initialize space: rc = -61 [ 207.802462] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 212.911499] Lustre: DEBUG MARKER: oleg338-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 214.121851] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 214.129181] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 224.213784] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 232.168551] Lustre: Modifying parameter general.lod.*.mdt_hash in log params [ 242.388640] Lustre: DEBUG MARKER: oleg338-server.virtnet: executing check_logdir /tmp/testlogs/ [ 247.001766] Lustre: DEBUG MARKER: oleg338-server.virtnet: executing yml_node [ 252.201376] Lustre: DEBUG MARKER: Client: 2.15.8.1 [ 254.945897] Lustre: DEBUG MARKER: MDS: 2.15.8.1 [ 257.759720] Lustre: DEBUG MARKER: OSS: 2.15.8.1 [ 259.500448] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity ============----- Tue Apr 14 17:10:10 EDT 2026 [ 267.936837] Lustre: DEBUG MARKER: - need MDS1_VERSION < v2_14_55-100-g8a84c7f9c7 (34539521 < 34486116) for LU-14927, skip 0f [ 269.611481] Lustre: DEBUG MARKER: excepting tests: 42a 42b 42c 407 118c 118d 817 411 [ 270.792867] Lustre: DEBUG MARKER: skipping tests SLOW=no: 27m 60i 64b 68 71 115 135 136 230d 300o [ 276.169692] Lustre: DEBUG MARKER: oleg338-client.virtnet: executing check_config_client /mnt/lustre [ 291.458337] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 293.837515] Lustre: Modifying parameter general.lod.*.mdt_hash in log params [ 297.495062] Lustre: DEBUG MARKER: oleg338-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 303.901183] Lustre: DEBUG MARKER: == sanity test 60a: llog_test run from kernel module and test llog_reader ========================================================== 17:10:55 (1776201055) [ 306.630282] Lustre: DEBUG MARKER: SKIP: sanity test_60a missing subtest run-llog.sh [ 307.875896] Lustre: DEBUG MARKER: == sanity test 60b: limit repeated messages from CERROR/CWARN ========================================================== 17:10:59 (1776201059) [ 313.961139] Lustre: DEBUG MARKER: == sanity test 60c: unlink file when mds full ============ 17:11:05 (1776201065) [ 439.069345] Lustre: DEBUG MARKER: == sanity test 60d: test printk console message masking == 17:13:10 (1776201190) [ 445.503124] Lustre: DEBUG MARKER: == sanity test 60e: no space while new llog is being created ========================================================== 17:13:16 (1776201196) [ 447.069270] Lustre: *** cfs_fail_loc=15b, val=0*** [ 447.072844] Lustre: *** cfs_fail_loc=15b, val=0*** [ 453.953038] Lustre: DEBUG MARKER: == sanity test 60f: change debug_path works ============== 17:13:25 (1776201205) [ 460.939586] Lustre: DEBUG MARKER: == sanity test 60g: transaction abort won't cause MDT hung ========================================================== 17:13:32 (1776201212) [ 461.897463] Lustre: *** cfs_fail_loc=19a, val=0*** [ 462.804337] Lustre: *** cfs_fail_loc=19a, val=0*** [ 462.821549] LustreError: 7272:0:(llog_cat.c:739:llog_cat_cancel_arr_rec()) lustre-MDT0001-osd: fail to cancel 1 llog-records: rc = -5 [ 462.844861] LustreError: 7272:0:(llog_cat.c:775:llog_cat_cancel_records()) lustre-MDT0001-osd: fail to cancel 1 of 1 llog-records: rc = -5 [ 463.863054] LustreError: 7272:0:(llog_cat.c:739:llog_cat_cancel_arr_rec()) lustre-MDT0000-osp-MDT0001: fail to cancel 1 llog-records: rc = -116 [ 463.874085] LustreError: 7272:0:(llog_cat.c:775:llog_cat_cancel_records()) lustre-MDT0000-osp-MDT0001: fail to cancel 1 of 1 llog-records: rc = -116 [ 464.514602] Lustre: *** cfs_fail_loc=19a, val=0*** [ 464.518258] Lustre: Skipped 1 previous similar message [ 464.530520] ------------[ cut here ]------------ [ 464.534752] do not call blocking ops when !TASK_RUNNING; state=402 set at [<00000000e1992244>] distribute_txn_commit_thread+0x95/0x1020 [ptlrpc] [ 464.548290] WARNING: CPU: 3 PID: 6294 at kernel/sched/core.c:7471 __might_sleep+0x9d/0xc0 [ 464.561730] Modules linked in: zfs(O) spl(O) lustre(O) osp(O) ofd(O) lod(O) ost(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) 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 serio_raw ata_piix libata dm_mirror dm_region_hash dm_log dm_mod sha512_ssse3 sha512_generic [ 464.603433] CPU: 3 PID: 6294 Comm: dist_txn-0 Kdump: loaded Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 464.617182] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.17.0-8.fc42 06/10/2025 [ 464.624166] RIP: 0010:__might_sleep+0x9d/0xc0 [ 464.626749] Code: a8 12 00 00 48 c7 c7 a8 56 98 ad 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 [ 464.640771] RSP: 0000:ffffb4e344d67d78 EFLAGS: 00010202 [ 464.648307] RAX: 0000000000000000 RBX: ffffffffad9add7d RCX: 0000000000000000 [ 464.652777] RDX: ffff92a2421ae640 RSI: ffff92a24219e5a8 RDI: ffff92a24219e5a8 [ 464.656709] RBP: 00000000000000e2 R08: 0000000000000000 R09: c0000000ffff7fff [ 464.662905] R10: 0000000000000001 R11: ffffb4e344d67b68 R12: 0000000000000000 [ 464.664856] R13: 0000000000000001 R14: 0000000000000058 R15: ffffffffc0dbffd8 [ 464.672277] FS: 0000000000000000(0000) GS:ffff92a242180000(0000) knlGS:0000000000000000 [ 464.676040] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [ 464.678831] CR2: 00007f207dfd3080 CR3: 000000001b016003 CR4: 0000000000170ee0 [ 464.682437] Call Trace: [ 464.685474] ? show_regs.cold.9+0x22/0x2f [ 464.687309] ? __warn+0xc8/0x150 [ 464.688766] ? __might_sleep+0x9d/0xc0 [ 464.690471] ? report_bug+0x113/0x140 [ 464.692239] ? do_error_trap+0xb6/0x130 [ 464.693905] ? do_invalid_op+0x46/0x60 [ 464.695633] ? __might_sleep+0x9d/0xc0 [ 464.697119] ? invalid_op+0x14/0x20 [ 464.698441] ? distribute_txn_commit_batchid_update+0x68/0xac0 [ptlrpc] [ 464.702432] ? __might_sleep+0x9d/0xc0 [ 464.703843] ? __might_sleep+0x95/0xc0 [ 464.708242] slab_pre_alloc_hook.constprop.64+0x11f/0x1d0 [ 464.711341] kmem_cache_alloc_trace+0x5b/0x440 [ 464.713092] distribute_txn_commit_batchid_update+0x68/0xac0 [ptlrpc] [ 464.715818] distribute_txn_commit_thread+0x90a/0x1020 [ptlrpc] [ 464.718385] ? distribute_txn_commit_batchid_update+0xac0/0xac0 [ptlrpc] [ 464.721715] kthread+0x1d1/0x200 [ 464.722855] ? set_kthread_struct+0x70/0x70 [ 464.724487] ret_from_fork+0x1f/0x30 [ 464.726501] ---[ end trace d3fa6a297619cc9f ]--- [ 467.184734] Lustre: *** cfs_fail_loc=19a, val=0*** [ 467.194303] Lustre: Skipped 2 previous similar messages [ 467.200719] LustreError: 7272:0:(llog_cat.c:739:llog_cat_cancel_arr_rec()) lustre-MDT0001-osd: fail to cancel 1 llog-records: rc = -5 [ 467.221199] LustreError: 7272:0:(llog_cat.c:739:llog_cat_cancel_arr_rec()) Skipped 1 previous similar message [ 467.232589] LustreError: 7272:0:(llog_cat.c:775:llog_cat_cancel_records()) lustre-MDT0001-osd: fail to cancel 1 of 1 llog-records: rc = -5 [ 467.245984] LustreError: 7272:0:(llog_cat.c:775:llog_cat_cancel_records()) Skipped 1 previous similar message [ 470.582844] LustreError: 7272:0:(llog_cat.c:739:llog_cat_cancel_arr_rec()) lustre-MDT0001-osd: fail to cancel 1 llog-records: rc = -5 [ 470.593500] LustreError: 7272:0:(llog_cat.c:775:llog_cat_cancel_records()) lustre-MDT0001-osd: fail to cancel 1 of 1 llog-records: rc = -5 [ 471.364401] Lustre: *** cfs_fail_loc=19a, val=0*** [ 471.367158] Lustre: Skipped 4 previous similar messages [ 474.901163] LustreError: 7272:0:(llog_cat.c:739:llog_cat_cancel_arr_rec()) lustre-MDT0001-osd: fail to cancel 1 llog-records: rc = -5 [ 474.912737] LustreError: 7272:0:(llog_cat.c:739:llog_cat_cancel_arr_rec()) Skipped 2 previous similar messages [ 474.936377] LustreError: 7272:0:(llog_cat.c:775:llog_cat_cancel_records()) lustre-MDT0001-osd: fail to cancel 1 of 1 llog-records: rc = -5 [ 474.956847] LustreError: 7272:0:(llog_cat.c:775:llog_cat_cancel_records()) Skipped 2 previous similar messages [ 479.698458] Lustre: *** cfs_fail_loc=19a, val=0*** [ 479.709776] Lustre: Skipped 8 previous similar messages [ 489.965673] LustreError: 7272:0:(llog_cat.c:739:llog_cat_cancel_arr_rec()) lustre-MDT0001-osd: fail to cancel 1 llog-records: rc = -5 [ 489.976316] LustreError: 7272:0:(llog_cat.c:739:llog_cat_cancel_arr_rec()) Skipped 4 previous similar messages [ 489.988960] LustreError: 7272:0:(llog_cat.c:775:llog_cat_cancel_records()) lustre-MDT0001-osd: fail to cancel 1 of 1 llog-records: rc = -5 [ 490.001096] LustreError: 7272:0:(llog_cat.c:775:llog_cat_cancel_records()) Skipped 4 previous similar messages [ 495.917409] Lustre: *** cfs_fail_loc=19a, val=0*** [ 495.920436] Lustre: Skipped 17 previous similar messages [ 506.026065] LustreError: 6294:0:(llog_cat.c:739:llog_cat_cancel_arr_rec()) lustre-MDT0000-osd: fail to cancel 1 llog-records: rc = -5 [ 506.032513] LustreError: 6294:0:(llog_cat.c:739:llog_cat_cancel_arr_rec()) Skipped 11 previous similar messages [ 506.041472] LustreError: 6294:0:(llog_cat.c:775:llog_cat_cancel_records()) lustre-MDT0000-osd: fail to cancel 1 of 1 llog-records: rc = -5 [ 506.045888] LustreError: 6294:0:(llog_cat.c:775:llog_cat_cancel_records()) Skipped 11 previous similar messages [ 528.614747] Lustre: *** cfs_fail_loc=19a, val=0*** [ 528.624209] Lustre: Skipped 39 previous similar messages [ 560.609376] Lustre: DEBUG MARKER: == sanity test 60h: striped directory with missing stripes can be accessed ========================================================== 17:15:11 (1776201311) [ 562.319188] Lustre: *** cfs_fail_loc=188, val=0*** [ 565.631390] Lustre: *** cfs_fail_loc=189, val=0*** [ 576.049706] Lustre: DEBUG MARKER: SKIP: sanity test_60i skipping SLOW test 60i [ 578.481222] Lustre: DEBUG MARKER: == sanity test 61a: mmap() writes don't make sync hang ========================================================================== 17:15:29 (1776201329) [ 585.483734] Lustre: DEBUG MARKER: == sanity test 61b: mmap() of unstriped file is successful ========================================================== 17:15:37 (1776201337) [ 591.662180] Lustre: DEBUG MARKER: == sanity test 63a: Verify oig_wait interruption does not crash ================================================================= 17:15:43 (1776201343) [ 661.179865] Lustre: DEBUG MARKER: == sanity test 63b: async write errors should be returned to fsync ============================================================= 17:16:52 (1776201412) [ 673.338672] Lustre: DEBUG MARKER: == sanity test 64a: verify filter grant calculations (in kernel) =============================================================== 17:17:05 (1776201425) [ 680.887975] Lustre: DEBUG MARKER: SKIP: sanity test_64b skipping SLOW test 64b [ 682.369629] Lustre: DEBUG MARKER: == sanity test 64c: verify grant shrink ================== 17:17:14 (1776201434) [ 690.063837] Lustre: DEBUG MARKER: == sanity test 64d: check grant limit exceed ============= 17:17:21 (1776201441) [ 745.054755] Lustre: DEBUG MARKER: == sanity test 64e: check grant consumption (no grant allocation) ========================================================== 17:18:16 (1776201496) [ 748.354125] Lustre: *** cfs_fail_loc=725, val=0*** [ 753.247503] Lustre: *** cfs_fail_loc=725, val=0*** [ 761.030638] Lustre: DEBUG MARKER: == sanity test 64f: check grant consumption (with grant allocation) ========================================================== 17:18:32 (1776201512) [ 774.901952] Lustre: DEBUG MARKER: == sanity test 64g: grant shrink on MDT ================== 17:18:45 (1776201525) [ 803.026547] Lustre: DEBUG MARKER: == sanity test 64h: grant shrink on read ================= 17:19:14 (1776201554) [ 824.168731] Lustre: DEBUG MARKER: == sanity test 64i: shrink on reconnect ================== 17:19:35 (1776201575) [ 831.972698] Lustre: *** cfs_fail_loc=513, val=0*** [ 833.625462] Lustre: Failing over lustre-OST0000 [ 834.017562] 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 [ 834.032449] Lustre: lustre-OST0000: Not available for connect from 0@lo (stopping) [ 835.717822] Lustre: server umount lustre-OST0000 complete [ 838.368774] LustreError: 137-5: lustre-OST0000_UUID: not available for connect from 192.168.203.38@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 839.138419] LustreError: 137-5: lustre-OST0000_UUID: 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. [ 839.164076] LustreError: Skipped 1 previous similar message [ 843.484249] LustreError: 137-5: lustre-OST0000_UUID: not available for connect from 192.168.203.38@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 848.590806] LustreError: 137-5: lustre-OST0000_UUID: not available for connect from 192.168.203.38@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 848.617986] LustreError: Skipped 2 previous similar messages [ 853.702647] LustreError: 137-5: lustre-OST0000_UUID: not available for connect from 192.168.203.38@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 853.729358] LustreError: Skipped 2 previous similar messages [ 854.548456] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 854.716980] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [ 854.741304] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 855.935879] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 859.194229] Lustre: lustre-OST0000: Recovery over after 0:04, of 3 clients 3 recovered and 0 were evicted. [ 859.207309] Lustre: lustre-OST0000-osc-MDT0001: Connection restored to 192.168.203.138@tcp (at 0@lo) [ 859.231721] Lustre: lustre-OST0000: deleting orphan objects from 0x0:2519 to 0x0:2561 [ 859.445681] Lustre: DEBUG MARKER: oleg338-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 868.721574] Lustre: DEBUG MARKER: oleg338-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 870.455334] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 880.346641] Lustre: DEBUG MARKER: == sanity test 65a: directory with no stripe info ======== 17:20:31 (1776201631) [ 886.532743] Lustre: DEBUG MARKER: == sanity test 65b: directory setstripe -S stripe_size*2 -i 0 -c 1 ========================================================== 17:20:38 (1776201638) [ 893.043496] Lustre: DEBUG MARKER: == sanity test 65c: directory setstripe -S stripe_size*4 -i 1 -c 1 ========================================================== 17:20:44 (1776201644) [ 899.395152] Lustre: DEBUG MARKER: == sanity test 65d: directory setstripe -S stripe_size -c stripe_count ========================================================== 17:20:51 (1776201651) [ 905.936760] Lustre: DEBUG MARKER: == sanity test 65e: directory setstripe defaults ========= 17:20:57 (1776201657) [ 912.062355] Lustre: DEBUG MARKER: == sanity test 65f: dir setstripe permission (should return error) ============================================================= 17:21:03 (1776201663) [ 917.664354] Lustre: DEBUG MARKER: == sanity test 65g: directory setstripe -d =============== 17:21:09 (1776201669) [ 923.263744] Lustre: DEBUG MARKER: == sanity test 65h: directory stripe info inherit ============================================================================== 17:21:15 (1776201675) [ 928.960449] Lustre: DEBUG MARKER: == sanity test 65i: various tests to set root directory striping ========================================================== 17:21:20 (1776201680) [ 937.378524] Lustre: DEBUG MARKER: == sanity test 65j: set default striping on root directory (bug 6367)=========================================================== 17:21:28 (1776201688) [ 945.091797] Lustre: DEBUG MARKER: == sanity test 65k: validate manual striping works properly with deactivated OSCs ========================================================== 17:21:36 (1776201696) [ 947.193544] 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 [ 947.216615] Lustre: Skipped 1 previous similar message [ 947.227698] Lustre: lustre-OST0000: Client lustre-MDT0001-mdtlov_UUID (at 0@lo) reconnecting [ 947.237324] Lustre: lustre-OST0000-osc-MDT0001: Connection restored to 192.168.203.138@tcp (at 0@lo) [ 947.240535] Lustre: lustre-OST0000: deleting orphan objects from 0x280000400:37 to 0x280000400:65 [ 947.243443] Lustre: Skipped 1 previous similar message [ 948.137513] Lustre: lustre-OST0000: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnecting [ 948.145059] Lustre: lustre-OST0000: deleting orphan objects from 0x0:2519 to 0x0:2593 [ 949.033892] 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 [ 949.053392] Lustre: Skipped 1 previous similar message [ 949.066973] Lustre: lustre-OST0001-osc-MDT0001: Connection restored to 192.168.203.138@tcp (at 0@lo) [ 949.076889] Lustre: lustre-OST0001: deleting orphan objects from 0x2c0000400:3 to 0x2c0000400:33 [ 949.084481] Lustre: Skipped 1 previous similar message [ 949.947896] Lustre: lustre-OST0001: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnecting [ 949.954197] Lustre: Skipped 1 previous similar message [ 949.967628] Lustre: lustre-OST0001: deleting orphan objects from 0x0:2514 to 0x0:2529 [ 970.352479] Lustre: setting import lustre-OST0000_UUID INACTIVE by administrator request [ 987.835919] 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 [ 987.843437] Lustre: Skipped 1 previous similar message [ 987.847221] Lustre: lustre-OST0000: Client lustre-MDT0001-mdtlov_UUID (at 0@lo) reconnecting [ 987.855082] LustreError: lustre-OST0000-osc-MDT0001: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 987.868789] Lustre: lustre-OST0000-osc-MDT0001: Connection restored to 192.168.203.138@tcp (at 0@lo) [ 987.873245] Lustre: lustre-OST0000: deleting orphan objects from 0x280000400:37 to 0x280000400:97 [ 987.877975] Lustre: Skipped 1 previous similar message [ 993.335494] Lustre: DEBUG MARKER: oleg338-server.virtnet: executing wait_import_state FULL os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid 40 [ 993.655894] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid in FULL state after 0 sec [ 998.571264] Lustre: DEBUG MARKER: oleg338-server.virtnet: executing wait_import_state FULL os[cp].lustre-OST0000-osc-MDT0001.ost_server_uuid 40 [ 998.793745] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0001.ost_server_uuid in FULL state after 0 sec [ 1019.463747] Lustre: setting import lustre-OST0000_UUID INACTIVE by administrator request [ 1036.972276] 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 [ 1036.983782] Lustre: lustre-OST0000: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnecting [ 1036.996165] LustreError: lustre-OST0000-osc-MDT0000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 1037.023674] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 192.168.203.138@tcp (at 0@lo) [ 1037.028574] Lustre: lustre-OST0000: deleting orphan objects from 0x0:3594 to 0x0:3617 [ 1041.785874] Lustre: DEBUG MARKER: oleg338-server.virtnet: executing wait_import_state FULL os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid 40 [ 1041.970420] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid in FULL state after 0 sec [ 1046.827486] Lustre: DEBUG MARKER: oleg338-server.virtnet: executing wait_import_state FULL os[cp].lustre-OST0000-osc-MDT0001.ost_server_uuid 40 [ 1047.020186] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0001.ost_server_uuid in FULL state after 0 sec [ 1067.658927] Lustre: setting import lustre-OST0001_UUID INACTIVE by administrator request [ 1084.536172] 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 [ 1084.560170] Lustre: lustre-OST0001: Client lustre-MDT0001-mdtlov_UUID (at 0@lo) reconnecting [ 1084.570043] LustreError: lustre-OST0001-osc-MDT0001: This client was evicted by lustre-OST0001; in progress operations using this service will fail. [ 1084.593747] Lustre: lustre-OST0001-osc-MDT0001: Connection restored to 192.168.203.138@tcp (at 0@lo) [ 1084.595050] Lustre: lustre-OST0001: deleting orphan objects from 0x2c0000400:35 to 0x2c0000400:65 [ 1088.841818] Lustre: DEBUG MARKER: oleg338-server.virtnet: executing wait_import_state FULL os[cp].lustre-OST0001-osc-MDT0000.ost_server_uuid 40 [ 1089.057941] Lustre: DEBUG MARKER: os[cp].lustre-OST0001-osc-MDT0000.ost_server_uuid in FULL state after 0 sec [ 1093.265511] Lustre: DEBUG MARKER: oleg338-server.virtnet: executing wait_import_state FULL os[cp].lustre-OST0001-osc-MDT0001.ost_server_uuid 40 [ 1093.420687] Lustre: DEBUG MARKER: os[cp].lustre-OST0001-osc-MDT0001.ost_server_uuid in FULL state after 0 sec [ 1113.425797] Lustre: setting import lustre-OST0001_UUID INACTIVE by administrator request [ 1131.851622] 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 [ 1131.868719] Lustre: lustre-OST0001: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnecting [ 1131.881207] LustreError: lustre-OST0001-osc-MDT0000: This client was evicted by lustre-OST0001; in progress operations using this service will fail. [ 1131.894452] Lustre: lustre-OST0001-osc-MDT0000: Connection restored to 192.168.203.138@tcp (at 0@lo) [ 1131.899300] Lustre: lustre-OST0001: deleting orphan objects from 0x0:3532 to 0x0:3553 [ 1136.741905] Lustre: DEBUG MARKER: oleg338-server.virtnet: executing wait_import_state FULL os[cp].lustre-OST0001-osc-MDT0000.ost_server_uuid 40 [ 1137.015997] Lustre: DEBUG MARKER: os[cp].lustre-OST0001-osc-MDT0000.ost_server_uuid in FULL state after 0 sec [ 1141.688573] Lustre: DEBUG MARKER: oleg338-server.virtnet: executing wait_import_state FULL os[cp].lustre-OST0001-osc-MDT0001.ost_server_uuid 40 [ 1141.903532] Lustre: DEBUG MARKER: os[cp].lustre-OST0001-osc-MDT0001.ost_server_uuid in FULL state after 0 sec [ 1147.636605] Lustre: DEBUG MARKER: == sanity test 65l: lfs find on -1 stripe dir ================================================================================== 17:24:59 (1776201899) [ 1154.158573] Lustre: DEBUG MARKER: == sanity test 65m: normal user can't set filesystem default stripe ========================================================== 17:25:05 (1776201905) [ 1159.277915] Lustre: DEBUG MARKER: == sanity test 65n: don't inherit default layout from root for new subdirectories ========================================================== 17:25:11 (1776201911) [ 1192.270666] Lustre: DEBUG MARKER: == sanity test 66: update inode blocks count on client ========================================================================= 17:25:43 (1776201943) [ 1205.498553] Lustre: DEBUG MARKER: == sanity test 69: verify oa2dentry return -ENOENT doesn't LBUG ================================================================ 17:25:57 (1776201957) [ 1207.919354] Lustre: *** cfs_fail_loc=217, val=0*** [ 1211.527966] Lustre: *** cfs_fail_loc=217, val=0*** [ 1211.529392] Lustre: Skipped 1 previous similar message [ 1219.267343] Lustre: DEBUG MARKER: SKIP: sanity test_71 skipping SLOW test 71 [ 1220.979959] Lustre: DEBUG MARKER: == sanity test 72a: Test that remove suid works properly (bug5695) ============================================================== 17:26:12 (1776201972) [ 1228.270625] Lustre: DEBUG MARKER: == sanity test 72b: Test that we keep mode setting if without file data changed (bug 24226) ========================================================== 17:26:19 (1776201979) [ 1237.689521] Lustre: DEBUG MARKER: == sanity test 73: multiple MDC requests (should not deadlock) ========================================================== 17:26:28 (1776201988) [ 1271.619701] Lustre: DEBUG MARKER: == sanity test 74a: ldlm_enqueue freed-export error path, ls (shouldn't LBUG) ========================================================== 17:27:03 (1776202023) [ 1277.528132] Lustre: DEBUG MARKER: == sanity test 74b: ldlm_enqueue freed-export error path, touch (shouldn't LBUG) ========================================================== 17:27:09 (1776202029) [ 1284.380033] Lustre: DEBUG MARKER: == sanity test 74c: ldlm_lock_create error path, (shouldn't LBUG) ========================================================== 17:27:15 (1776202035) [ 1291.993285] Lustre: DEBUG MARKER: == sanity test 76a: confirm clients recycle inodes properly ============================================================== 17:27:23 (1776202043) [ 1354.178668] Lustre: DEBUG MARKER: == sanity test 76b: confirm clients recycle directory inodes properly ============================================================== 17:28:25 (1776202105) [ 1398.608670] Lustre: DEBUG MARKER: == sanity test 77a: normal checksum read/write operation ========================================================== 17:29:10 (1776202150) [ 1407.577396] Lustre: DEBUG MARKER: == sanity test 77b: checksum error on client write, read ========================================================== 17:29:18 (1776202158) [ 1408.526323] LustreError: 168-f: lustre-OST0000: BAD WRITE CHECKSUM: from 12345-192.168.203.38@tcp inode [0x200000407:0xc12:0x0] object 0x0:3883 extent [0-4194303]: client csum a78044ec, server csum a78044eb [ 1411.879691] Lustre: DEBUG MARKER: set checksum type to crc32, rc = 0 [ 1413.331030] LustreError: 132-0: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.203.38@tcp inode [0x200000407:0xc12:0x0] object 0x0:3883 extent [0-4194303], client returned csum e5108ffb (type 1), server csum e6ccc095 (type 1) [ 1416.079446] Lustre: DEBUG MARKER: set checksum type to adler, rc = 0 [ 1417.748132] LustreError: 132-0: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.203.38@tcp inode [0x200000407:0xc12:0x0] object 0x0:3883 extent [0-4194303], client returned csum f15b6798 (type 2), server csum ff7067e0 (type 2) [ 1420.708963] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 1422.283204] LustreError: 132-0: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.203.38@tcp inode [0x200000407:0xc12:0x0] object 0x0:3883 extent [0-4194303], client returned csum a73f5ea7 (type 4), server csum a78044eb (type 4) [ 1425.056664] Lustre: DEBUG MARKER: set checksum type to t10ip512, rc = 0 [ 1426.585564] LustreError: 132-0: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.203.38@tcp inode [0x200000407:0xc12:0x0] object 0x0:3883 extent [0-4194303], client returned csum 4679f1df (type 10), server csum 88ff296 (type 10) [ 1429.245346] Lustre: DEBUG MARKER: set checksum type to t10ip4K, rc = 0 [ 1432.620555] Lustre: DEBUG MARKER: set checksum type to t10crc512, rc = 0 [ 1434.076555] LustreError: 132-0: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.203.38@tcp inode [0x200000407:0xc12:0x0] object 0x0:3883 extent [0-4194303], client returned csum 2257df61 (type 40), server csum a1c3df53 (type 40) [ 1434.096477] LustreError: Skipped 1 previous similar message [ 1436.447560] Lustre: DEBUG MARKER: set checksum type to t10crc4K, rc = 0 [ 1439.870260] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 1446.509405] Lustre: DEBUG MARKER: == sanity test 77c: checksum error on client read with debug ========================================================== 17:29:57 (1776202197) [ 1451.208130] Lustre: 20609:0:(tgt_handler.c:1903:dump_all_bulk_pages()) dumping checksum data to /tmp/lustre-log-checksum_dump-ost-[0x200000407:0xc13:0x0]:[0-1048575]-da379b31-70ee1f51 [ 1451.226513] LustreError: dumping log to /tmp/lustre-log.1776202204.20609 [ 1451.313989] LustreError: 132-0: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.203.38@tcp inode [0x200000407:0xc13:0x0] object 0x0:3884 extent [0-1048575], client returned csum da379b31 (type 4), server csum 70ee1f51 (type 4) [ 1451.332734] LustreError: Skipped 1 previous similar message [ 1487.173171] Lustre: DEBUG MARKER: == sanity test 77d: checksum error on OST direct write, read ========================================================== 17:30:38 (1776202238) [ 1487.886271] LustreError: 168-f: lustre-OST0001: BAD WRITE CHECKSUM: from 12345-192.168.203.38@tcp inode [0x200000407:0xc15:0x0] object 0x0:3817 extent [0-4194303]: client csum de2bf73f, server csum de2bf73e [ 1490.956617] LustreError: 132-0: lustre-OST0001: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.203.38@tcp inode [0x200000407:0xc15:0x0] object 0x0:3817 extent [0-4194303], client returned csum f5a99216 (type 4), server csum de2bf73e (type 4) [ 1498.738471] Lustre: DEBUG MARKER: == sanity test 77f: repeat checksum error on write (expect error) ========================================================== 17:30:50 (1776202250) [ 1500.566284] Lustre: DEBUG MARKER: set checksum type to crc32, rc = 0 [ 1500.983507] LustreError: 168-f: lustre-OST0000: BAD WRITE CHECKSUM: from 12345-192.168.203.38@tcp inode [0x200000407:0xc16:0x0] object 0x0:3885 extent [0-4194303]: client csum 8b19b060, server csum 8b19b05f [ 1504.321361] LustreError: 168-f: lustre-OST0000: BAD WRITE CHECKSUM: from 12345-192.168.203.38@tcp inode [0x200000407:0xc16:0x0] object 0x0:3885 extent [4194304-8388607]: client csum 8b19b060, server csum 8b19b05f [ 1504.339729] LustreError: Skipped 3 previous similar messages [ 1511.248360] LustreError: 168-f: lustre-OST0000: BAD WRITE CHECKSUM: from 12345-192.168.203.38@tcp inode [0x200000407:0xc16:0x0] object 0x0:3885 extent [0-4194303]: client csum 8b19b060, server csum 8b19b05f [ 1511.265530] LustreError: Skipped 3 previous similar messages [ 1522.474205] LustreError: 168-f: lustre-OST0000: BAD WRITE CHECKSUM: from 12345-192.168.203.38@tcp inode [0x200000407:0xc16:0x0] object 0x0:3885 extent [4194304-8388607]: client csum 8b19b060, server csum 8b19b05f [ 1522.484616] LustreError: Skipped 3 previous similar messages [ 1541.432551] LustreError: 168-f: lustre-OST0000: BAD WRITE CHECKSUM: from 12345-192.168.203.38@tcp inode [0x200000407:0xc16:0x0] object 0x0:3885 extent [0-4194303]: client csum 8b19b060, server csum 8b19b05f [ 1541.443218] LustreError: Skipped 5 previous similar messages [ 1550.494560] Lustre: DEBUG MARKER: set checksum type to adler, rc = 0 [ 1578.765820] LustreError: 168-f: lustre-OST0000: BAD WRITE CHECKSUM: from 12345-192.168.203.38@tcp inode [0x200000407:0xc16:0x0] object 0x0:3885 extent [0-4194303]: client csum 7d33b9a0, server csum 7d33b99f [ 1578.777309] LustreError: Skipped 17 previous similar messages [ 1602.465914] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 1643.296092] LustreError: 168-f: lustre-OST0000: BAD WRITE CHECKSUM: from 12345-192.168.203.38@tcp inode [0x200000407:0xc16:0x0] object 0x0:3885 extent [4194304-8388607]: client csum de2bf73f, server csum de2bf73e [ 1643.312425] LustreError: Skipped 25 previous similar messages [ 1652.813089] Lustre: DEBUG MARKER: set checksum type to t10ip512, rc = 0 [ 1703.477902] Lustre: DEBUG MARKER: set checksum type to t10ip4K, rc = 0 [ 1752.289646] Lustre: DEBUG MARKER: set checksum type to t10crc512, rc = 0 [ 1774.356314] LustreError: 168-f: lustre-OST0000: BAD WRITE CHECKSUM: from 12345-192.168.203.38@tcp inode [0x200000407:0xc16:0x0] object 0x0:3885 extent [0-4194303]: client csum a30822f0, server csum a30822ef [ 1774.374676] LustreError: Skipped 59 previous similar messages [ 1802.050074] Lustre: DEBUG MARKER: set checksum type to t10crc4K, rc = 0 [ 1852.390685] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 1858.307342] Lustre: DEBUG MARKER: == sanity test 77g: checksum error on OST write, read ==== 17:36:50 (1776202610) [ 1859.622247] Lustre: *** cfs_fail_loc=21a, val=0*** [ 1862.799958] Lustre: *** cfs_fail_loc=21b, val=0*** [ 1870.937899] Lustre: DEBUG MARKER: == sanity test 77k: enable/disable checksum correctly ==== 17:37:02 (1776202622) [ 1871.673817] Lustre: Setting parameter lustre.osc.lustre*.checksums in log params [ 1875.011201] Lustre: Modifying parameter lustre.osc.lustre*.checksums in log params [ 1878.762603] Lustre: Disabling parameter lustre.osc.lustre*.checksums in log params [ 1889.919081] Lustre: Setting parameter lustre.osc.lustre*.checksums in log params [ 1893.485877] Lustre: DEBUG MARKER: == sanity test 77l: preferred checksum type is remembered after reconnected ========================================================== 17:37:25 (1776202645) [ 1894.974840] Lustre: DEBUG MARKER: set checksum type to invalid, rc = 22 [ 1896.422586] Lustre: DEBUG MARKER: set checksum type to crc32, rc = 0 [ 1901.945523] Lustre: DEBUG MARKER: oleg338-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff926a185a7000.ost_server_uuid 40 [ 1907.554096] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff926a185a7000.ost_server_uuid in IDLE state after 4 sec [ 1913.792460] Lustre: DEBUG MARKER: oleg338-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff926a185a7000.ost_server_uuid 40 [ 1915.238629] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff926a185a7000.ost_server_uuid in FULL state after 0 sec [ 1916.892534] Lustre: DEBUG MARKER: set checksum type to adler, rc = 0 [ 1923.016040] Lustre: DEBUG MARKER: oleg338-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff926a185a7000.ost_server_uuid 40 [ 1943.294160] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff926a185a7000.ost_server_uuid in IDLE state after 17 sec [ 1949.028802] Lustre: DEBUG MARKER: oleg338-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff926a185a7000.ost_server_uuid 40 [ 1950.375740] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff926a185a7000.ost_server_uuid in FULL state after 0 sec [ 1952.037914] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 1957.307633] Lustre: DEBUG MARKER: oleg338-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff926a185a7000.ost_server_uuid 40 [ 1980.189981] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff926a185a7000.ost_server_uuid in IDLE state after 19 sec [ 1986.682776] Lustre: DEBUG MARKER: oleg338-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff926a185a7000.ost_server_uuid 40 [ 1988.172151] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff926a185a7000.ost_server_uuid in FULL state after 0 sec [ 1989.821920] Lustre: DEBUG MARKER: set checksum type to t10ip512, rc = 0 [ 1995.548421] Lustre: DEBUG MARKER: oleg338-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff926a185a7000.ost_server_uuid 40 [ 2014.103786] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff926a185a7000.ost_server_uuid in IDLE state after 15 sec [ 2021.106579] Lustre: DEBUG MARKER: oleg338-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff926a185a7000.ost_server_uuid 40 [ 2022.536139] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff926a185a7000.ost_server_uuid in FULL state after 0 sec [ 2024.599499] Lustre: DEBUG MARKER: set checksum type to t10ip4K, rc = 0 [ 2031.503473] Lustre: DEBUG MARKER: oleg338-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff926a185a7000.ost_server_uuid 40 [ 2048.796347] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff926a185a7000.ost_server_uuid in IDLE state after 14 sec [ 2054.632516] Lustre: DEBUG MARKER: oleg338-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff926a185a7000.ost_server_uuid 40 [ 2056.262958] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff926a185a7000.ost_server_uuid in FULL state after 0 sec [ 2058.008473] Lustre: DEBUG MARKER: set checksum type to t10crc512, rc = 0 [ 2063.946527] Lustre: DEBUG MARKER: oleg338-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff926a185a7000.ost_server_uuid 40 [ 2085.190080] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff926a185a7000.ost_server_uuid in IDLE state after 18 sec [ 2091.844312] Lustre: DEBUG MARKER: oleg338-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff926a185a7000.ost_server_uuid 40 [ 2093.243536] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff926a185a7000.ost_server_uuid in FULL state after 0 sec [ 2094.713663] Lustre: DEBUG MARKER: set checksum type to t10crc4K, rc = 0 [ 2100.575412] Lustre: DEBUG MARKER: oleg338-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff926a185a7000.ost_server_uuid 40 [ 2121.356475] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff926a185a7000.ost_server_uuid in IDLE state after 17 sec [ 2128.579871] Lustre: DEBUG MARKER: oleg338-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff926a185a7000.ost_server_uuid 40 [ 2130.329452] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff926a185a7000.ost_server_uuid in FULL state after 0 sec [ 2137.643455] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 2139.635533] Lustre: DEBUG MARKER: == sanity test 77m: Verify checksum_speed is correctly read ========================================================== 17:41:30 (1776202890) [ 2148.916134] Lustre: DEBUG MARKER: == sanity test 77n: Verify read from a hole inside contiguous blocks with T10PI ========================================================== 17:41:40 (1776202900) [ 2151.305462] Lustre: DEBUG MARKER: set checksum type to t10ip512, rc = 0 [ 2153.098952] Lustre: DEBUG MARKER: set checksum type to t10ip4K, rc = 0 [ 2154.720262] Lustre: DEBUG MARKER: set checksum type to t10crc512, rc = 0 [ 2156.062296] Lustre: DEBUG MARKER: set checksum type to t10crc4K, rc = 0 [ 2162.301223] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 2163.786395] Lustre: DEBUG MARKER: == sanity test 77o: Verify checksum_type for server (mdt and ofd(obdfilter)) ========================================================== 17:41:55 (1776202915) [ 2175.321451] Lustre: DEBUG MARKER: == sanity test 78: handle large O_DIRECT writes correctly ====================================================================== 17:42:06 (1776202926) [ 2184.347324] Lustre: DEBUG MARKER: == sanity test 79: df report consistency check ================================================================================= 17:42:15 (1776202935) [ 2198.561459] Lustre: DEBUG MARKER: == sanity test 80: Page eviction is equally fast at high offsets too ========================================================== 17:42:30 (1776202950) [ 2206.021281] Lustre: DEBUG MARKER: == sanity test 81a: OST should retry write when get -ENOSPC ========================================================================= 17:42:37 (1776202957) [ 2207.386943] Lustre: *** cfs_fail_loc=228, val=0*** [ 2213.113798] Lustre: DEBUG MARKER: == sanity test 81b: OST should return -ENOSPC when retry still fails ================================================================= 17:42:44 (1776202964) [ 2214.305486] Lustre: *** cfs_fail_loc=228, val=0*** [ 2220.771595] Lustre: DEBUG MARKER: == sanity test 99: cvs strange file/directory operations ========================================================== 17:42:52 (1776202972) [ 2240.076729] Lustre: DEBUG MARKER: == sanity test 100: check local port using privileged port ===================================================================== 17:43:11 (1776202991) [ 2248.405684] Lustre: DEBUG MARKER: == sanity test 101a: check read-ahead for random reads === 17:43:20 (1776203000) [ 2343.292527] Lustre: DEBUG MARKER: == sanity test 101b: check stride-io mode read-ahead =========================================================================== 17:44:54 (1776203094) [ 2360.188714] Lustre: DEBUG MARKER: == sanity test 101c: check stripe_size aligned read-ahead ========================================================== 17:45:11 (1776203111) [ 2405.283749] Lustre: DEBUG MARKER: == sanity test 101d: file read with and without read-ahead enabled ========================================================== 17:45:56 (1776203156) [ 2573.955398] Lustre: DEBUG MARKER: == sanity test 101e: check read-ahead for small read(1k) for small files(500k) ========================================================== 17:48:45 (1776203325) [ 2611.161713] Lustre: DEBUG MARKER: == sanity test 101f: check mmap read performance ========= 17:49:22 (1776203362) [ 2621.611572] Lustre: DEBUG MARKER: == sanity test 101g: Big bulk(4/16 MiB) readahead ======== 17:49:33 (1776203373) [ 2659.695145] Lustre: DEBUG MARKER: == sanity test 101h: Readahead should cover current read window ========================================================== 17:50:11 (1776203411) [ 2669.458662] Lustre: DEBUG MARKER: == sanity test 101i: allow current readahead to exceed reservation ========================================================== 17:50:20 (1776203420) [ 2677.255278] Lustre: DEBUG MARKER: == sanity test 101j: A complete read block should be submitted when no RA ========================================================== 17:50:28 (1776203428) [ 2715.051332] Lustre: DEBUG MARKER: == sanity test 102a: user xattr test ============================================================================================ 17:51:06 (1776203466) [ 2723.968860] Lustre: DEBUG MARKER: == sanity test 102b: getfattr/setfattr for trusted.lov EAs ========================================================== 17:51:15 (1776203475) [ 2735.633745] Lustre: DEBUG MARKER: == sanity test 102c: non-root getfattr/setfattr for lustre.lov EAs ===================================================================== 17:51:27 (1776203487) [ 2743.392987] Lustre: DEBUG MARKER: == sanity test 102d: tar restore stripe info from tarfile,not keep osts ========================================================== 17:51:34 (1776203494) [ 2760.614331] Lustre: DEBUG MARKER: == sanity test 102f: tar copy files, not keep osts ======= 17:51:51 (1776203511) [ 2777.321647] Lustre: DEBUG MARKER: == sanity test 102h: grow xattr from inside inode to external block ========================================================== 17:52:08 (1776203528) [ 2779.584380] Lustre: DEBUG MARKER: save trusted.big on /mnt/lustre/f102h.sanity [ 2781.746393] Lustre: DEBUG MARKER: save trusted.sml on /mnt/lustre/f102h.sanity [ 2783.706721] Lustre: DEBUG MARKER: grow trusted.sml on /mnt/lustre/f102h.sanity [ 2785.340140] Lustre: DEBUG MARKER: trusted.big still valid after growing trusted.sml [ 2791.923909] Lustre: DEBUG MARKER: == sanity test 102ha: grow xattr from inside inode to external inode ========================================================== 17:52:23 (1776203543) [ 2795.068587] Lustre: DEBUG MARKER: save trusted.big on /mnt/lustre/f102ha.sanity [ 2796.607827] Lustre: DEBUG MARKER: save trusted.sml on /mnt/lustre/f102ha.sanity [ 2797.974293] Lustre: DEBUG MARKER: grow trusted.sml on /mnt/lustre/f102ha.sanity [ 2799.436664] Lustre: DEBUG MARKER: trusted.big still valid after growing trusted.sml [ 2801.533270] Lustre: DEBUG MARKER: save trusted.big on /mnt/lustre/f102ha.sanity [ 2807.647415] Lustre: DEBUG MARKER: == sanity test 102i: lgetxattr test on symbolic link ====================================================================== 17:52:39 (1776203559) [ 2814.272381] Lustre: DEBUG MARKER: == sanity test 102j: non-root tar restore stripe info from tarfile, not keep osts ============================================================= 17:52:45 (1776203565) [ 2829.663561] Lustre: DEBUG MARKER: == sanity test 102k: setfattr without parameter of value shouldn't cause a crash ========================================================== 17:53:01 (1776203581) [ 2838.665250] Lustre: DEBUG MARKER: == sanity test 102l: listxattr size test ============================================================================================ 17:53:09 (1776203589) [ 2847.550911] Lustre: DEBUG MARKER: == sanity test 102m: Ensure listxattr fails on small bufffer ================================================================== 17:53:18 (1776203598) [ 2856.699863] Lustre: DEBUG MARKER: == sanity test 102n: silently ignore setxattr on internal trusted xattrs ========================================================== 17:53:27 (1776203607) [ 2864.909919] Lustre: DEBUG MARKER: == sanity test 102p: check setxattr(2) correctly fails without permission ========================================================== 17:53:36 (1776203616) [ 2872.989203] Lustre: DEBUG MARKER: == sanity test 102q: flistxattr should not return trusted.link EAs for orphans ========================================================== 17:53:43 (1776203623) [ 2880.537686] Lustre: DEBUG MARKER: == sanity test 102r: set EAs with empty values =========== 17:53:51 (1776203631) [ 2886.999472] Lustre: DEBUG MARKER: == sanity test 102s: getting nonexistent xattrs should fail ========================================================== 17:53:58 (1776203638) [ 2893.419562] Lustre: DEBUG MARKER: == sanity test 102t: zero length xattr values handled correctly ========================================================== 17:54:05 (1776203645) [ 2900.934839] Lustre: DEBUG MARKER: == sanity test 103a: acl test ============================ 17:54:12 (1776203652) [ 3099.678715] Lustre: DEBUG MARKER: == sanity test 103b: umask lfs setstripe ================= 17:57:31 (1776203851) [ 3156.337996] Lustre: DEBUG MARKER: == sanity test 103c: 'cp -rp' won't set empty acl ======== 17:58:27 (1776203907) [ 3162.698549] Lustre: DEBUG MARKER: == sanity test 103e: inheritance of big amount of default ACLs ========================================================== 17:58:34 (1776203914) [ 3737.852589] Lustre: lustre-MDT0000: Client e7d67f6f-424e-4433-a0ee-fc9a83840bd5 (at 192.168.203.38@tcp) reconnecting [ 3844.333715] Lustre: lustre-MDT0000: Client e7d67f6f-424e-4433-a0ee-fc9a83840bd5 (at 192.168.203.38@tcp) reconnecting [ 4151.547126] Lustre: lustre-MDT0000: Client e7d67f6f-424e-4433-a0ee-fc9a83840bd5 (at 192.168.203.38@tcp) reconnecting [ 4251.954454] Lustre: DEBUG MARKER: == sanity test 103f: changelog doesn't interfere with default ACLs buffers ========================================================== 18:16:43 (1776205003) [ 4256.453581] Lustre: lustre-MDD0000: changelog on [ 4258.602966] Lustre: lustre-MDD0001: changelog on [ 4266.626890] Lustre: lustre-MDD0001: changelog off [ 4269.316622] Lustre: lustre-MDD0000: changelog off [ 4271.918422] Lustre: DEBUG MARKER: == sanity test 104a: lfs df [-ih] [path] test =================================================================================== 18:17:03 (1776205023) [ 4272.371482] Lustre: lustre-OST0000: Client e7d67f6f-424e-4433-a0ee-fc9a83840bd5 (at 192.168.203.38@tcp) reconnecting [ 4278.259791] Lustre: DEBUG MARKER: oleg338-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0000-osc-ffff926a07911000.ost_server_uuid 40 [ 4279.654758] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff926a07911000.ost_server_uuid in FULL state after 0 sec [ 4286.270762] Lustre: DEBUG MARKER: == sanity test 104b: runas -u 500 -g 500 lfs check servers test ============================================================================== 18:17:17 (1776205037) [ 4294.263357] Lustre: DEBUG MARKER: == sanity test 104c: Verify df vs lfs_df stays same after recordsize change ========================================================== 18:17:25 (1776205045) [ 4295.882116] Lustre: DEBUG MARKER: SKIP: sanity test_104c zfs only test [ 4297.884780] Lustre: DEBUG MARKER: == sanity test 105a: flock when mounted without -o flock test ================================================================== 18:17:29 (1776205049) [ 4305.572589] Lustre: DEBUG MARKER: == sanity test 105b: fcntl when mounted without -o flock test ================================================================== 18:17:36 (1776205056) [ 4313.757605] Lustre: DEBUG MARKER: == sanity test 105c: lockf when mounted without -o flock test ========================================================== 18:17:45 (1776205065) [ 4321.392661] Lustre: DEBUG MARKER: == sanity test 105d: flock race (should not freeze) ================================================================== 18:17:52 (1776205072) [ 4340.611604] Lustre: DEBUG MARKER: == sanity test 105e: Two conflicting flocks from same process ========================================================== 18:18:11 (1776205091) [ 4349.034927] Lustre: DEBUG MARKER: == sanity test 106: attempt exec of dir followed by chown of that dir ========================================================== 18:18:20 (1776205100) [ 4356.927843] Lustre: DEBUG MARKER: == sanity test 107: Coredump on SIG ====================== 18:18:28 (1776205108) [ 4368.788857] Lustre: DEBUG MARKER: == sanity test 110: filename length checking ============= 18:18:40 (1776205120) [ 4376.711565] Lustre: DEBUG MARKER: SKIP: sanity test_115 skipping SLOW test 115 [ 4378.660810] Lustre: DEBUG MARKER: == sanity test 116a: stripe QOS: free space balance ============================================================================= 18:18:50 (1776205130) [ 4528.075430] Lustre: DEBUG MARKER: == sanity test 116b: QoS shouldn't LBUG if not enough OSTs found on the 2nd pass ========================================================== 18:21:19 (1776205279) [ 4531.500264] Lustre: *** cfs_fail_loc=147, val=0*** [ 4543.241369] Lustre: DEBUG MARKER: == sanity test 117: verify osd extend ==================== 18:21:34 (1776205294) [ 4552.180368] Lustre: DEBUG MARKER: == sanity test 118a: verify O_SYNC works ================= 18:21:43 (1776205303) [ 4559.973205] Lustre: DEBUG MARKER: == sanity test 118b: Reclaim dirty pages on fatal error ==================================================================== 18:21:51 (1776205311) [ 4561.981766] Lustre: *** cfs_fail_loc=217, val=0*** [ 4561.985785] Lustre: Skipped 22 previous similar messages [ 4571.029832] Lustre: DEBUG MARKER: SKIP: sanity test_118c skipping ALWAYS excluded test 118c [ 4572.885931] Lustre: DEBUG MARKER: SKIP: sanity test_118d skipping ALWAYS excluded test 118d [ 4574.694404] Lustre: DEBUG MARKER: == sanity test 118f: Simulate unrecoverable OSC side error ==================================================================== 18:22:06 (1776205326) [ 4581.754823] Lustre: DEBUG MARKER: == sanity test 118g: Don't stay in wait if we got local -ENOMEM ==================================================================== 18:22:13 (1776205333) [ 4588.530212] Lustre: DEBUG MARKER: == sanity test 118h: Verify timeout in handling recoverables errors ==================================================================== 18:22:20 (1776205340) [ 4590.496240] Lustre: *** cfs_fail_loc=20e, val=0*** [ 4591.621216] Lustre: *** cfs_fail_loc=20e, val=0*** [ 4593.675703] Lustre: *** cfs_fail_loc=20e, val=0*** [ 4596.741701] Lustre: *** cfs_fail_loc=20e, val=0*** [ 4600.774428] Lustre: *** cfs_fail_loc=20e, val=0*** [ 4610.184520] Lustre: DEBUG MARKER: == sanity test 118i: Fix error before timeout in recoverable error ==================================================================== 18:22:41 (1776205361) [ 4612.357230] Lustre: *** cfs_fail_loc=20e, val=0*** [ 4630.385964] Lustre: DEBUG MARKER: == sanity test 118j: Simulate unrecoverable OST side error ==================================================================== 18:23:01 (1776205381) [ 4632.350857] Lustre: *** cfs_fail_loc=220, val=0*** [ 4632.356451] Lustre: Skipped 3 previous similar messages [ 4641.544266] Lustre: DEBUG MARKER: == sanity test 118k: bio alloc -ENOMEM and IO TERM handling =================================================================== 18:23:12 (1776205392) [ 4661.872378] Lustre: DEBUG MARKER: == sanity test 118l: fsync dir =========================== 18:23:33 (1776205413) [ 4669.253974] Lustre: DEBUG MARKER: == sanity test 118m: fdatasync dir ======================= 18:23:40 (1776205420) [ 4677.046181] Lustre: DEBUG MARKER: == sanity test 118n: statfs() sends OST_STATFS requests in parallel ========================================================== 18:23:48 (1776205428) [ 4690.037412] Lustre: DEBUG MARKER: == sanity test 119a: Short directIO read must return actual read amount ========================================================== 18:24:01 (1776205441) [ 4697.719677] Lustre: DEBUG MARKER: == sanity test 119b: Sparse directIO read must return actual read amount ========================================================== 18:24:09 (1776205449) [ 4706.351953] Lustre: DEBUG MARKER: == sanity test 119c: Testing for direct read hitting hole ========================================================== 18:24:17 (1776205457) [ 4714.350564] Lustre: DEBUG MARKER: == sanity test 119d: The DIO path should try to send a new rpc once one is completed ========================================================== 18:24:25 (1776205465) [ 4717.301264] Lustre: DEBUG MARKER: the DIO writes have completed, now wait for the reads (should not block very long) [ 4726.983545] Lustre: DEBUG MARKER: == sanity test 120a: Early Lock Cancel: mkdir test ======= 18:24:38 (1776205478) [ 4736.674548] Lustre: DEBUG MARKER: == sanity test 120b: Early Lock Cancel: create test ====== 18:24:48 (1776205488) [ 4745.452805] Lustre: DEBUG MARKER: == sanity test 120c: Early Lock Cancel: link test ======== 18:24:57 (1776205497) [ 4754.169569] Lustre: DEBUG MARKER: == sanity test 120d: Early Lock Cancel: setattr test ===== 18:25:05 (1776205505) [ 4762.417829] Lustre: DEBUG MARKER: == sanity test 120e: Early Lock Cancel: unlink test ====== 18:25:14 (1776205514) [ 4777.949822] Lustre: DEBUG MARKER: == sanity test 120f: Early Lock Cancel: rename test ====== 18:25:29 (1776205529) [ 4794.730984] Lustre: DEBUG MARKER: == sanity test 120g: Early Lock Cancel: performance test ========================================================== 18:25:46 (1776205546) [ 5145.684748] Lustre: DEBUG MARKER: == sanity test 121: read cancel race ===================== 18:31:37 (1776205897) [ 5152.751839] Lustre: DEBUG MARKER: == sanity test 123aa: verify statahead work ============== 18:31:44 (1776205904) [ 5158.161571] Lustre: DEBUG MARKER: ls -l 100 files without statahead: 1 sec [ 5160.538783] Lustre: DEBUG MARKER: ls -l 100 files with statahead: 0 sec [ 5198.502961] Lustre: DEBUG MARKER: ls -l 1000 files without statahead: 17 sec [ 5204.392623] Lustre: DEBUG MARKER: ls -l 1000 files with statahead: 3 sec [ 5206.683392] Lustre: DEBUG MARKER: ls -l done [ 5221.390646] Lustre: DEBUG MARKER: rm -r /mnt/lustre/d123aa.sanity/: 12 seconds [ 5223.174593] Lustre: DEBUG MARKER: rm done [ 5231.102226] Lustre: DEBUG MARKER: == sanity test 123ab: verify statahead work by using statx ========================================================== 18:33:02 (1776205982) [ 5236.772302] Lustre: DEBUG MARKER: statx -l 100 files without statahead: 2 sec [ 5239.302960] Lustre: DEBUG MARKER: statx -l 100 files with statahead: 0 sec [ 5276.921103] Lustre: DEBUG MARKER: statx -l 1000 files without statahead: 16 sec [ 5282.749849] Lustre: DEBUG MARKER: statx -l 1000 files with statahead: 3 sec [ 5284.310801] Lustre: DEBUG MARKER: statx -l done [ 5297.999679] Lustre: DEBUG MARKER: rm -r /mnt/lustre/d123ab.sanity/: 11 seconds [ 5299.437280] Lustre: DEBUG MARKER: rm done [ 5307.324099] Lustre: DEBUG MARKER: == sanity test 123ac: verify statahead work by using statx without glimpse RPCs ========================================================== 18:34:18 (1776206058) [ 5312.815522] Lustre: DEBUG MARKER: statx -c 1 [ 5315.551731] Lustre: DEBUG MARKER: statx -c 1 [ 5354.604683] Lustre: DEBUG MARKER: statx -c 1 [ 5359.250608] Lustre: DEBUG MARKER: statx -c 1 [ 5361.319688] Lustre: DEBUG MARKER: statx -c 1 [ 5373.766114] Lustre: DEBUG MARKER: rm -r /mnt/lustre/d123ac.sanity/: 10 seconds [ 5375.977889] Lustre: DEBUG MARKER: rm done [ 5380.402876] Lustre: DEBUG MARKER: statx --cached=always -D 100 files without statahead: 0 sec [ 5382.436120] Lustre: DEBUG MARKER: statx --cached=always -D 100 files with statahead: 0 sec [ 5403.982562] Lustre: DEBUG MARKER: statx --cached=always -D 1000 files without statahead: 0 sec [ 5406.480991] Lustre: DEBUG MARKER: statx --cached=always -D 1000 files with statahead: 0 sec [ 5557.651672] Lustre: DEBUG MARKER: statx --cached=always -D 10000 files without statahead: 1 sec [ 5559.943770] Lustre: DEBUG MARKER: statx --cached=always -D 10000 files with statahead: 1 sec [ 6954.534453] Lustre: DEBUG MARKER: statx --cached=always -D 100000 files without statahead: 2 sec [ 6957.437566] Lustre: DEBUG MARKER: statx --cached=always -D 100000 files with statahead: 1 sec [ 6959.274559] Lustre: DEBUG MARKER: statx --cached=always -D done [ 8523.874427] Lustre: DEBUG MARKER: rm -r /mnt/lustre/d123ac.sanity/: 1562 seconds [ 8525.312584] Lustre: DEBUG MARKER: rm done [ 8531.983637] Lustre: DEBUG MARKER: == sanity test 123b: not panic with network error in statahead enqueue (bug 15027) ========================================================== 19:28:03 (1776209283) [ 8553.322475] Lustre: DEBUG MARKER: ls done [ 8568.492532] Lustre: DEBUG MARKER: == sanity test 123c: Can not initialize inode warning on DNE statahead ========================================================== 19:28:39 (1776209319) [ 8578.157955] Lustre: DEBUG MARKER: == sanity test 124a: lru resize ================================================================================================= 19:28:49 (1776209329) [ 8580.035347] Lustre: DEBUG MARKER: create 2000 files at /mnt/lustre/d124a.sanity [ 8617.314700] Lustre: DEBUG MARKER: NSDIR=ldlm.namespaces.lustre-MDT0000-mdc-ffff926a08f6d800 [ 8619.126698] Lustre: DEBUG MARKER: NS=ldlm.namespaces.lustre-MDT0000-mdc-ffff926a08f6d800 [ 8620.892446] Lustre: DEBUG MARKER: LRU=1004 [ 8622.416234] Lustre: DEBUG MARKER: LIMIT=46162 [ 8623.927395] Lustre: DEBUG MARKER: LVF=5517300 [ 8625.619881] Lustre: DEBUG MARKER: OLD_LVF=100 [ 8627.119890] Lustre: DEBUG MARKER: Sleep 50 sec [ 8679.862852] Lustre: DEBUG MARKER: Dropped 519 locks in 50s [ 8681.644856] Lustre: DEBUG MARKER: unlink 2000 files at /mnt/lustre/d124a.sanity [ 8718.381970] Lustre: DEBUG MARKER: == sanity test 124b: lru resize (performance test) ================================================================================= 19:31:09 (1776209469) [ 8833.511844] Lustre: DEBUG MARKER: doing ls -la /mnt/lustre/d124b.sanity/disable_lru_resize 3 times [ 8911.486588] Lustre: DEBUG MARKER: ls -la time: 75 seconds [ 8912.960857] Lustre: DEBUG MARKER: lru_size = 400 [ 9135.803872] Lustre: DEBUG MARKER: doing ls -la /mnt/lustre/d124b.sanity/enable_lru_resize 3 times [ 9194.989876] Lustre: DEBUG MARKER: ls -la time: 55 seconds [ 9196.737861] Lustre: DEBUG MARKER: lru_size = 4006 [ 9198.670265] Lustre: DEBUG MARKER: ls -la is 26% faster with lru resize enabled [ 9274.400462] Lustre: DEBUG MARKER: == sanity test 124c: LRUR cancel very aged locks ========= 19:40:25 (1776210025) [ 9305.812821] Lustre: DEBUG MARKER: == sanity test 124d: cancel very aged locks if lru-resize diasbaled ========================================================== 19:40:57 (1776210057) [ 9341.317149] Lustre: DEBUG MARKER: == sanity test 125: don't return EPROTO when a dir has a non-default striping and ACLs ========================================================== 19:41:32 (1776210092) [ 9350.072547] Lustre: DEBUG MARKER: == sanity test 126: check that the fsgid provided by the client is taken into account ========================================================== 19:41:41 (1776210101) [ 9357.667960] Lustre: DEBUG MARKER: == sanity test 127a: verify the client stats are sane ==== 19:41:49 (1776210109) [ 9364.723576] Lustre: DEBUG MARKER: == sanity test 127b: verify the llite client stats are sane ========================================================== 19:41:56 (1776210116) [ 9373.363558] Lustre: DEBUG MARKER: == sanity test 127c: test llite extent stats with regular [ 9394.542592] Lustre: DEBUG MARKER: == sanity test 128: interactive lfs for 2 consecutive find's ========================================================== 19:42:26 (1776210146) [ 9402.222490] Lustre: DEBUG MARKER: == sanity test 129: test directory size limit ================================================================================== 19:42:33 (1776210153) [ 9419.457974] Lustre: 6264:0:(osd_handler.c:586:osd_ldiskfs_add_entry()) lustre-MDT0000: directory (inode: 1806, FID: [0x20000040b:0x23dc:0x0]) is approaching max size limit [ 9421.156857] Lustre: 8563:0:(osd_handler.c:586:osd_ldiskfs_add_entry()) lustre-MDT0000: directory (inode: 1806, FID: [0x20000040b:0x23dc:0x0]) is approaching max size limit [ 9432.570562] Lustre: 6264:0:(osd_handler.c:582:osd_ldiskfs_add_entry()) lustre-MDT0000: directory (inode: 1806, FID: [0x20000040b:0x23dc:0x0]) has reached max size limit [ 9467.462094] Lustre: DEBUG MARKER: == sanity test 130a: FIEMAP (1-stripe file) ============== 19:43:38 (1776210218) [ 9476.543896] Lustre: DEBUG MARKER: == sanity test 130b: FIEMAP (2-stripe file) ============== 19:43:47 (1776210227) [ 9485.967885] Lustre: DEBUG MARKER: == sanity test 130c: FIEMAP (2-stripe file with hole) ==== 19:43:56 (1776210236) [ 9496.854399] Lustre: DEBUG MARKER: == sanity test 130d: FIEMAP (N-stripe file) ============== 19:44:07 (1776210247) [ 9499.413429] Lustre: DEBUG MARKER: SKIP: sanity test_130d needs >= 3 OSTs [ 9502.435620] Lustre: DEBUG MARKER: == sanity test 130e: FIEMAP (test continuation FIEMAP calls) ========================================================== 19:44:12 (1776210252) [ 9551.526670] Lustre: DEBUG MARKER: == sanity test 130f: FIEMAP (unstriped file) ============= 19:45:02 (1776210302) [ 9559.888117] Lustre: DEBUG MARKER: == sanity test 130g: FIEMAP (overstripe file) ============ 19:45:10 (1776210310) [ 9580.352601] Lustre: DEBUG MARKER: == sanity test 131a: test iov's crossing stripe boundary for writev/readv ========================================================== 19:45:30 (1776210330) [ 9592.008247] Lustre: DEBUG MARKER: == sanity test 131b: test append writev ================== 19:45:43 (1776210343) [ 9599.956303] Lustre: DEBUG MARKER: == sanity test 131c: test read/write on file w/o objects ========================================================== 19:45:51 (1776210351) [ 9608.249122] Lustre: DEBUG MARKER: == sanity test 131d: test short read ===================== 19:45:59 (1776210359) [ 9617.332874] Lustre: DEBUG MARKER: == sanity test 131e: test read hitting hole ============== 19:46:08 (1776210368) [ 9626.791808] Lustre: DEBUG MARKER: == sanity test 133a: Verifying MDT stats ================================================================================================== 19:46:17 (1776210377) [ 9651.854964] Lustre: DEBUG MARKER: == sanity test 133b: Verifying extra MDT stats ============================================================================================ 19:46:42 (1776210402) [ 9665.224315] Lustre: DEBUG MARKER: == sanity test 133c: Verifying OST stats ================================================================================================== 19:46:56 (1776210416) [ 9702.171730] Lustre: DEBUG MARKER: == sanity test 133d: Verifying rename_stats ================================================================================================== 19:47:33 (1776210453) [ 9738.739613] Lustre: DEBUG MARKER: == sanity test 133e: Verifying OST read_bytes write_bytes nid stats =========================================================================== 19:48:10 (1776210490) [ 9752.327405] Lustre: DEBUG MARKER: == sanity test 133f: Check reads/writes of client lustre proc files with bad area io ========================================================== 19:48:23 (1776210503) [ 9769.958056] LustreError: 11-0: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 9769.969152] 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 [ 9769.989710] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 9769.992419] Lustre: Skipped 1 previous similar message [ 9770.976706] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 9770.985993] Lustre: Skipped 3 previous similar messages [ 9775.927093] Lustre: server umount lustre-MDT0000 complete [ 9776.109821] LustreError: 137-5: lustre-MDT0000_UUID: 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. [ 9776.130762] LustreError: Skipped 5 previous similar messages [ 9781.219804] LustreError: 137-5: lustre-MDT0000_UUID: 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. [ 9781.236218] LustreError: Skipped 3 previous similar messages [ 9782.239125] Lustre: 3361:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776210528/real 1776210528] req@00000000f507b3cf x1862481559556544/t0(0) o400->MGC192.168.203.138@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1776210535 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:1.0' [ 9782.256254] LustreError: 166-1: MGC192.168.203.138@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 9784.878551] Lustre: server umount lustre-MDT0001 complete [ 9794.399151] Lustre: 3359:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776210540/real 1776210540] req@000000002d07a566 x1862481559558784/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1776210547 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:2.0' [ 9794.421740] 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 [ 9794.436304] Lustre: Skipped 3 previous similar messages [ 9796.127308] Lustre: 3361:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776210541/real 1776210541] req@00000000ba9693fd x1862481559559040/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1776210548 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:2.0' [ 9799.136252] Lustre: 84065:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776210545/real 1776210545] req@00000000f507b3cf x1862481559559488/t0(0) o39->lustre-MDT0001-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1776210551 ref 2 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'umount.0' [ 9799.218155] Lustre: server umount lustre-OST0000 complete [ 9807.438355] Lustre: server umount lustre-OST0001 complete [ 9829.174974] Lustre: DEBUG MARKER: oleg338-server.virtnet: executing unload_modules_local [ 9832.490700] Key type lgssc unregistered [ 9832.798555] LNet: 85369:0:(lib-ptl.c:992:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 9832.805186] LNet: Removed LNI 192.168.203.138@tcp [ 9833.771451] Key type .llcrypt unregistered [ 9833.774195] Key type ._llcrypt unregistered [ 9847.087233] alg: No test for adler32 (adler32-zlib) [ 9847.840511] Key type ._llcrypt registered [ 9847.844025] Key type .llcrypt registered [ 9847.948959] Lustre: DEBUG MARKER: oleg338-server.virtnet: executing load_modules_local [ 9848.597618] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 9849.261165] Lustre: Lustre: Build Version: 2.15.8_1_g00e7d23 [ 9849.437876] LNet: Added LNI 192.168.203.138@tcp [8/256/0/180] [ 9849.442738] LNet: Accept secure, port 988 [ 9851.088496] Key type lgssc registered [ 9852.144366] Lustre: Echo OBD driver; http://www.lustre.org/ [ 9868.331444] Lustre: DEBUG MARKER: oleg338-server.virtnet: executing load_modules_local [ 9879.406451] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 9880.852639] LustreError: 137-5: lustre-MDT0001_UUID: 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. [ 9880.956950] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 9885.662346] Lustre: DEBUG MARKER: oleg338-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 9886.182642] LustreError: 137-5: lustre-MDT0001_UUID: 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. [ 9891.305211] LustreError: 137-5: lustre-MDT0001_UUID: 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. [ 9895.394364] LustreError: 137-5: lustre-MDT0001_UUID: 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. [ 9896.826764] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 9897.169351] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 9902.448258] Lustre: DEBUG MARKER: oleg338-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 9914.767640] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 9915.164890] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 9920.219415] Lustre: DEBUG MARKER: oleg338-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 9927.459335] LustreError: 137-5: lustre-OST0001_UUID: 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. [ 9927.486901] Lustre: lustre-OST0000: deleting orphan objects from 0x280000400:34355 to 0x280000400:34401 [ 9930.548186] Lustre: lustre-OST0000: deleting orphan objects from 0x0:39973 to 0x0:40001 [ 9934.793450] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 9935.258917] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 9940.478265] Lustre: lustre-OST0001: deleting orphan objects from 0x0:39714 to 0x0:39745 [ 9940.490720] Lustre: lustre-OST0001: deleting orphan objects from 0x2c0000400:34190 to 0x2c0000400:34209 [ 9941.009460] Lustre: DEBUG MARKER: oleg338-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 9953.289890] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 9958.009259] Lustre: Modifying parameter general.lod.*.mdt_hash in log params [ 9970.336834] Lustre: DEBUG MARKER: == sanity test 133g: Check reads/writes of server lustre proc files with bad area io ========================================================== 19:52:01 (1776210721) [10037.729813] 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 [10037.732309] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [10037.740938] Lustre: Skipped 3 previous similar messages [10037.743790] Lustre: Skipped 2 previous similar messages [10042.853409] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [10042.856306] Lustre: Skipped 2 previous similar messages [10043.925990] Lustre: server umount lustre-MDT0000 complete [10047.969322] LustreError: 137-5: lustre-MDT0000_UUID: 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. [10047.988744] LustreError: Skipped 5 previous similar messages [10051.666499] LustreError: 87517:0:(ldlm_lockd.c:2526:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1776210804 with bad export cookie 5890015969817393626 [10051.675232] LustreError: 166-1: MGC192.168.203.138@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [10051.678837] LustreError: 87517:0:(ldlm_lockd.c:2526:ldlm_cancel_handler()) Skipped 2 previous similar messages [10051.953511] Lustre: server umount lustre-MDT0001 complete [10060.127360] Lustre: 85893:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776210805/real 1776210805] req@00000000e68d4a8c x1862491808254976/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1776210812 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:1.0' [10060.130962] Lustre: lustre-MDT0001-lwp-OST0000: Connection to lustre-MDT0001 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [10060.153146] Lustre: 85893:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 1 previous similar message [10060.176207] Lustre: Skipped 1 previous similar message [10060.282666] Lustre: server umount lustre-OST0000 complete [10063.215804] Lustre: 85890:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776210808/real 1776210808] req@00000000c83e343a x1862491808255104/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1776210815 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:0.0' [10064.353216] Lustre: 85892:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776210810/real 1776210810] req@000000009ba65e6f x1862491808255232/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1776210817 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:0.0' [10069.042232] Lustre: server umount lustre-OST0001 complete [10085.653510] Lustre: DEBUG MARKER: oleg338-server.virtnet: executing unload_modules_local [10088.729996] Key type lgssc unregistered [10089.044651] LNet: 96041:0:(lib-ptl.c:992:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [10089.057930] LNet: Removed LNI 192.168.203.138@tcp [10090.021470] Key type .llcrypt unregistered [10090.027555] Key type ._llcrypt unregistered [10104.123498] alg: No test for adler32 (adler32-zlib) [10104.882713] Key type ._llcrypt registered [10104.888767] Key type .llcrypt registered [10105.049889] Lustre: DEBUG MARKER: oleg338-server.virtnet: executing load_modules_local [10105.986315] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [10106.701757] Lustre: Lustre: Build Version: 2.15.8_1_g00e7d23 [10106.989359] LNet: Added LNI 192.168.203.138@tcp [8/256/0/180] [10107.009301] LNet: Accept secure, port 988 [10108.743239] Key type lgssc registered [10110.038518] Lustre: Echo OBD driver; http://www.lustre.org/ [10127.003910] Lustre: DEBUG MARKER: oleg338-server.virtnet: executing load_modules_local [10140.986648] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [10142.578363] LustreError: 137-5: lustre-MDT0001_UUID: 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. [10142.684524] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [10147.815270] LustreError: 137-5: lustre-MDT0001_UUID: 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. [10147.862580] Lustre: DEBUG MARKER: oleg338-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [10152.927752] LustreError: 137-5: lustre-MDT0001_UUID: 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. [10158.050261] LustreError: 137-5: lustre-MDT0001_UUID: 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. [10159.186756] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [10159.543444] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [10164.100236] Lustre: DEBUG MARKER: oleg338-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [10176.847316] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [10177.256154] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [10182.015696] Lustre: DEBUG MARKER: oleg338-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [10189.546308] LustreError: 137-5: lustre-OST0001_UUID: 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. [10189.572560] Lustre: lustre-OST0000: deleting orphan objects from 0x280000400:34355 to 0x280000400:34433 [10192.632934] Lustre: lustre-OST0000: deleting orphan objects from 0x0:39973 to 0x0:40033 [10194.556802] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [10194.803664] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [10199.493632] Lustre: DEBUG MARKER: oleg338-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [10200.060612] Lustre: lustre-OST0001: deleting orphan objects from 0x2c0000400:34190 to 0x2c0000400:34241 [10200.061430] Lustre: lustre-OST0001: deleting orphan objects from 0x0:39714 to 0x0:39777 [10208.634588] Lustre: DEBUG MARKER: Using TIMEOUT=20 [10213.129868] Lustre: Modifying parameter general.lod.*.mdt_hash in log params [10226.279975] Lustre: DEBUG MARKER: == sanity test 133h: Proc files should end with newlines ========================================================== 19:56:17 (1776210977) [11017.950989] Lustre: DEBUG MARKER: == sanity test 134a: Server reclaims locks when reaching lock_reclaim_threshold ========================================================== 20:09:29 (1776211769) [11037.453834] Lustre: *** cfs_fail_loc=327, val=0*** [11071.917466] Lustre: DEBUG MARKER: == sanity test 134b: Server rejects lock request when reaching lock_limit_mb ========================================================== 20:10:23 (1776211823) [11078.385355] Lustre: *** cfs_fail_loc=328, val=0*** [11078.388560] Lustre: Skipped 512 previous similar messages [11079.388397] Lustre: *** cfs_fail_loc=328, val=0*** [11079.390484] Lustre: Skipped 72 previous similar messages [11081.401721] Lustre: *** cfs_fail_loc=328, val=0*** [11081.407826] Lustre: Skipped 168 previous similar messages [11086.364265] Lustre: *** cfs_fail_loc=328, val=0*** [11086.366280] Lustre: Skipped 136 previous similar messages [11094.826279] Lustre: *** cfs_fail_loc=328, val=0*** [11094.828368] Lustre: Skipped 66 previous similar messages [11099.298807] LustreError: 141929:0:(ldlm_resource.c:133:seq_watermark_write()) Failed to set lock_reclaim_threshold_mb, rc = -22. [11119.641367] Lustre: DEBUG MARKER: SKIP: sanity test_135 skipping SLOW test 135 [11121.676354] Lustre: DEBUG MARKER: SKIP: sanity test_136 skipping SLOW test 136 [11123.829290] Lustre: DEBUG MARKER: == sanity test 140: Check reasonable stack depth (shouldn't LBUG) ============================================================== 20:11:14 (1776211874) [11164.082162] Lustre: DEBUG MARKER: == sanity test 150a: truncate/append tests =============== 20:11:55 (1776211915) [11190.470796] Lustre: DEBUG MARKER: == sanity test 150b: Verify fallocate (prealloc) functionality ========================================================== 20:12:21 (1776211941) [11219.821437] Lustre: DEBUG MARKER: == sanity test 150bb: Verify fallocate modes both zero space ========================================================== 20:12:50 (1776211970) [11251.513742] Lustre: DEBUG MARKER: == sanity test 150c: Verify fallocate Size and Blocks ==== 20:13:22 (1776212002) [11275.580689] Lustre: DEBUG MARKER: == sanity test 150d: Verify fallocate Size and Blocks - Non zero start ========================================================== 20:13:46 (1776212026) [11287.321556] Lustre: DEBUG MARKER: == sanity test 150e: Verify 60% of available OST space consumed by fallocate ========================================================== 20:13:58 (1776212038) [11316.815294] Lustre: DEBUG MARKER: == sanity test 150f: Verify fallocate punch functionality ========================================================== 20:14:27 (1776212067) [11338.730976] Lustre: DEBUG MARKER: == sanity test 150g: Verify fallocate punch on large range ========================================================== 20:14:50 (1776212090) [11362.269927] Lustre: DEBUG MARKER: == sanity test 151: test cache on oss and controls ========================================================================================= 20:15:13 (1776212113) [11380.466772] bash (147970): drop_caches: 1 [11393.420188] Lustre: DEBUG MARKER: == sanity test 152: test read/write with enomem ====================================================================================== 20:15:45 (1776212145) [11401.033306] Lustre: DEBUG MARKER: == sanity test 153: test if fdatasync does not crash ================================================================================= 20:15:52 (1776212152) [11407.515264] Lustre: DEBUG MARKER: == sanity test 154A: lfs path2fid and fid2path basic checks ========================================================== 20:15:59 (1776212159) [11414.909477] Lustre: DEBUG MARKER: == sanity test 154B: verify the ll_decode_linkea tool ==== 20:16:06 (1776212166) [11422.412823] Lustre: DEBUG MARKER: == sanity test 154a: Open-by-FID ========================= 20:16:13 (1776212173) [11423.952155] LustreError: 101877:0:(fld_handler.c:263:fld_server_lookup()) srv-lustre-MDT0000: Cannot find sequence 0xf00000400: rc = -2 [11433.675905] Lustre: DEBUG MARKER: == sanity test 154b: Open-by-FID for remote directory ==== 20:16:24 (1776212184) [11435.008822] LustreError: 141783:0:(fld_handler.c:263:fld_server_lookup()) srv-lustre-MDT0000: Cannot find sequence 0xf00000400: rc = -2 [11435.020028] LustreError: 141783:0:(fld_handler.c:263:fld_server_lookup()) Skipped 3 previous similar messages [11443.564340] Lustre: DEBUG MARKER: == sanity test 154c: lfs path2fid and fid2path multiple arguments ========================================================== 20:16:34 (1776212194) [11451.559430] Lustre: DEBUG MARKER: == sanity test 154d: Verify open file fid ================ 20:16:42 (1776212202) [11460.457949] Lustre: DEBUG MARKER: == sanity test 154e: .lustre is not returned by readdir == 20:16:51 (1776212211) [11467.012228] Lustre: DEBUG MARKER: == sanity test 154f: get parent fids by reading link ea == 20:16:58 (1776212218) [11475.983412] Lustre: DEBUG MARKER: == sanity test 154g: various llapi FID tests ============= 20:17:07 (1776212227) [11891.088455] Lustre: DEBUG MARKER: == sanity test 155a: Verify small file correctness: read cache:on write_cache:on ========================================================== 20:24:02 (1776212642) [11905.702965] Lustre: DEBUG MARKER: == sanity test 155b: Verify small file correctness: read cache:on write_cache:off ========================================================== 20:24:16 (1776212656) [11920.738991] Lustre: DEBUG MARKER: == sanity test 155c: Verify small file correctness: read cache:off write_cache:on ========================================================== 20:24:31 (1776212671) [11933.746662] Lustre: DEBUG MARKER: == sanity test 155d: Verify small file correctness: read cache:off write_cache:off ========================================================== 20:24:45 (1776212685) [11948.121985] Lustre: DEBUG MARKER: == sanity test 155e: Verify big file correctness: read cache:on write_cache:on ========================================================== 20:24:59 (1776212699) [11980.274442] Lustre: DEBUG MARKER: == sanity test 155f: Verify big file correctness: read cache:on write_cache:off ========================================================== 20:25:31 (1776212731) [12009.234896] Lustre: DEBUG MARKER: == sanity test 155g: Verify big file correctness: read cache:off write_cache:on ========================================================== 20:26:00 (1776212760) [12037.909235] Lustre: DEBUG MARKER: == sanity test 155h: Verify big file correctness: read cache:off write_cache:off ========================================================== 20:26:29 (1776212789) [12069.475827] Lustre: DEBUG MARKER: == sanity test 156: Verification of tunables ============= 20:27:01 (1776212821) [12078.428479] Lustre: DEBUG MARKER: Turn on read and write cache [12082.995600] Lustre: DEBUG MARKER: Write data and read it back. [12085.319680] Lustre: DEBUG MARKER: Read should be satisfied from the cache. [12089.917669] Lustre: DEBUG MARKER: cache hits: before: 65581, after: 65584 [12091.772618] Lustre: DEBUG MARKER: Read again; it should be satisfied from the cache. [12095.344084] Lustre: DEBUG MARKER: cache hits:: before: 65584, after: 65587 [12097.421272] Lustre: DEBUG MARKER: Turn off the read cache and turn on the write cache [12103.139480] Lustre: DEBUG MARKER: Read again; it should be satisfied from the cache. [12108.434192] Lustre: DEBUG MARKER: cache hits:: before: 65587, after: 65590 [12110.145151] Lustre: DEBUG MARKER: Write data and read it back. [12111.945956] Lustre: DEBUG MARKER: Read should be satisfied from the cache. [12118.059820] Lustre: DEBUG MARKER: cache hits:: before: 65590, after: 65593 [12119.909364] Lustre: DEBUG MARKER: Turn off read and write cache [12124.992644] Lustre: DEBUG MARKER: Write data and read it back [12126.768612] Lustre: DEBUG MARKER: It should not be satisfied from the cache. [12131.986441] Lustre: DEBUG MARKER: cache hits:: before: 65593, after: 65593 [12133.508628] Lustre: DEBUG MARKER: Turn on the read cache and turn off the write cache [12137.957312] Lustre: DEBUG MARKER: Write data and read it back [12139.500384] Lustre: DEBUG MARKER: It should not be satisfied from the cache. [12143.912670] Lustre: DEBUG MARKER: cache hits:: before: 65593, after: 65593 [12145.511361] Lustre: DEBUG MARKER: Read again; it should be satisfied from the cache. [12150.387342] Lustre: DEBUG MARKER: cache hits:: before: 65593, after: 65596 [12159.759201] Lustre: DEBUG MARKER: == sanity test 160a: changelog sanity ==================== 20:28:31 (1776212911) [12162.824895] Lustre: lustre-MDD0000: changelog on [12166.350602] Lustre: lustre-MDD0001: changelog on [12183.462504] Lustre: Failing over lustre-MDT0000 [12183.675892] Lustre: server umount lustre-MDT0000 complete [12186.338069] LustreError: 137-5: lustre-MDT0000_UUID: not available for connect from 192.168.203.38@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [12186.371326] LustreError: Skipped 2 previous similar messages [12186.607706] 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 [12186.623889] Lustre: Skipped 3 previous similar messages [12191.453280] LustreError: 137-5: lustre-MDT0000_UUID: not available for connect from 192.168.203.38@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [12191.480302] LustreError: Skipped 4 previous similar messages [12192.836254] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [12192.977341] LustreError: 11-0: MGC192.168.203.138@tcp: operation mgs_target_reg to node 0@lo failed: rc = -107 [12192.980459] LustreError: 166-1: MGC192.168.203.138@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [12193.024857] Lustre: Evicted from MGS (at 192.168.203.138@tcp) after server handle changed from 0x644751aac144d32e to 0x644751aac14de012 [12193.037462] Lustre: MGC192.168.203.138@tcp: Connection restored to (at 0@lo) [12193.279245] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [12193.321255] Lustre: lustre-MDD0000: changelog on [12193.347519] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [12193.530699] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [12198.337841] Lustre: DEBUG MARKER: oleg338-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [12198.373531] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to (at 0@lo) [12198.579651] Lustre: lustre-MDT0000: Recovery over after 0:05, of 2 clients 2 recovered and 0 were evicted. [12198.662562] Lustre: lustre-OST0000: deleting orphan objects from 0x0:40858 to 0x0:40897 [12198.679642] Lustre: lustre-OST0001: deleting orphan objects from 0x0:40607 to 0x0:40641 [12202.995939] Lustre: lustre-MDD0000: changelog off [12205.329466] Lustre: lustre-MDD0001: changelog off [12219.546454] Lustre: DEBUG MARKER: == sanity test 160b: Verify that very long rename doesn't crash in changelog ========================================================== 20:29:30 (1776212970) [12222.427890] Lustre: lustre-MDD0000: changelog on [12234.605764] Lustre: lustre-MDD0001: changelog off [12237.383677] Lustre: lustre-MDD0000: changelog off [12239.985325] Lustre: DEBUG MARKER: == sanity test 160c: verify that changelog log catch the truncate event ========================================================== 20:29:51 (1776212991) [12242.751854] Lustre: lustre-MDD0000: changelog on [12242.755692] Lustre: Skipped 1 previous similar message [12255.830404] Lustre: lustre-MDD0001: changelog off [12261.430658] Lustre: DEBUG MARKER: == sanity test 160d: verify that changelog log catch the migrate event ========================================================== 20:30:12 (1776213012) [12264.386730] Lustre: lustre-MDD0000: changelog on [12264.390886] Lustre: Skipped 1 previous similar message [12274.965540] Lustre: lustre-MDD0001: changelog off [12274.978728] Lustre: Skipped 1 previous similar message [12280.707749] Lustre: DEBUG MARKER: == sanity test 160e: changelog negative testing (should return errors) ========================================================== 20:30:32 (1776213032) [12283.644298] Lustre: lustre-MDD0000: changelog on [12283.647276] Lustre: Skipped 1 previous similar message [12295.879158] Lustre: lustre-MDD0001: changelog off [12295.885749] Lustre: Skipped 1 previous similar message [12302.158884] Lustre: DEBUG MARKER: == sanity test 160f: changelog garbage collect (timestamped users) ========================================================== 20:30:53 (1776213053) [12317.026891] Lustre: DEBUG MARKER: 1776213068: creating first files [12345.585338] Lustre: *** cfs_fail_loc=1313, val=0*** [12345.591866] Lustre: 141783:0:(mdd_dir.c:895:mdd_changelog_store()) lustre-MDD0000: starting changelog garbage collection [12345.609832] Lustre: 165384:0:(mdd_trans.c:160:mdd_chlg_garbage_collect()) lustre-MDD0000: force deregister of changelog user cl7 idle for 34s with 4 unprocessed records [12372.005588] Lustre: lustre-MDD0001: changelog off [12372.008291] Lustre: Skipped 1 previous similar message [12377.705543] Lustre: DEBUG MARKER: == sanity test 160g: changelog garbage collect on idle records ========================================================== 20:32:08 (1776213128) [12380.963723] Lustre: lustre-MDD0000: changelog on [12380.968415] Lustre: Skipped 3 previous similar messages [12403.713682] Lustre: 98205:0:(mdd_dir.c:895:mdd_changelog_store()) lustre-MDD0000: starting changelog garbage collection [12403.719964] Lustre: 98205:0:(mdd_dir.c:895:mdd_changelog_store()) Skipped 1 previous similar message [12403.738876] Lustre: 167850:0:(mdd_trans.c:160:mdd_chlg_garbage_collect()) lustre-MDD0000: force deregister of changelog user cl9 idle for 17s with 4 unprocessed records [12403.769595] Lustre: 167850:0:(mdd_trans.c:160:mdd_chlg_garbage_collect()) Skipped 1 previous similar message [12430.277289] Lustre: DEBUG MARKER: == sanity test 160h: changelog gc thread stop upon umount, orphan records delete ========================================================== 20:33:01 (1776213181) [12471.139381] Lustre: *** cfs_fail_loc=1316, val=0*** [12471.155287] Lustre: 98205:0:(mdd_dir.c:895:mdd_changelog_store()) lustre-MDD0001: simulate starting changelog garbage collection [12471.187398] Lustre: 98205:0:(mdd_dir.c:895:mdd_changelog_store()) Skipped 1 previous similar message [12471.203095] Lustre: 170309:0:(mdd_trans.c:160:mdd_chlg_garbage_collect()) lustre-MDD0001: force deregister of changelog user cl11 idle for 30s with 3 unprocessed records [12471.237055] Lustre: 170309:0:(mdd_trans.c:160:mdd_chlg_garbage_collect()) Skipped 1 previous similar message [12475.855119] Lustre: Failing over lustre-MDT0001 [12477.287269] Lustre: Failing over lustre-MDT0000 [12477.600023] LustreError: 11-0: lustre-MDT0001-osp-MDT0000: operation mds_disconnect to node 0@lo failed: rc = -107 [12478.181038] Lustre: lustre-MDT0000: Not available for connect from 192.168.203.38@tcp (stopping) [12479.977100] 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 [12479.995845] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [12479.995845] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [12479.996359] Lustre: Skipped 1 previous similar message [12479.998056] Lustre: Skipped 2 previous similar messages [12480.046659] Lustre: Skipped 2 previous similar messages [12483.306508] Lustre: lustre-MDT0000: Not available for connect from 192.168.203.38@tcp (stopping) [12483.323404] Lustre: Skipped 1 previous similar message [12488.400039] Lustre: lustre-MDT0000: Not available for connect from 192.168.203.38@tcp (stopping) [12488.415391] Lustre: Skipped 4 previous similar messages [12492.019616] Lustre: server umount lustre-MDT0000 complete [12502.060615] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [12502.245362] LustreError: 166-1: MGC192.168.203.138@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [12502.279822] Lustre: Evicted from MGS (at 192.168.203.138@tcp) after server handle changed from 0x644751aac14de012 to 0x644751aac14df184 [12502.309697] Lustre: MGC192.168.203.138@tcp: Connection restored to (at 0@lo) [12502.326656] Lustre: Skipped 3 previous similar messages [12502.561628] LustreError: 137-5: lustre-MDT0001_UUID: 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. [12502.575685] LustreError: Skipped 12 previous similar messages [12502.682519] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [12502.725719] Lustre: lustre-MDD0000: changelog on [12502.730906] Lustre: Skipped 3 previous similar messages [12502.735333] Lustre: 171639:0:(mdd_device.c:618:mdd_changelog_llog_init()) lustre-MDD0000 : orphan changelog records found, starting from index 24 to index 25, being cleared now [12502.758451] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [12507.828351] Lustre: DEBUG MARKER: oleg338-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [12508.134809] LustreError: 137-5: lustre-MDT0001_UUID: 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. [12514.956787] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [12516.326076] LustreError: 137-5: lustre-MDT0001_UUID: 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. [12516.332383] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to (at 0@lo) [12516.352070] LustreError: Skipped 3 previous similar messages [12517.455872] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [12517.972923] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [12518.005138] Lustre: 172440:0:(mdd_device.c:618:mdd_changelog_llog_init()) lustre-MDD0001 : orphan changelog records found, starting from index 22 to index 23, being cleared now [12518.042918] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [12519.651267] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 2 clients reconnect [12522.978474] Lustre: lustre-MDT0001-lwp-OST0000: Connection restored to (at 0@lo) [12522.990443] Lustre: Skipped 1 previous similar message [12523.317966] Lustre: lustre-MDT0000: Recovery over after 0:09, of 2 clients 2 recovered and 0 were evicted. [12523.329919] Lustre: Skipped 1 previous similar message [12523.382777] Lustre: lustre-OST0000: deleting orphan objects from 0x280000400:34440 to 0x280000400:34465 [12523.394437] Lustre: lustre-OST0001: deleting orphan objects from 0x2c0000400:34249 to 0x2c0000400:34273 [12523.485967] Lustre: lustre-OST0001: deleting orphan objects from 0x0:40643 to 0x0:40673 [12523.489351] Lustre: lustre-OST0000: deleting orphan objects from 0x0:40858 to 0x0:40929 [12523.908717] Lustre: DEBUG MARKER: oleg338-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [12549.835067] Lustre: lustre-MDD0001: changelog off [12549.844366] Lustre: Skipped 3 previous similar messages [12555.334054] Lustre: DEBUG MARKER: == sanity test 160i: changelog user register/unregister race ========================================================== 20:35:06 (1776213306) [12566.457573] LustreError: 174462:0:(libcfs_fail.h:169:cfs_race()) cfs_race id 1315 sleeping [12570.277821] LustreError: 174596:0:(libcfs_fail.h:180:cfs_race()) cfs_fail_race id 1315 waking [12570.287420] LustreError: 174462:0:(libcfs_fail.h:178:cfs_race()) cfs_fail_race id 1315 awake: rc=1182 [12573.267641] LustreError: 174791:0:(libcfs_fail.h:180:cfs_race()) cfs_fail_race id 1315 waking [12574.282283] LustreError: 174848:0:(libcfs_fail.h:180:cfs_race()) cfs_fail_race id 1315 waking [12601.176746] Lustre: DEBUG MARKER: == sanity test 160j: client can be umounted while its chanangelog is being used ========================================================== 20:35:52 (1776213352) [12626.111452] Lustre: DEBUG MARKER: == sanity test 160k: Verify that changelog records are not lost ========================================================== 20:36:17 (1776213377) [12632.464576] Lustre: lustre-MDD0001: changelog on [12632.474687] Lustre: Skipped 8 previous similar messages [12634.845789] LustreError: 172449:0:(fail.c:138:__cfs_fail_timeout_set()) cfs_fail_timeout id 15d sleeping for 3000ms [12637.903166] LustreError: 172449:0:(fail.c:149:__cfs_fail_timeout_set()) cfs_fail_timeout id 15d awake [12658.305615] Lustre: DEBUG MARKER: == sanity test 160l: Verify that MTIME changelog records contain the parent FID ========================================================== 20:36:49 (1776213409) [12678.217264] Lustre: lustre-MDD0001: changelog off [12678.220445] Lustre: Skipped 9 previous similar messages [12684.085194] Lustre: DEBUG MARKER: == sanity test 160m: Changelog clear race ================ 20:37:15 (1776213435) [12698.907253] LustreError: 177129:0:(libcfs_fail.h:169:cfs_race()) cfs_race id 15f sleeping [12700.938213] LustreError: 171652:0:(libcfs_fail.h:180:cfs_race()) cfs_fail_race id 15f waking [12700.949947] LustreError: 177129:0:(libcfs_fail.h:178:cfs_race()) cfs_fail_race id 15f awake: rc=2965 [12719.313514] Lustre: DEBUG MARKER: == sanity test 160n: Changelog destroy race ============== 20:37:50 (1776213470) [14609.092543] LustreError: 181017:0:(libcfs_fail.h:169:cfs_race()) cfs_race id 16c sleeping [14611.127705] LustreError: 172449:0:(libcfs_fail.h:180:cfs_race()) cfs_fail_race id 16c waking [14611.147745] LustreError: 181017:0:(libcfs_fail.h:178:cfs_race()) cfs_fail_race id 16c awake: rc=2951 [14619.210667] Lustre: lustre-MDD0001: changelog off [14619.212889] Lustre: Skipped 3 previous similar messages [14625.611423] Lustre: DEBUG MARKER: == sanity test 160o: changelog user name and mask ======== 21:09:36 (1776215376) [14628.441909] Lustre: lustre-MDD0000: changelog on [14628.446951] Lustre: Skipped 6 previous similar messages [14632.290172] LustreError: 182677:0:(mdd_device.c:1704:mdd_changelog_name_check()) lustre-MDD0000: wrong char '#' in name 'Tt3_-#': rc = -22 [14633.499391] Lustre: 182725:0:(mdd_device.c:1721:mdd_changelog_name_check()) lustre-MDD0000: changelog name test_160o exists already: rc = -17 [14634.412639] LustreError: 182773:0:(mdd_device.c:1713:mdd_changelog_name_check()) lustre-MDD0000: name 'test_160toolongname' is over 16 symbols limit: rc = -36 [14657.279405] Lustre: lustre-MDD0000: changelog off [14657.285292] Lustre: Skipped 1 previous similar message [14666.333302] Lustre: DEBUG MARKER: == sanity test 160p: Changelog orphan cleanup with no users ========================================================== 21:10:17 (1776215417) [14670.265747] Lustre: lustre-MDD0000: changelog on [14670.274159] Lustre: Skipped 1 previous similar message [14677.382348] Lustre: Failing over lustre-MDT0000 [14677.608629] Lustre: server umount lustre-MDT0000 complete [14677.611326] Lustre: Skipped 1 previous similar message [14677.786108] LustreError: 137-5: lustre-MDT0000_UUID: not available for connect from 192.168.203.38@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [14677.801417] LustreError: Skipped 1 previous similar message [14679.020217] LustreError: 11-0: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [14679.033529] 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 [14679.038967] Lustre: Skipped 1 previous similar message [14682.829461] LustreError: 137-5: lustre-MDT0000_UUID: not available for connect from 192.168.203.38@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [14682.872623] LustreError: Skipped 4 previous similar messages [14687.200294] Lustre: 96563:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776215432/real 1776215432] req@000000004f5bda17 x1862492078899008/t0(0) o400->MGC192.168.203.138@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1776215439 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:5.0' [14687.272943] LustreError: 166-1: MGC192.168.203.138@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [14687.307056] LustreError: 137-5: lustre-MDT0000_UUID: 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. [14687.336556] LustreError: Skipped 8 previous similar messages [14692.077165] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [14693.355816] Lustre: Evicted from MGS (at 192.168.203.138@tcp) after server handle changed from 0x644751aac14df184 to 0x644751aac19167e9 [14693.374511] Lustre: MGC192.168.203.138@tcp: Connection restored to (at 0@lo) [14693.377141] Lustre: Skipped 3 previous similar messages [14693.926161] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [14694.595077] Lustre: 185011:0:(mdd_device.c:618:mdd_changelog_llog_init()) lustre-MDD0000 : orphan changelog records found, starting from index 90148 to index 18446744073709551615, being cleared now [14694.664949] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [14695.113942] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [14699.023856] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to (at 0@lo) [14699.097593] Lustre: lustre-MDT0000: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [14699.168039] Lustre: lustre-OST0001: deleting orphan objects from 0x0:40675 to 0x0:40705 [14699.168232] Lustre: lustre-OST0000: deleting orphan objects from 0x0:40931 to 0x0:40961 [14702.672373] Lustre: DEBUG MARKER: oleg338-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [14721.160663] Lustre: DEBUG MARKER: == sanity test 160q: changelog effective mask is DEFMASK if not set ========================================================== 21:11:12 (1776215472) [14726.366164] Lustre: lustre-MDD0000: changelog off [14726.370806] Lustre: Skipped 2 previous similar messages [14733.785504] Lustre: DEBUG MARKER: == sanity test 160s: changelog garbage collect on idle records nbd-3.19-1.fc29.src.rpm rpmbuild time ========================================================== 21:11:25 (1776215485) [14737.927956] Lustre: lustre-MDD0000: changelog on [14737.930975] Lustre: Skipped 2 previous similar messages [14751.598400] Lustre: 177129:0:(mdd_dir.c:895:mdd_changelog_store()) lustre-MDD0000: starting changelog garbage collection [14751.621773] Lustre: 177129:0:(mdd_dir.c:895:mdd_changelog_store()) Skipped 1 previous similar message [14751.653258] Lustre: 187062:0:(mdd_trans.c:160:mdd_chlg_garbage_collect()) lustre-MDD0000: force deregister of changelog user cl2 idle for 864014s with 500000004 unprocessed records [14772.375826] Lustre: DEBUG MARKER: == sanity test 161a: link ea sanity ====================== 21:12:03 (1776215523) [14818.877301] Lustre: DEBUG MARKER: == sanity test 161b: link ea sanity under remote directory ========================================================== 21:12:50 (1776215570) [14863.634354] Lustre: DEBUG MARKER: == sanity test 161c: check CL_RENME[UNLINK] changelog record flags ========================================================== 21:13:34 (1776215614) [14866.667447] Lustre: lustre-MDD0000: changelog on [14866.673569] Lustre: Skipped 1 previous similar message [14879.349420] Lustre: lustre-MDD0001: changelog off [14879.353699] Lustre: Skipped 2 previous similar messages [14886.256783] Lustre: DEBUG MARKER: == sanity test 161d: create with concurrent .lustre/fid access ========================================================== 21:13:56 (1776215636) [14914.123030] Lustre: DEBUG MARKER: == sanity test 162a: path lookup sanity ================== 21:14:25 (1776215665) [14923.052887] Lustre: DEBUG MARKER: == sanity test 162b: striped directory path lookup sanity ========================================================== 21:14:34 (1776215674) [14932.681594] Lustre: DEBUG MARKER: == sanity test 162c: fid2path works with paths 100 or more directories deep ========================================================== 21:14:44 (1776215684) [15018.797913] Lustre: DEBUG MARKER: == sanity test 165a: ofd access log discovery ============ 21:16:09 (1776215769) [15029.659522] Lustre: Failing over lustre-OST0000 [15029.829084] Lustre: server umount lustre-OST0000 complete [15031.780901] 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 [15031.797209] Lustre: Skipped 3 previous similar messages [15031.804214] LustreError: 137-5: lustre-OST0000_UUID: 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. [15031.824056] LustreError: Skipped 10 previous similar messages [15049.414289] LustreError: 137-5: lustre-OST0000_UUID: not available for connect from 192.168.203.38@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [15049.437127] LustreError: Skipped 9 previous similar messages [15053.052606] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [15053.208288] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [15053.216778] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [15054.536972] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [15055.093730] Lustre: lustre-OST0000: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [15055.101195] Lustre: lustre-OST0000-osc-MDT0001: Connection restored to 192.168.203.138@tcp (at 0@lo) [15055.126455] Lustre: Skipped 3 previous similar messages [15055.132141] Lustre: lustre-OST0000: deleting orphan objects from 0x0:40966 to 0x0:40993 [15055.133690] Lustre: lustre-OST0000: deleting orphan objects from 0x280000400:34470 to 0x280000400:34497 [15059.854473] Lustre: DEBUG MARKER: oleg338-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [15064.199909] Lustre: DEBUG MARKER: == sanity test 165b: ofd access log entries are produced and consumed ========================================================== 21:16:55 (1776215815) [15096.423813] Lustre: Failing over lustre-OST0000 [15098.504091] Lustre: server umount lustre-OST0000 complete [15099.372559] 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 [15099.392644] Lustre: Skipped 1 previous similar message [15099.398857] LustreError: 137-5: lustre-OST0000_UUID: 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. [15099.435210] LustreError: Skipped 3 previous similar messages [15108.024059] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [15108.341737] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [15108.359831] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [15109.790218] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [15110.282511] Lustre: lustre-OST0000: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [15110.285475] Lustre: lustre-OST0000-osc-MDT0001: Connection restored to 192.168.203.138@tcp (at 0@lo) [15110.309132] Lustre: lustre-OST0000: deleting orphan objects from 0x280000400:34470 to 0x280000400:34529 [15110.313627] Lustre: Skipped 1 previous similar message [15110.323972] Lustre: lustre-OST0000: deleting orphan objects from 0x0:40995 to 0x0:41025 [15115.245835] Lustre: DEBUG MARKER: oleg338-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [15120.709571] Lustre: DEBUG MARKER: == sanity test 165c: full ofd access logs do not block IOs ========================================================== 21:17:51 (1776215871) [15150.238502] Lustre: Failing over lustre-OST0000 [15150.495349] Lustre: server umount lustre-OST0000 complete [15151.585669] LustreError: 11-0: lustre-OST0000-osc-MDT0001: operation ost_statfs to node 0@lo failed: rc = -107 [15151.596220] 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 [15151.619903] Lustre: Skipped 1 previous similar message [15160.380882] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [15160.592479] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [15160.604238] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [15162.070286] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [15162.228744] Lustre: lustre-OST0000: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [15162.229261] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 192.168.203.138@tcp (at 0@lo) [15162.249827] Lustre: Skipped 1 previous similar message [15162.259206] Lustre: lustre-OST0000: deleting orphan objects from 0x0:41093 to 0x0:41121 [15162.283364] Lustre: lustre-OST0000: deleting orphan objects from 0x280000400:34591 to 0x280000400:34625 [15164.816740] Lustre: DEBUG MARKER: oleg338-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [15168.653867] Lustre: DEBUG MARKER: == sanity test 165d: ofd_access_log mask works =========== 21:18:40 (1776215920) [15210.834568] Lustre: Failing over lustre-OST0000 [15210.872221] Lustre: server umount lustre-OST0000 complete [15212.004783] 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 [15212.016316] LustreError: 137-5: lustre-OST0000_UUID: 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. [15212.032692] Lustre: Skipped 2 previous similar messages [15212.050262] LustreError: Skipped 13 previous similar messages [15220.079557] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [15220.306874] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [15220.319961] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [15221.838908] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [15221.929083] Lustre: lustre-OST0000: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [15221.934075] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 192.168.203.138@tcp (at 0@lo) [15221.946650] Lustre: Skipped 1 previous similar message [15221.952192] Lustre: lustre-OST0000: deleting orphan objects from 0x0:41123 to 0x0:41153 [15221.961951] Lustre: lustre-OST0000: deleting orphan objects from 0x280000400:34591 to 0x280000400:34657 [15225.239740] Lustre: DEBUG MARKER: oleg338-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [15229.258812] Lustre: DEBUG MARKER: == sanity test 165e: ofd_access_log MDT index filter works ========================================================== 21:19:40 (1776215980) [15255.907354] Lustre: Failing over lustre-OST0000 [15255.958184] Lustre: server umount lustre-OST0000 complete [15256.037055] 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 [15267.388945] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [15267.786555] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [15267.812304] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [15269.084392] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [15269.282229] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 192.168.203.138@tcp (at 0@lo) [15269.292470] Lustre: lustre-OST0000: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [15269.292607] Lustre: lustre-OST0000: deleting orphan objects from 0x0:41155 to 0x0:41185 [15269.294340] Lustre: Skipped 1 previous similar message [15269.382203] Lustre: lustre-OST0000: deleting orphan objects from 0x280000400:34659 to 0x280000400:34689 [15273.608071] Lustre: DEBUG MARKER: oleg338-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [15278.761914] Lustre: DEBUG MARKER: == sanity test 165f: ofd_access_log_reader --exit-on-close works ========================================================== 21:20:29 (1776216029) [15287.078927] Lustre: Failing over lustre-OST0000 [15287.196759] Lustre: server umount lustre-OST0000 complete [15288.289878] 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 [15288.312544] Lustre: Skipped 1 previous similar message [15308.293430] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [15308.606913] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [15308.632238] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [15310.479281] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [15314.692578] Lustre: DEBUG MARKER: oleg338-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [15318.620915] Lustre: DEBUG MARKER: == sanity test 169: parallel read and truncate should not deadlock ========================================================== 21:21:09 (1776216069) [15320.186902] Lustre: DEBUG MARKER: creating a 10 Mb file [15320.332488] Lustre: lustre-OST0000: Recovery over after 0:10, of 3 clients 3 recovered and 0 were evicted. [15320.336723] Lustre: lustre-OST0000: deleting orphan objects from 0x280000400:34659 to 0x280000400:34721 [15320.342070] Lustre: lustre-OST0000: deleting orphan objects from 0x0:41187 to 0x0:41217 [15322.529663] Lustre: DEBUG MARKER: starting reads [15324.506164] Lustre: DEBUG MARKER: truncating the file [15326.495991] Lustre: DEBUG MARKER: killing dd [15328.208131] Lustre: DEBUG MARKER: removing the temporary file [15335.662896] Lustre: DEBUG MARKER: == sanity test 170: test lctl df to handle corrupted log =============================================================================== 21:21:26 (1776216086) [15343.808396] Lustre: DEBUG MARKER: == sanity test 171: test libcfs_debug_dumplog_thread stuck in do_exit() ================================================================ 21:21:35 (1776216095) [15355.140304] Lustre: DEBUG MARKER: == sanity test 180a: test obdecho on osc ================= 21:21:46 (1776216106) [15356.844458] Lustre: DEBUG MARKER: SKIP: sanity test_180a obdecho on osc is no longer supported [15358.860790] Lustre: DEBUG MARKER: == sanity test 180b: test obdecho directly on obdfilter == 21:21:50 (1776216110) [15363.458485] Lustre: DEBUG MARKER: oleg338-server.virtnet: executing load_module obdecho/obdecho [15385.583335] Lustre: DEBUG MARKER: == sanity test 180c: test huge bulk I/O size on obdfilter, don't LASSERT ========================================================== 21:22:16 (1776216136) [15392.128383] Lustre: DEBUG MARKER: oleg338-server.virtnet: executing load_module obdecho/obdecho [15392.443471] Lustre: Echo OBD driver; http://www.lustre.org/ [15413.395344] Lustre: DEBUG MARKER: == sanity test 181: Test open-unlinked dir ================================================================================== 21:22:44 (1776216164) [15530.658198] Lustre: DEBUG MARKER: == sanity test 182: Test parallel modify metadata operations ========================================================================== 21:24:41 (1776216281) [15655.090064] Lustre: DEBUG MARKER: == sanity test 183: No crash or request leak in case of strange dispositions ================================================================== 21:26:46 (1776216406) [15656.653983] Lustre: *** cfs_fail_loc=148, val=0*** [15665.429352] Lustre: DEBUG MARKER: == sanity test 184a: Basic layout swap =================== 21:26:56 (1776216416) [15678.596538] Lustre: DEBUG MARKER: == sanity test 184b: Forbidden layout swap (will generate errors) ========================================================== 21:27:09 (1776216429) [15689.400570] Lustre: DEBUG MARKER: == sanity test 184c: Concurrent write and layout swap ==== 21:27:20 (1776216440) [15729.225112] Lustre: DEBUG MARKER: == sanity test 184d: allow stripeless layouts swap ======= 21:28:00 (1776216480) [15757.396359] Lustre: DEBUG MARKER: == sanity test 184e: Recreate layout after stripeless layout swaps ========================================================== 21:28:27 (1776216507) [15781.920650] Lustre: DEBUG MARKER: == sanity test 184f: IOC_MDC_GETFILEINFO for files with long names but no striping ========================================================== 21:28:53 (1776216533) [15789.628354] Lustre: DEBUG MARKER: == sanity test 185: Volatile file support ================ 21:29:01 (1776216541) [15798.756799] Lustre: DEBUG MARKER: == sanity test 185a: Volatile file creation in .lustre/fid/ ========================================================== 21:29:09 (1776216549) [15813.963805] Lustre: DEBUG MARKER: == sanity test 187a: Test data version change ============ 21:29:24 (1776216564) [15823.297283] Lustre: DEBUG MARKER: == sanity test 187b: Test data version change on volatile file ========================================================== 21:29:34 (1776216574) [15835.817158] Lustre: DEBUG MARKER: == sanity test complete, duration 15574 sec ============== 21:29:46 (1776216586) [15950.816176] 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 [15950.817678] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [15950.831869] Lustre: Skipped 2 previous similar messages [15950.847180] Lustre: Skipped 8 previous similar messages [15955.938684] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [15955.941453] Lustre: Skipped 3 previous similar messages [15956.423956] Lustre: server umount lustre-MDT0000 complete [15961.056389] LustreError: 137-5: lustre-MDT0000_UUID: 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. [15961.112896] LustreError: Skipped 25 previous similar messages [15966.858713] LustreError: 101659:0:(ldlm_lockd.c:2526:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1776216719 with bad export cookie 7225833920973072361 [15966.860131] LustreError: 166-1: MGC192.168.203.138@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [15966.888739] LustreError: 101659:0:(ldlm_lockd.c:2526:ldlm_cancel_handler()) Skipped 2 previous similar messages [15967.337819] Lustre: server umount lustre-MDT0001 complete [15978.405457] Lustre: 96566:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776216724/real 1776216724] req@0000000027537b41 x1862492080711744/t0(0) o400->lustre-MDT0001-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1776216731 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:10.0' [15978.458075] Lustre: lustre-MDT0001-lwp-OST0000: Connection to lustre-MDT0001 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [15978.483614] Lustre: Skipped 2 previous similar messages [15979.423219] Lustre: 96563:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776216725/real 1776216725] req@000000000fc2c9fb x1862492080711936/t0(0) o400->lustre-MDT0001-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1776216732 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:2.0' [15979.444980] Lustre: 96563:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 1 previous similar message [15979.626690] Lustre: server umount lustre-OST0000 complete [15983.583239] Lustre: 96566:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776216729/real 1776216729] req@0000000096d3b671 x1862492080712000/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1776216736 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:10.0' [15983.639719] Lustre: 96566:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 1 previous similar message [15985.661151] Lustre: 96565:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776216731/real 1776216731] req@00000000137d3d54 x1862492080712256/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1776216738 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:10.0' [15985.741109] Lustre: 96565:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 1 previous similar message [16010.980687] Lustre: DEBUG MARKER: oleg338-server.virtnet: executing unload_modules_local [16013.503540] Key type lgssc unregistered [16013.776296] LNet: 212383:0:(lib-ptl.c:992:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [16013.801144] LNet: Removed LNI 192.168.203.138@tcp [16014.787794] Key type .llcrypt unregistered [16014.791443] Key type ._llcrypt unregistered