[ 0.000000] Linux version 4.18.0rh8.10-debug (green@maintenance) (gcc version 8.5.0 20210514 (Red Hat 8.5.0-26) (GCC)) #2 SMP Mon Jul 14 01:24:22 EDT 2025 [ 0.000000] Command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers' [ 0.000000] x86/fpu: xstate_offset[2]: 576, xstate_sizes[2]: 256 [ 0.000000] x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'standard' format. [ 0.000000] signal: max sigframe size: 1776 [ 0.000000] BIOS-provided physical RAM map: [ 0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable [ 0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000000100000-0x00000000bffcdfff] usable [ 0.000000] BIOS-e820: [mem 0x00000000bffce000-0x00000000bfffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000100000000-0x0000000146dfffff] usable [ 0.000000] NX (Execute Disable) protection: active [ 0.000000] SMBIOS 2.8 present. [ 0.000000] DMI: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.17.0-10.fc44 06/10/2025 [ 0.000000] Hypervisor detected: KVM [ 0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00 [ 0.000000] kvm-clock: using sched offset of 1218971237 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2399.998 MHz processor [ 0.000000] last_pfn = 0x146e00 max_arch_pfn = 0x400000000 [ 0.000000] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT [ 0.000000] last_pfn = 0xbffce max_arch_pfn = 0x400000000 [ 0.000000] found SMP MP-table at [mem 0x000f54b0-0x000f54bf] [ 0.000000] RAMDISK: [mem 0xbcc54000-0xbffbffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F52D0 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE247C 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE2318 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 0022D8 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE238C 000090 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE241C 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE2454 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe2318-0xbffe238b] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe2317] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe238c-0xbffe241b] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe241c-0xbffe2453] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe2454-0xbffe247b] [ 0.000000] No NUMA configuration found [ 0.000000] Faking a node at [mem 0x0000000000000000-0x0000000146dfffff] [ 0.000000] NODE_DATA(0) allocated [mem 0x1465a3000-0x1465cdfff] [ 0.000000] Reserving 256MB of memory at 2752MB for crashkernel (System RAM: 4205MB) [ 0.000000] Zone ranges: [ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.000000] DMA32 [mem 0x0000000001000000-0x00000000ffffffff] [ 0.000000] Normal [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Device empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff] [ 0.000000] node 0: [mem 0x0000000000100000-0x00000000bffcdfff] [ 0.000000] node 0: [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Zeroed struct page in unavailable ranges: 4756 pages [ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x0000000146dfffff] [ 0.000000] ACPI: PM-Timer IO Port: 0x608 [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) [ 0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) [ 0.000000] Using ACPI (MADT) for SMP configuration information [ 0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000] TSC deadline timer available [ 0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs [ 0.000000] kvm-guest: KVM setup pv remote TLB flush [ 0.000000] kvm-guest: setup PV sched yield [ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff] [ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff] [ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff] [ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff] [ 0.000000] PM: Registered nosave memory: [mem 0xbffce000-0xbfffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xc0000000-0xfeffbfff] [ 0.000000] PM: Registered nosave memory: [mem 0xfeffc000-0xfeffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xff000000-0xfffbffff] [ 0.000000] PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff] [ 0.000000] [mem 0xc0000000-0xfeffbfff] available for PCI devices [ 0.000000] Booting paravirtualized kernel on KVM [ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns [ 0.000000] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1 [ 0.000000] percpu: Embedded 63 pages/cpu s221184 r8192 d28672 u524288 [ 0.000000] kvm-guest: PV spinlocks enabled [ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1059606 [ 0.000000] Policy zone: Normal [ 0.000000] Kernel command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] Specific versions of hardware are certified with Red Hat Enterprise Linux 8. Please see the list of hardware certified with Red Hat Enterprise Linux 8 at https://catalog.redhat.com. [ 0.000000] audit: disabled (until reboot) [ 0.000000] software IO TLB: area num 4. [ 0.000000] Memory: 2829652K/4306352K available (18435K kernel code, 11221K rwdata, 7248K rodata, 2908K init, 18040K bss, 524580K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] ftrace: allocating 41240 entries in 162 pages [ 0.000000] ftrace: allocated 162 pages with 3 groups [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] rcu: RCU event tracing is enabled. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ 0.000000] rcu: RCU callback double-/use-after-free debug enabled. [ 0.000000] Rude variant of Tasks RCU enabled. [ 0.000000] Tracing variant of Tasks RCU enabled. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 0.000000] NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16 [ 0.000000] random: get_random_bytes called from start_kernel+0x622/0x9a8 with crng_init=0 [ 0.001000] Console: colour *CGA 80x25 [ 0.001000] printk: console [ttyS1] enabled [ 0.001000] ACPI: Core revision 20220331 [ 0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.001011] APIC: Switch to symmetric I/O mode setup [ 0.002408] x2apic enabled [ 0.003010] Switched APIC routing to physical x2apic. [ 0.004017] kvm-guest: setup PV IPIs [ 0.008472] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.009000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.009026] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.011009] pid_max: default: 32768 minimum: 301 [ 0.012187] LSM: Security Framework initializing [ 0.013074] Yama: becoming mindful. [ 0.014040] SELinux: Initializing. [ 0.015109] *** VALIDATE selinux *** [ 0.025557] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.030275] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.031152] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.032116] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.033125] *** VALIDATE tmpfs *** [ 0.034467] *** VALIDATE proc *** [ 0.035290] *** VALIDATE cgroup *** [ 0.036010] *** VALIDATE cgroup2 *** [ 0.037292] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.038159] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.039007] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.040040] Spectre V2 : User space: Vulnerable [ 0.041010] Speculative Store Bypass: Vulnerable [ 0.044417] debug: unmapping init [mem 0xffffffffb7459000-0xffffffffb7460fff] [ 0.047266] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.048746] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.049023] ... version: 2 [ 0.050010] ... bit width: 48 [ 0.051014] ... generic registers: 4 [ 0.052010] ... value mask: 0000ffffffffffff [ 0.053010] ... max period: 00007fffffffffff [ 0.054012] ... fixed-purpose events: 3 [ 0.055013] ... event mask: 000000070000000f [ 0.056415] rcu: Hierarchical SRCU implementation. [ 0.059429] smp: Bringing up secondary CPUs ... [ 0.061266] x86: Booting SMP configuration: [ 0.062896] .... node #0, CPUs: #1 #2 #3 [ 0.076284] smp: Brought up 1 node, 4 CPUs [ 0.078024] smpboot: Max logical packages: 1 [ 0.079024] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.117000] node 0 deferred pages initialised in 32ms [ 0.124282] devtmpfs: initialized [ 0.125386] x86/mm: Memory block size: 128MB [ 0.128664] gcov: version magic: 0x41383552 [ 0.131025] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.132117] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.133576] pinctrl core: initialized pinctrl subsystem [ 0.134261] [ 0.135021] ************************************************************* [ 0.136034] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.137026] ** ** [ 0.138023] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.139022] ** ** [ 0.140023] ** This means that this kernel is built to expose internal ** [ 0.141020] ** IOMMU data structures, which may compromise security on ** [ 0.142018] ** your system. ** [ 0.143022] ** ** [ 0.144020] ** If you see this message and you are not debugging the ** [ 0.145026] ** kernel, report this immediately to your vendor! ** [ 0.146020] ** ** [ 0.147024] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.148028] ************************************************************* [ 0.151151] NET: Registered protocol family 16 [ 0.153457] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.154077] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.155319] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.159640] cpuidle: using governor menu [ 0.172076] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.181164] PCI: Using configuration type 1 for base access [ 0.185833] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.200063] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.204025] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.213171] cryptd: max_cpu_qlen set to 1000 [ 0.215239] ACPI: Added _OSI(Module Device) [ 0.216015] ACPI: Added _OSI(Processor Device) [ 0.217030] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.218419] ACPI: Added _OSI(Processor Aggregator Device) [ 0.230621] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.246739] ACPI: Interpreter enabled [ 0.249679] ACPI: PM: (supports S0 S3 S4 S5) [ 0.259335] ACPI: Using IOAPIC for interrupt routing [ 0.265694] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.276326] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.305000] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.307051] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.308026] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.313086] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.329341] acpiphp: Slot [2] registered [ 0.334225] acpiphp: Slot [5] registered [ 0.339143] acpiphp: Slot [6] registered [ 0.344207] acpiphp: Slot [7] registered [ 0.348193] acpiphp: Slot [8] registered [ 0.349000] acpiphp: Slot [9] registered [ 0.350191] acpiphp: Slot [10] registered [ 0.355178] acpiphp: Slot [3] registered [ 0.359723] acpiphp: Slot [4] registered [ 0.364406] acpiphp: Slot [11] registered [ 0.369174] acpiphp: Slot [12] registered [ 0.374149] acpiphp: Slot [13] registered [ 0.378149] acpiphp: Slot [14] registered [ 0.381270] acpiphp: Slot [15] registered [ 0.385126] acpiphp: Slot [16] registered [ 0.390174] acpiphp: Slot [17] registered [ 0.393968] acpiphp: Slot [18] registered [ 0.397085] acpiphp: Slot [19] registered [ 0.399000] acpiphp: Slot [20] registered [ 0.404168] acpiphp: Slot [21] registered [ 0.407718] acpiphp: Slot [22] registered [ 0.415123] acpiphp: Slot [23] registered [ 0.422147] acpiphp: Slot [24] registered [ 0.427149] acpiphp: Slot [25] registered [ 0.434141] acpiphp: Slot [26] registered [ 0.435141] acpiphp: Slot [27] registered [ 0.440215] acpiphp: Slot [28] registered [ 0.443972] acpiphp: Slot [29] registered [ 0.450156] acpiphp: Slot [30] registered [ 0.455384] acpiphp: Slot [31] registered [ 0.458076] PCI host bridge to bus 0000:00 [ 0.459042] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.466027] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.473026] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.476036] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.481026] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.484031] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.487179] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.494130] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.501079] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.523570] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.533775] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.538019] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.544020] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.547020] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.551601] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.558900] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.568058] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.572110] pci 0000:00:01.3: quirk_piix4_acpi+0x0/0x1e0 took 12695 usecs [ 0.581451] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.591018] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.620019] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.635028] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.647651] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.663022] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.678019] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.730018] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.756278] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.765022] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.779017] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.814018] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.833621] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.847018] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.862018] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.904020] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.924842] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.929019] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.938017] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.962019] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.976185] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.986026] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.993024] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 1.011023] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 1.022000] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 1.037027] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 1.047023] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 1.087019] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 1.119172] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 1.121404] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 1.127211] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 1.132292] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 1.135877] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 1.144098] iommu: Default domain type: Passthrough [ 1.146801] SCSI subsystem initialized [ 1.149244] ACPI: bus type USB registered [ 1.151176] usbcore: registered new interface driver usbfs [ 1.154108] usbcore: registered new interface driver hub [ 1.157124] usbcore: registered new device driver usb [ 1.161367] pps_core: LinuxPPS API ver. 1 registered [ 1.164015] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 1.171079] PTP clock support registered [ 1.175365] EDAC MC: Ver: 3.0.0 [ 1.176169] PCI: Using ACPI for IRQ routing [ 1.180487] NetLabel: Initializing [ 1.182015] NetLabel: domain hash size = 128 [ 1.184013] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 1.188091] NetLabel: unlabeled traffic allowed by default [ 1.194084] vgaarb: loaded [ 1.199133] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 1.204013] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 1.214213] clocksource: Switched to clocksource kvm-clock [ 1.453396] VFS: Disk quotas dquot_6.6.0 [ 1.457333] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 1.463123] *** VALIDATE ramfs *** [ 1.465371] *** VALIDATE hugetlbfs *** [ 1.468918] pnp: PnP ACPI init [ 1.473700] pnp: PnP ACPI: found 6 devices [ 1.524263] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 1.533855] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 1.540289] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 1.545354] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 1.549152] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 1.555562] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 1.564028] NET: Registered protocol family 2 [ 1.569255] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 1.588060] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 1.601130] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 1.621176] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 1.632227] TCP: Hash tables configured (established 65536 bind 65536) [ 1.640383] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 1.651267] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 1.656199] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 1.660962] NET: Registered protocol family 1 [ 1.665186] RPC: Registered named UNIX socket transport module. [ 1.669921] RPC: Registered udp transport module. [ 1.673066] RPC: Registered tcp transport module. [ 1.676510] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 1.683546] NET: Registered protocol family 44 [ 1.686091] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 1.689234] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 1.692412] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 1.696040] PCI: CLS 0 bytes, default 64 [ 1.698157] Unpacking initramfs... [ 3.594202] hrtimer: interrupt took 4200347 ns [ 5.655218] debug: unmapping init [mem 0xffff98a97cc54000-0xffff98a97ffbffff] [ 5.666977] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 5.675637] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 5.681954] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 9.468942] Initialise system trusted keyrings [ 9.473414] Key type blacklist registered [ 9.478046] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 9.505214] zbud: loaded [ 9.522712] *** VALIDATE nfs *** [ 9.524203] *** VALIDATE nfs4 *** [ 9.534814] pstore: using deflate compression [ 9.570756] Platform Keyring initialized [ 10.147508] NET: Registered protocol family 38 [ 10.152776] Key type asymmetric registered [ 10.161624] Asymmetric key parser 'x509' registered [ 10.179211] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 10.190787] io scheduler mq-deadline registered [ 10.197897] io scheduler kyber registered [ 10.206936] io scheduler bfq registered [ 10.214515] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 10.221123] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 10.234159] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 10.260413] ACPI: Power Button [PWRF] [ 10.292153] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 10.329456] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 10.377632] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 10.396752] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 10.427797] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 10.504754] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 10.575181] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 10.626433] Non-volatile memory driver v1.3 [ 10.648364] Linux agpgart interface v0.103 [ 10.863214] virtio_blk virtio1: [vda] 145872 512-byte logical blocks (74.7 MB/71.2 MiB) [ 10.873480] vda: detected capacity change from 0 to 74686464 [ 10.972430] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 10.985236] vdb: detected capacity change from 0 to 1073741824 [ 11.106794] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 11.118066] vdc: detected capacity change from 0 to 2621440000 [ 11.198787] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 11.209223] vdd: detected capacity change from 0 to 2621440000 [ 11.282326] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 11.290037] vde: detected capacity change from 0 to 4294967296 [ 11.405161] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 11.430784] vdf: detected capacity change from 0 to 4294967296 [ 11.485178] libphy: Fixed MDIO Bus: probed [ 11.531617] usbcore: registered new interface driver usbserial_generic [ 11.547038] usbserial: USB Serial support registered for generic [ 11.563745] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 11.590961] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 11.595536] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 11.610216] mousedev: PS/2 mouse device common for all mice [ 11.622720] rtc_cmos 00:05: RTC can wake from S4 [ 11.641162] rtc_cmos 00:05: registered as rtc0 [ 11.648127] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 11.651368] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 11.655828] intel_pstate: CPU model not supported [ 11.671748] hid: raw HID events driver (C) Jiri Kosina [ 11.692367] usbcore: registered new interface driver usbhid [ 11.695526] usbhid: USB HID core driver [ 11.698519] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 11.705533] drop_monitor: Initializing network drop monitor service [ 11.705708] Initializing XFRM netlink socket [ 11.712868] NET: Registered protocol family 10 [ 11.725965] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 11.783405] Segment Routing with IPv6 [ 11.803372] NET: Registered protocol family 17 [ 11.814571] mpls_gso: MPLS GSO support [ 11.860671] RAS: Correctable Errors collector initialized. [ 11.871629] AVX version of gcm_enc/dec engaged. [ 11.877948] AES CTR mode by8 optimization enabled [ 12.263109] sched_clock: Marking stable (12263082836, 0)->(15014378506, -2751295670) [ 12.287282] registered taskstats version 1 [ 12.295666] Loading compiled-in X.509 certificates [ 12.303771] zswap: loaded using pool lzo/zbud [ 12.485425] Key type big_key registered [ 12.551419] Key type encrypted registered [ 12.563223] ima: No TPM chip found, activating TPM-bypass! [ 12.574710] ima: Allocated hash algorithm: sha1 [ 12.587072] ima: No architecture policies found [ 12.600375] evm: Initialising EVM extended attributes: [ 12.601839] evm: security.selinux [ 12.602846] evm: security.ima [ 12.610995] evm: security.capability [ 12.614081] evm: HMAC attrs: 0x1 [ 12.626470] rtc_cmos 00:05: setting system clock to 2026-09-08 12:04:35 UTC (1788869075) [ 12.674900] debug: unmapping init [mem 0xffffffffb8403000-0xffffffffb85fffff] [ 12.688864] debug: unmapping init [mem 0xffffffffb7182000-0xffffffffb7458fff] [ 12.697123] Write protecting the kernel read-only data: 28672k [ 12.712577] debug: unmapping init [mem 0xffffffffb5803000-0xffffffffb59fffff] [ 12.717255] debug: unmapping init [mem 0xffffffffb6114000-0xffffffffb61fffff] [ 12.842211] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 12.868516] systemd[1]: Detected virtualization kvm. [ 12.870207] systemd[1]: Detected architecture x86-64. [ 12.873665] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 12.935257] systemd[1]: No hostname configured. [ 12.937766] systemd[1]: Set hostname to . [ 12.941562] random: systemd: uninitialized urandom read (16 bytes read) [ 12.947475] systemd[1]: Initializing machine ID from random generator. [ 13.114987] random: ln: uninitialized urandom read (6 bytes read) [ 13.431532] random: systemd: uninitialized urandom read (16 bytes read) [ 13.440357] systemd[1]: Reached target Timers. [ OK ] Reached target Timers. [ 13.466938] systemd[1]: Listening on Journal Socket. [ OK ] Listening on Journal Socket. [ 13.524607] systemd[1]: Starting Setup Virtual Console... Starting Setup Virtual Console... [ OK ] Reached target Local File Systems. Starting Create Volatile Files and Directories... [ OK ] Reached target Initrd Root Device. Starting Apply Kernel Variables... [ OK ] Reached target Swap. [ OK ] Listening on udev Kernel Socket. [ OK ] Listening on udev Control Socket. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Paths. [ OK ] Reached target Slices. [ OK ] Listening on Journal Socket (/dev/log). [ OK ] Reached target Sockets. Starting Journal Service... Starting Create list of required st…ce nodes for the current kernel... [ OK ] Started Memstrack Anylazing Service. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Started Setup Virtual Console. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Apply Kernel Variables. [ 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... [ 16.118671] device-mapper: uevent: version 1.0.3 [ 16.127713] device-mapper: ioctl: 4.46.0-ioctl (2022-02-22) initialised: dm-devel@redhat.com [ OK ] Started dracut pre-udev hook. Starting udev Kernel Device Manager... [ OK ] Started udev Kernel Device Manager. Starting dracut pre-trigger hook... [ OK ] Started dracut pre-trigger hook. Starting udev Coldplug all Devices... Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting dracut initqueue hook... [ 19.285273] virtio_net virtio0 ens2: renamed from eth0 [ 19.514969] random: fast init done [ 20.569229] scsi host0: ata_piix [ 20.715719] scsi host1: ata_piix [ 20.734263] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 20.750175] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 26.166562] random: crng init done [ 26.167941] random: 7 urandom warning(s) missed due to ratelimiting [ 30.087090] dracut-initqueue[586]: RTNETLINK answers: File exists Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Mounting /sysroot... [ 33.123989] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped target Timers. [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target System Initialization. [ OK ] Stopped target Swap. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. Stopping udev Kernel Device Manager... [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. [ OK ] Stopped target Slices. [ OK ] Stopped target Paths. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped target Sockets. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Closed udev Control Socket. [ OK ] Closed udev Kernel Socket. Starting Cleanup udevd DB... [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 37.295712] printk: systemd: 26 output lines suppressed due to ratelimiting [ 39.561617] SELinux: Disabled at runtime. [ 39.825172] 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) [ 39.889078] systemd[1]: Detected virtualization kvm. [ 39.892870] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 43.010425] systemd[1]: initrd-switch-root.service: Succeeded. [ 43.025671] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 43.082997] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 43.123566] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 43.143275] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 43.193133] systemd[1]: Starting Journal Service... Starting Journal Service... [ 43.233906] systemd[1]: Started Dispatch Password Requests to Console Directory Watch. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [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 Forward Password Requests to Wall Directory Watch. [ OK ] Reached target Paths. [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Listening on Process Core Dump Socket. [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Created slice User and Session Slice. [ OK ] Listening on udev Control Socket. Starting Apply Kernel Variables... Activating swap /dev/disk/by-label/SWAP... Starting Remount Root and Kernel File Systems... Mounting POSIX Message Queue File System... Mounting Kernel Debug File System... [ OK ] Listening on udev Kernel Socket. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Created slice system-getty.slice. [ OK ] Reached target Local Encrypted Volumes. Mounting Huge Pages File System... [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Reached target RPC Port Mapper. [ OK ] Reached target Slices. [ 44.471214] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd File Systems. [ OK ] Stopped target Initrd Root File System. Starting udev Coldplug all Devices... [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Reached target rpc_pipefs.target. [ OK ] Started Apply Kernel Variables. [ 44.838382] systemd[1]: Activated swap /dev/disk/by-label/SWAP. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ 44.916166] systemd[1]: systemd-remount-fs.service: Main process exited, code=exited, status=1/FAILURE [ 44.933612] systemd[1]: systemd-remount-fs.service: Failed with result 'exit-code'. [ 44.970534] systemd[1]: Failed to start Remount Root and Kernel File Systems. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ 45.022739] systemd[1]: Started Journal Service. [ OK ] Started Journal Service. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Mounted Kernel Debug File System. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Mounted Huge Pages File System. Starting Configure read-only root support... Starting Create Static Device Nodes in /dev... Starting Flush Journal to Persistent Storage... [ OK ] Reached target Swap. [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started udev Coldplug all Devices. [ OK ] Started Create Static Device Nodes in /dev. Starting udev Kernel Device Manager... [ OK ] Reached target Local File Systems (Pre). Mounting /home/green/git/lustre-release... Mounting /mnt... [ OK ] Mounted /mnt. [ 46.375798] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 48.189210] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 48.376732] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 49.309499] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 49.364429] EDAC sbridge: Ver: 1.1.2 [* ] A start job is running for Configur…only root support (10s / no limit) [** ] A start job is running for Configur…only root support (10s / no limit) [*** ] A start job is running for Configur…only root support (11s / no limit) [ *** ] A start job is running for Configur…only root support (11s / no limit) [ *** ] A start job is running for Configur…only root support (12s / no limit)[ 55.195271] Key type dns_resolver registered [ ***] A start job is running for Configur…only root support (12s / no limit) [ **] A start job is running for Configur…only root support (13s / no limit)[ 56.066597] NFS: Registering the id_resolver key type [ 56.083636] Key type id_resolver registered [ 56.085393] Key type id_legacy registered [ *] A start job is running for Configur…only root support (13s / no limit) [ **] A start job is running for Configur…only root support (14s / no limit) [ OK ] Started Configure read-only root support. [ OK ] Reached target Local File Systems. Starting Create Volatile Files and Directories... Starting Rebuild Dynamic Linker Cache... Starting Mark the need to relabel after reboot... Starting Load/Save Random Seed... [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Load/Save Random Seed. Starting RPC Bind... Starting Update UTMP about System Boot/Shutdown... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Started dnf makecache --timer. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Reached target Timers. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting Login Service... [ OK ] Started D-Bus System Message Bus. [ OK ] Reached target sshd-keygen.target. Starting Network Manager... Starting Restore /run/initramfs on shutdown... [ OK ] Started irqbalance daemon. [ OK ] Started Restore /run/initramfs on shutdown. [ 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... [ OK ] Started Login Service. Starting Hostname Service... [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... [ OK ] Started OpenSSH server daemon. [ OK ] Started Permit User Sessions. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Command Scheduler. [ OK ] Started Serial Getty on ttyS1. [ OK ] Started Getty on tty1. [ OK ] Reached target Login Prompts. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting Crash recovery kernel arming... Starting System Logging Service... Starting Notify NFS peers of a restart... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg439-server login: [ 128.949526] libcfs: loading out-of-tree module taints kernel. [ 129.037368] Key type ._llcrypt registered [ 129.039576] Key type .llcrypt registered [ 129.240229] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_hostid [ 147.116853] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing load_modules_local [ 148.632449] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 148.646336] alg: No test for adler32 (adler32-zlib) [ 150.418422] Lustre: Lustre: Build Version: 2.17.55_24_g1bda257 [ 151.300212] LNet: Added LNI 192.168.204.139@tcp [8/256/0/180] [ 153.159871] Key type lgssc registered [ 155.279318] Lustre: Echo OBD driver; http://www.lustre.org/ [ 179.305925] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 230.950080] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing load_modules_local [ 244.251533] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 244.328504] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 245.688411] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 245.720975] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 245.852187] Lustre: lustre-MDT0000: new disk, initializing [ 245.983933] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 246.018670] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 250.938683] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 266.366232] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 266.505773] Lustre: 6512:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 266.535195] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 266.539811] Lustre: Skipped 1 previous similar message [ 266.651289] Lustre: lustre-MDT0001: new disk, initializing [ 266.799105] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 266.862835] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 266.882179] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 271.786042] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 277.375476] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 288.012696] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 288.363310] Lustre: lustre-OST0000: new disk, initializing [ 288.370583] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 288.379681] Lustre: 8452:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 288.471741] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 294.943568] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 294.975656] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 295.099114] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 296.272321] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 311.901077] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 312.049913] Lustre: lustre-OST0001: new disk, initializing [ 312.057580] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 312.067601] Lustre: 9525:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 312.143333] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 319.922504] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 321.590728] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 321.603220] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 321.651408] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 334.293498] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 345.404241] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 353.507504] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing check_logdir /tmp/testlogs/ [ 359.663616] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing yml_node [ 364.850659] Lustre: DEBUG MARKER: Client: 2.17.55.24 [ 367.665411] Lustre: DEBUG MARKER: MDS: 2.17.55.24 [ 371.013734] Lustre: DEBUG MARKER: OSS: 2.17.55.24 [ 372.804667] Lustre: DEBUG MARKER: -----============= acceptance-small: replay-single ============----- Tue Sep 8 08:10:34 EDT 2026 [ 395.749977] Lustre: DEBUG MARKER: excepting tests: 110f 131b 59 36 [ 399.053990] Lustre: DEBUG MARKER: === replay-single: start setup 08:11:00 (1788869460) === [ 405.915277] Lustre: DEBUG MARKER: oleg439-client.virtnet: executing check_config_client /mnt/lustre [ 430.686808] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 434.788893] Lustre: 13341:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 439.591546] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 446.746841] Lustre: DEBUG MARKER: === replay-single: finish setup 08:11:47 (1788869507) === [ 450.809809] Lustre: DEBUG MARKER: == replay-single test 100a: DNE: create striped dir, drop update rep from MDT1, fail MDT1 ========================================================== 08:11:52 (1788869512) [ 452.419430] Lustre: *** cfs_fail_loc=1701, val=2147483648*** [ 452.425265] LustreError: 6526:0:(ldlm_lib.c:3345:target_send_reply_msg()) @@@ dropping reply req@ffff98a9c12adf80 x1875765325066240/t4294967300(0) o1000->lustre-MDT0000-mdtlov_UUID@0@lo:461/0 lens 264/4320 e 0 to 0 dl 1788869526 ref 1 fl Interpret:/200/0 rc 0/0 job:'osp_up1-0.0' uid:0 gid:0 projid:4294967295 [ 454.447545] Lustre: Failing over lustre-MDT0001 [ 454.632799] 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 [ 454.648659] Lustre: Skipped 1 previous similar message [ 454.818895] Lustre: server umount lustre-MDT0001 complete [ 459.756881] LustreError: 6525:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 459.781217] LustreError: 6525:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 7 previous similar messages [ 460.854030] LustreError: 6521:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0001: not available for connect from 192.168.204.39@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 464.865912] LustreError: 6520:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 464.900742] LustreError: 6520:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 2 previous similar messages [ 468.959204] Lustre: 7879:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788869515/real 1788869515] req@ffff98a9c12afb80 x1875765325066240/t0(0) o1000->lustre-MDT0001-osp-MDT0000@0@lo:24/4 lens 264/4320 e 0 to 1 dl 1788869531 ref 2 fl Rpc:XQr/200/ffffffff rc 0/-1 job:'osp_up1-0.0' uid:0 gid:0 projid:4294967295 [ 469.996570] LustreError: 6520:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 470.041311] LustreError: 6520:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 3 previous similar messages [ 475.107144] LustreError: 6521:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 475.142874] LustreError: 6521:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 3 previous similar messages [ 475.548907] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 476.069827] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 476.232649] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 481.270913] Lustre: lustre-MDT0001-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 481.347639] Lustre: lustre-MDT0001: Recovery over after 0:05, of 2 clients 2 recovered and 0 were evicted. [ 481.766813] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 494.480725] Lustre: DEBUG MARKER: oleg439-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 496.862849] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 507.898992] Lustre: DEBUG MARKER: == replay-single test 100b: DNE: create striped dir, fail MDT0 ========================================================== 08:12:49 (1788869569) [ 509.235720] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 509.237962] LustreError: 8665:0:(ldlm_lib.c:3345:target_send_reply_msg()) @@@ dropping reply req@ffff98a9f5543100 x1875765307166720/t4294967364(0) o36->36591596-e2d0-4912-b465-46eb13f66fcb@192.168.204.39@tcp:557/0 lens 560/536 e 0 to 0 dl 1788869622 ref 1 fl Interpret:/200/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 511.463664] Lustre: Failing over lustre-MDT0000 [ 511.919933] Lustre: server umount lustre-MDT0000 complete [ 511.974083] 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 [ 511.979620] LustreError: 6521:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 511.994258] Lustre: Skipped 3 previous similar messages [ 512.021538] LustreError: 6521:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 3 previous similar messages [ 528.510055] LustreError: 8665:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.204.39@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 528.526928] LustreError: 8665:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 16 previous similar messages [ 532.943394] Lustre: 3644:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788869579/real 1788869579] req@ffff98a9efa72300 x1875765325112576/t0(0) o400->MGC192.168.204.139@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1788869595 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 532.961287] LustreError: MGC192.168.204.139@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 533.010571] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 542.503670] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 543.796957] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 547.827285] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 547.832678] Lustre: Skipped 2 previous similar messages [ 547.881058] Lustre: lustre-MDT0000: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 547.892345] Lustre: 6521:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff98a8c46ce300 x1875765307166720/t4294967364(0) o36->36591596-e2d0-4912-b465-46eb13f66fcb@192.168.204.39@tcp:595/0 lens 560/2880 e 0 to 0 dl 1788869660 ref 1 fl Interpret:/202/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 547.950780] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:6 to 0x2c0000401:33) [ 547.950816] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:6 to 0x280000401:33) [ 548.039220] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 559.412119] Lustre: DEBUG MARKER: oleg439-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 561.208427] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 574.161285] Lustre: DEBUG MARKER: == replay-single test 100c: DNE: create striped dir, abort_recov_mdt mds2 ========================================================== 08:13:55 (1788869635) [ 582.591361] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 584.816416] Lustre: Failing over lustre-MDT0001 [ 585.059577] Lustre: server umount lustre-MDT0001 complete [ 588.768719] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 588.773912] 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 [ 588.786049] LustreError: 6525:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 588.809901] Lustre: Skipped 3 previous similar messages [ 588.847902] LustreError: 6525:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 16 previous similar messages [ 600.579641] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 600.581755] LDISKFS-fs (dm-1): recovery complete [ 600.608797] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 601.184245] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 601.224458] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 601.224886] Lustre: lustre-MDT0001: Aborting MDT recovery [ 602.440580] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 606.182814] Lustre: lustre-MDT0001-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 606.199642] Lustre: Skipped 3 previous similar messages [ 606.335107] Lustre: lustre-MDT0001-osd: cancel update llog [0x240000400:0x1:0x0] [ 606.366384] Lustre: lustre-MDT0000-osp-MDT0001: cancel update llog [0x200000401:0x1:0x0] [ 606.413180] Lustre: lustre-MDT0001: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 606.450466] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 606.467305] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:46 to 0x2c0000400:65) [ 606.468577] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:46 to 0x280000400:65) [ 625.268637] Lustre: Failing over lustre-MDT0001 [ 625.738625] Lustre: server umount lustre-MDT0001 complete [ 626.661800] 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 [ 626.687297] Lustre: Skipped 1 previous similar message [ 646.261935] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 646.891225] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 646.939898] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 648.245066] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 652.264544] Lustre: lustre-MDT0001-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 652.270696] Lustre: Skipped 2 previous similar messages [ 652.286450] Lustre: lustre-MDT0001: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 652.373486] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:70 to 0x280000400:97) [ 652.374294] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:70 to 0x2c0000400:97) [ 652.490446] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 663.653746] Lustre: DEBUG MARKER: oleg439-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 665.510394] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 676.009647] Lustre: DEBUG MARKER: == replay-single test 100d: DNE: cancel update logs upon recovery abort ========================================================== 08:15:37 (1788869737) [ 691.963158] Lustre: Failing over lustre-MDT0000 [ 692.219888] Lustre: server umount lustre-MDT0000 complete [ 692.708871] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 692.715808] 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 [ 692.731162] Lustre: Skipped 1 previous similar message [ 692.739713] LustreError: 7882:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 692.756471] LustreError: 7882:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 25 previous similar messages [ 702.522271] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 702.658508] LustreError: MGC192.168.204.139@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 702.996509] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 703.003741] Lustre: lustre-MDT0000: Aborting client recovery [ 703.009451] LustreError: 20227:0:(lod_dev.c:512:lod_sub_recovery_thread()) lustre-MDT0001-osp-MDT0000: get update log duration 0, retries 0, failed: rc = -108 [ 703.017489] LustreError: 20195:0:(ldlm_lib.c:3003:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 703.026191] LustreError: 20227:0:(lod_dev.c:512:lod_sub_recovery_thread()) Skipped 1 previous similar message [ 703.038118] Lustre: 20228:0:(ldlm_lib.c:2403:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 703.046631] Lustre: 20228:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 36591596-e2d0-4912-b465-46eb13f66fcb@ [ 703.055065] Lustre: lustre-MDT0000: disconnecting 2 stale clients [ 703.061437] Lustre: lustre-MDT0000-osd: cancel update llog [0x200000400:0x1:0x0] [ 703.080353] Lustre: lustre-MDT0001-osp-MDT0000: cancel update llog [0x240000401:0x1:0x0] [ 703.185735] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:44 to 0x2c0000401:65) [ 703.187127] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:44 to 0x280000401:65) [ 708.097907] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 708.106330] Lustre: Skipped 2 previous similar messages [ 708.133657] LustreError: lustre-MDT0000-osp-MDT0001: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 709.016272] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 734.127852] Lustre: DEBUG MARKER: == replay-single test 100e: DNE: create striped dir on MDT0 and MDT1, fail MDT0, MDT1 ========================================================== 08:16:35 (1788869795) [ 743.637174] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 752.742964] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 755.119959] Lustre: Failing over lustre-MDT0000 [ 755.472361] Lustre: server umount lustre-MDT0000 complete [ 759.269382] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 759.291977] 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 [ 759.310334] Lustre: Skipped 4 previous similar messages [ 760.091462] LustreError: 6505:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788869822 with bad export cookie 16494126457842912786 [ 760.094844] Lustre: Failing over lustre-MDT0001 [ 760.106234] LustreError: MGC192.168.204.139@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 760.107696] LustreError: 6505:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 3 previous similar messages [ 760.651505] Lustre: server umount lustre-MDT0001 complete [ 787.026303] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 787.036362] LDISKFS-fs (dm-0): recovery complete [ 787.044566] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 787.085831] LDISKFS-fs (dm-1): 7 truncates cleaned up [ 787.092801] LDISKFS-fs (dm-1): recovery complete [ 787.129827] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 804.319716] LustreError: 3643:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff98a9cb5d9c00 x1875765325484160/t0(0) o250->MGC192.168.204.139@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 0 ref 1 fl Rpc:NQU/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 804.995181] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 805.003131] Lustre: Skipped 1 previous similar message [ 805.024504] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 805.031212] Lustre: Skipped 2 previous similar messages [ 805.263340] 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 [ 805.271691] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_connect to node 0@lo failed: rc = -114 [ 805.296385] Lustre: Skipped 3 previous similar messages [ 805.320424] Lustre: lustre-MDT0001-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 805.336687] Lustre: Skipped 3 previous similar messages [ 805.776082] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 811.112481] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 811.585022] Lustre: lustre-MDT0001: Recovery over after 0:06, of 2 clients 2 recovered and 0 were evicted. [ 811.654096] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:70 to 0x280000400:129) [ 811.655600] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:70 to 0x2c0000400:129) [ 811.921085] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 819.167216] Lustre: 3647:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788869827/real 1788869827] req@ffff98a9ff54ea00 x1875765325480960/t0(0) o400->lustre-MDT0001-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788869882 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 821.075881] Lustre: lustre-MDT0000: Recovery over after 0:11, of 2 clients 2 recovered and 0 were evicted. [ 821.131825] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:44 to 0x280000401:97) [ 821.138331] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:44 to 0x2c0000401:97) [ 824.160815] Lustre: 3645:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788869832/real 1788869832] req@ffff98a9ff54d500 x1875765325481728/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788869887 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 824.213359] Lustre: 3645:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 824.807259] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 824.824239] Lustre: Skipped 3 previous similar messages [ 827.994293] Lustre: DEBUG MARKER: oleg439-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 829.407248] Lustre: 3644:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788869837/real 1788869837] req@ffff98a9ff54f480 x1875765325481984/t0(0) o400->lustre-MDT0001-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788869892 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 829.441642] Lustre: 3644:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 829.638673] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 831.380706] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 839.135252] Lustre: 3647:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788869847/real 1788869847] req@ffff98a9cb5daa00 x1875765325483008/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788869902 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 839.169509] Lustre: 3647:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 842.236747] Lustre: DEBUG MARKER: == replay-single test 101: Shouldn't reassign precreated objs to other files after recovery ========================================================== 08:18:23 (1788869903) [ 851.471841] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 860.127340] Lustre: 3646:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788869867/real 1788869867] req@ffff98a9ef2dc700 x1875765325484416/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788869922 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 860.170143] Lustre: 3646:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 8 previous similar messages [ 876.852187] Lustre: Failing over lustre-MDT0000 [ 877.160453] LustreError: 23190:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.204.39@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 877.177836] LustreError: 23190:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 17 previous similar messages [ 877.444558] Lustre: server umount lustre-MDT0000 complete [ 877.543320] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 877.550616] 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 [ 890.291659] LDISKFS-fs (dm-0): 4 truncates cleaned up [ 890.294196] LDISKFS-fs (dm-0): recovery complete [ 890.301609] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 890.384078] LustreError: MGC192.168.204.139@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 890.741593] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 890.747336] Lustre: lustre-MDT0000: Aborting client recovery [ 890.751286] Lustre: Skipped 1 previous similar message [ 890.768260] LustreError: 25618:0:(ldlm_lib.c:3003:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 890.777149] Lustre: 25651:0:(ldlm_lib.c:2403:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 890.785234] Lustre: 25651:0:(ldlm_lib.c:2403:target_recovery_overseer()) Skipped 2 previous similar messages [ 890.795071] Lustre: 25651:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client lustre-MDT0001-mdtlov_UUID@ [ 890.808979] Lustre: 25651:0:(genops.c:1622:class_disconnect_stale_exports()) Skipped 1 previous similar message [ 890.819579] Lustre: lustre-MDT0000: disconnecting 2 stale clients [ 890.834134] Lustre: lustre-MDT0000-osd: cancel update llog [0x2000013a0:0x1:0x0] [ 890.854126] Lustre: lustre-MDT0001-osp-MDT0000: cancel update llog [0x240001b71:0x1:0x0] [ 890.942215] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:44 to 0x280000401:129) [ 890.993761] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:44 to 0x2c0000401:129) [ 895.985327] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 895.999191] Lustre: Skipped 1 previous similar message [ 896.009497] LustreError: lustre-MDT0000-osp-MDT0001: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 896.169209] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1003.879098] Lustre: DEBUG MARKER: == replay-single test 102a: check resend (request lost) with multiple modify RPCs in flight ========================================================== 08:21:05 (1788870065) [ 1005.332649] Lustre: *** cfs_fail_loc=159, val=0*** [ 1005.344565] Lustre: Skipped 1 previous similar message [ 1060.479787] Lustre: lustre-MDT0000: Client 36591596-e2d0-4912-b465-46eb13f66fcb (at 192.168.204.39@tcp) reconnecting [ 1068.361946] Lustre: DEBUG MARKER: == replay-single test 102b: check resend (reply lost) with multiple modify RPCs in flight ========================================================== 08:22:10 (1788870130) [ 1070.161160] Lustre: *** cfs_fail_loc=15a, val=0*** [ 1124.918896] Lustre: lustre-MDT0001: Client 36591596-e2d0-4912-b465-46eb13f66fcb (at 192.168.204.39@tcp) reconnecting [ 1125.053542] Lustre: 23190:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff98a8c5ae2d80 x1875765310479744/t21474843567(0) o36->36591596-e2d0-4912-b465-46eb13f66fcb@192.168.204.39@tcp:417/0 lens 488/3152 e 0 to 0 dl 1788870237 ref 1 fl Interpret:/202/0 rc 0/0 job:'chmod.0' uid:0 gid:0 projid:4294967295 [ 1125.082461] Lustre: 23190:0:(mdt_recovery.c:102:mdt_req_from_lrd()) Skipped 6 previous similar messages [ 1134.680689] Lustre: DEBUG MARKER: == replay-single test 102c: check replay w/o reconstruction with multiple mod RPCs in flight ========================================================== 08:23:16 (1788870196) [ 1143.816716] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1145.352531] Lustre: *** cfs_fail_loc=15a, val=0*** [ 1145.355037] Lustre: Skipped 5 previous similar messages [ 1149.804439] Lustre: Failing over lustre-MDT0000 [ 1150.190714] Lustre: server umount lustre-MDT0000 complete [ 1150.515746] LustreError: 23192:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.204.39@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1150.530905] LustreError: 23192:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 11 previous similar messages [ 1151.968664] Lustre: lustre-MDT0000-lwp-OST0000: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 1151.994694] Lustre: Skipped 5 previous similar messages [ 1152.011644] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1167.337524] Lustre: 3647:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788870214/real 1788870214] req@ffff98a8c6527800 x1875765326218496/t0(0) o400->MGC192.168.204.139@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1788870230 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1167.373931] LustreError: MGC192.168.204.139@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1173.834834] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1173.838488] LDISKFS-fs (dm-0): recovery complete [ 1173.850022] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1177.832960] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1177.837706] Lustre: Skipped 2 previous similar messages [ 1177.902642] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1177.914851] Lustre: Skipped 2 previous similar messages [ 1179.534777] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 1179.553615] Lustre: Skipped 1 previous similar message [ 1182.364382] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1183.209137] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 1183.214372] Lustre: Skipped 3 previous similar messages [ 1183.322449] Lustre: lustre-MDT0000: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 1183.386622] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:137 to 0x2c0000401:161) [ 1183.391488] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:137 to 0x280000401:161) [ 1192.213977] Lustre: DEBUG MARKER: oleg439-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1194.420991] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1203.518315] Lustre: DEBUG MARKER: == replay-single test 102d: check replay [ 1205.038712] Lustre: *** cfs_fail_loc=15a, val=0*** [ 1205.041461] Lustre: Skipped 7 previous similar messages [ 1209.480183] Lustre: Failing over lustre-MDT0001 [ 1209.792527] Lustre: server umount lustre-MDT0001 complete [ 1213.929057] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 1227.460032] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1227.846433] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 1229.131885] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 1232.406638] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1232.907716] Lustre: lustre-MDT0001: Recovery over after 0:03, of 2 clients 2 recovered and 0 were evicted. [ 1232.921312] Lustre: 23191:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff98a9f85b0a80 x1875765310544768/t21474843610(0) o36->36591596-e2d0-4912-b465-46eb13f66fcb@192.168.204.39@tcp:525/0 lens 488/3152 e 0 to 0 dl 1788870345 ref 1 fl Interpret:/202/0 rc 0/0 job:'chmod.0' uid:0 gid:0 projid:4294967295 [ 1232.951093] Lustre: 23191:0:(mdt_recovery.c:102:mdt_req_from_lrd()) Skipped 5 previous similar messages [ 1232.982922] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:1137 to 0x2c0000400:1153) [ 1232.983477] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:1138 to 0x280000400:1153) [ 1242.272194] Lustre: DEBUG MARKER: oleg439-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 1243.864803] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1252.803958] Lustre: DEBUG MARKER: == replay-single test 103: Check otr_next_id overflow ==== 08:25:14 (1788870314) [ 1257.025803] Lustre: Failing over lustre-MDT0000 [ 1257.552983] Lustre: server umount lustre-MDT0000 complete [ 1274.320283] Lustre: 3645:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788870321/real 1788870321] req@ffff98a9efa5b800 x1875765326290176/t0(0) o400->MGC192.168.204.139@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1788870337 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1274.350066] LustreError: MGC192.168.204.139@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1276.940818] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1284.576757] LustreError: 3643:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff98a8c5ae0380 x1875765326298496/t0(0) o250->MGC192.168.204.139@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 0 ref 1 fl Rpc:NQU/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1284.934659] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1286.706854] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 1289.617487] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1290.289657] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:177 to 0x2c0000401:193) [ 1290.293862] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:177 to 0x280000401:193) [ 1299.378043] Lustre: DEBUG MARKER: oleg439-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1300.988246] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1308.931920] Lustre: DEBUG MARKER: == replay-single test 110a: DNE: create striped dir, fail MDT1 ========================================================== 08:26:10 (1788870370) [ 1316.327676] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1318.618919] Lustre: Failing over lustre-MDT0000 [ 1318.828627] Lustre: server umount lustre-MDT0000 complete [ 1320.929967] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1320.932948] 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 [ 1320.968389] Lustre: Skipped 11 previous similar messages [ 1336.288742] LustreError: MGC192.168.204.139@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1342.712452] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1342.719345] LDISKFS-fs (dm-0): recovery complete [ 1342.751095] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1352.167707] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 1352.181688] Lustre: Skipped 10 previous similar messages [ 1352.266266] Lustre: lustre-MDT0000: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 1352.282050] Lustre: Skipped 1 previous similar message [ 1352.372064] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:177 to 0x2c0000401:225) [ 1352.372984] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:177 to 0x280000401:225) [ 1353.062059] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1364.763585] Lustre: DEBUG MARKER: oleg439-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1367.067618] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1379.273905] Lustre: DEBUG MARKER: == replay-single test 110b: DNE: create striped dir, fail MDT1 and client ========================================================== 08:27:20 (1788870440) [ 1388.941606] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1392.185155] Lustre: Failing over lustre-MDT0000 [ 1392.478857] Lustre: server umount lustre-MDT0000 complete [ 1393.124885] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1408.479219] Lustre: 3646:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788870455/real 1788870455] req@ffff98a9c88c3b80 x1875765326377984/t0(0) o400->MGC192.168.204.139@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1788870471 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1408.527723] Lustre: 3646:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 1408.544735] LustreError: MGC192.168.204.139@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1418.362905] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1418.372119] LDISKFS-fs (dm-0): recovery complete [ 1418.382575] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1419.745661] LustreError: 3643:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff98a9dfe59500 x1875765326386944/t0(0) o250->MGC192.168.204.139@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 0 ref 1 fl Rpc:NQU/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1420.256559] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1420.268598] Lustre: Skipped 1 previous similar message [ 1425.386779] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 1425.400828] Lustre: Skipped 1 previous similar message [ 1426.302233] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1437.574856] Lustre: DEBUG MARKER: oleg439-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1440.363072] Lustre: lustre-MDT0000: Denying connection for new client 778be103-744a-44d7-a6bc-034a43ad9ee4 (at 192.168.204.39@tcp), waiting for 2 known clients (0 recovered, 1 in progress, and 0 evicted) to recover in 0:55 [ 1445.445831] Lustre: lustre-MDT0000: Denying connection for new client 778be103-744a-44d7-a6bc-034a43ad9ee4 (at 192.168.204.39@tcp), waiting for 2 known clients (0 recovered, 1 in progress, and 0 evicted) to recover in 0:50 [ 1450.550674] Lustre: lustre-MDT0000: Denying connection for new client 778be103-744a-44d7-a6bc-034a43ad9ee4 (at 192.168.204.39@tcp), waiting for 2 known clients (0 recovered, 1 in progress, and 0 evicted) to recover in 0:44 [ 1455.674584] Lustre: lustre-MDT0000: Denying connection for new client 778be103-744a-44d7-a6bc-034a43ad9ee4 (at 192.168.204.39@tcp), waiting for 2 known clients (0 recovered, 1 in progress, and 0 evicted) to recover in 0:39 [ 1460.791492] Lustre: lustre-MDT0000: Denying connection for new client 778be103-744a-44d7-a6bc-034a43ad9ee4 (at 192.168.204.39@tcp), waiting for 2 known clients (0 recovered, 1 in progress, and 0 evicted) to recover in 0:34 [ 1471.039885] Lustre: lustre-MDT0000: Denying connection for new client 778be103-744a-44d7-a6bc-034a43ad9ee4 (at 192.168.204.39@tcp), waiting for 2 known clients (0 recovered, 1 in progress, and 0 evicted) to recover in 0:24 [ 1471.072359] Lustre: Skipped 1 previous similar message [ 1491.504387] Lustre: lustre-MDT0000: Denying connection for new client 778be103-744a-44d7-a6bc-034a43ad9ee4 (at 192.168.204.39@tcp), waiting for 2 known clients (0 recovered, 1 in progress, and 0 evicted) to recover in 0:03 [ 1491.521850] Lustre: Skipped 3 previous similar messages [ 1495.500361] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 1495.502241] Lustre: 35035:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 36591596-e2d0-4912-b465-46eb13f66fcb@ [ 1495.513409] Lustre: 35035:0:(genops.c:1622:class_disconnect_stale_exports()) Skipped 1 previous similar message [ 1495.521813] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 1495.538493] Lustre: lustre-MDT0000: Recovery over after 1:10, of 2 clients 1 recovered and 1 was evicted. [ 1495.616888] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:177 to 0x2c0000401:257) [ 1495.618640] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:177 to 0x280000401:257) [ 1508.336256] Lustre: DEBUG MARKER: == replay-single test 110c: DNE: create striped dir, fail MDT2 ========================================================== 08:29:29 (1788870569) [ 1516.456240] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 1518.830633] Lustre: Failing over lustre-MDT0001 [ 1519.132062] Lustre: server umount lustre-MDT0001 complete [ 1543.749666] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 1543.751885] LDISKFS-fs (dm-1): recovery complete [ 1543.773785] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1544.230582] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 1544.241922] Lustre: Skipped 4 previous similar messages [ 1549.380543] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:1137 to 0x2c0000400:1185) [ 1549.382863] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:1138 to 0x280000400:1185) [ 1549.725855] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1559.883841] Lustre: DEBUG MARKER: oleg439-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 1562.000437] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1571.538791] Lustre: DEBUG MARKER: == replay-single test 110d: DNE: create striped dir, fail MDT2 and client ========================================================== 08:30:33 (1788870633) [ 1580.473641] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 1582.853085] Lustre: Failing over lustre-MDT0001 [ 1583.106091] Lustre: server umount lustre-MDT0001 complete [ 1585.125713] 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 [ 1585.132232] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 1585.146494] Lustre: Skipped 9 previous similar messages [ 1607.429871] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 1607.434765] LDISKFS-fs (dm-1): recovery complete [ 1607.447569] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1607.785732] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 1607.796306] Lustre: Skipped 1 previous similar message [ 1612.553629] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1612.774368] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 1612.782948] Lustre: lustre-MDT0001-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 1612.789867] Lustre: Skipped 1 previous similar message [ 1612.810185] Lustre: Skipped 10 previous similar messages [ 1621.730778] Lustre: DEBUG MARKER: oleg439-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 1623.928857] Lustre: lustre-MDT0001: Denying connection for new client 3785dfb7-5bf1-4058-8525-bae04c4e8e60 (at 192.168.204.39@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 0:58 [ 1682.500173] Lustre: lustre-MDT0001: recovery is timed out, evict stale exports [ 1682.517851] Lustre: 38865:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0001: disconnect stale client 778be103-744a-44d7-a6bc-034a43ad9ee4@ [ 1682.537808] Lustre: lustre-MDT0001: disconnecting 1 stale clients [ 1682.655489] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:1138 to 0x280000400:1217) [ 1682.655677] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:1137 to 0x2c0000400:1217) [ 1692.883538] Lustre: DEBUG MARKER: == replay-single test 110e: DNE: create striped dir, uncommit on MDT2, fail client/MDT1/MDT2 ========================================================== 08:32:35 (1788870755) [ 1701.897113] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 1709.120511] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1710.790360] Lustre: Failing over lustre-MDT0000 [ 1711.004879] Lustre: server umount lustre-MDT0000 complete [ 1713.730134] LustreError: 19657:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788870776 with bad export cookie 16494126457843146845 [ 1713.733611] LustreError: MGC192.168.204.139@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1713.744253] LustreError: 19657:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 1713.757907] Lustre: Failing over lustre-MDT0001 [ 1713.954402] Lustre: server umount lustre-MDT0001 complete [ 1735.117032] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 1735.120090] LDISKFS-fs (dm-1): recovery complete [ 1735.147702] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1735.150421] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1735.173196] LDISKFS-fs (dm-0): recovery complete [ 1735.195739] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1735.442826] LustreError: 41814:0:(llog.c:1655:llog_backup()) MGC192.168.204.139@tcp: failed to open log lustre-sptlrpc: rc = -108 [ 1735.448526] Lustre: 41814:0:(mgc_request_server.c:770:mgc_llog_local_copy()) MGC192.168.204.139@tcp: failed to copy new config lustre-sptlrpc: rc = -108 [ 1738.719762] LustreError: 3643:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff98a9ef9e3480 x1875765326555520/t0(0) o250->MGC192.168.204.139@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 0 ref 1 fl Rpc:NQU/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1738.750298] LustreError: 41826:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1738.766432] LustreError: 41826:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 171 previous similar messages [ 1744.042949] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1744.154548] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1745.406266] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:177 to 0x2c0000401:289) [ 1745.406962] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:177 to 0x280000401:289) [ 1752.781830] Lustre: DEBUG MARKER: oleg439-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 1755.107486] Lustre: lustre-MDT0001: Denying connection for new client ead62d1a-3ffe-4854-ac58-57a9f6e28e77 (at 192.168.204.39@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 0:59 [ 1755.136763] Lustre: Skipped 11 previous similar messages [ 1770.975378] Lustre: 3646:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788870778/real 1788870778] req@ffff98a8c4df1500 x1875765326552320/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788870833 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1771.007854] Lustre: 3646:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 1814.500793] Lustre: lustre-MDT0001: recovery is timed out, evict stale exports [ 1814.508976] Lustre: 41871:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0001: disconnect stale client 3785dfb7-5bf1-4058-8525-bae04c4e8e60@ [ 1814.521961] Lustre: lustre-MDT0001: disconnecting 1 stale clients [ 1814.552538] Lustre: lustre-MDT0001: Recovery over after 1:10, of 2 clients 1 recovered and 1 was evicted. [ 1814.561226] Lustre: Skipped 3 previous similar messages [ 1814.621816] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:1138 to 0x280000400:1249) [ 1814.622897] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:1137 to 0x2c0000400:1249) [ 1823.332399] Lustre: DEBUG MARKER: SKIP: replay-single test_110f skipping excluded test 110f [ 1824.890471] Lustre: DEBUG MARKER: == replay-single test 110g: DNE: create striped dir, uncommit on MDT1, fail client/MDT1/MDT2 ========================================================== 08:34:46 (1788870886) [ 1831.770988] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1839.762431] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 1841.570567] Lustre: Failing over lustre-MDT0000 [ 1841.766498] Lustre: server umount lustre-MDT0000 complete [ 1842.661719] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1842.685601] LustreError: Skipped 1 previous similar message [ 1845.974481] Lustre: Failing over lustre-MDT0001 [ 1845.983339] LustreError: 6506:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788870908 with bad export cookie 16494126457843151255 [ 1845.990195] LustreError: MGC192.168.204.139@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1845.991896] LustreError: 6506:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 1847.778565] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 1847.792465] Lustre: Skipped 1 previous similar message [ 1850.857816] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 1850.870087] Lustre: Skipped 1 previous similar message [ 1852.209914] Lustre: server umount lustre-MDT0001 complete [ 1878.299369] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 1878.305728] LDISKFS-fs (dm-1): recovery complete [ 1878.335488] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1878.348169] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1878.354900] LDISKFS-fs (dm-0): recovery complete [ 1878.362778] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1878.682892] LustreError: 45251:0:(llog.c:1655:llog_backup()) MGC192.168.204.139@tcp: failed to open log lustre-sptlrpc: rc = -108 [ 1878.713980] Lustre: 45251:0:(mgc_request_server.c:770:mgc_llog_local_copy()) MGC192.168.204.139@tcp: failed to copy new config lustre-sptlrpc: rc = -108 [ 1891.048441] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 1891.060250] Lustre: Skipped 2 previous similar messages [ 1894.799969] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1895.213349] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1896.420027] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 1896.437617] Lustre: Skipped 3 previous similar messages [ 1897.356150] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:1138 to 0x280000400:1281) [ 1897.359083] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:1137 to 0x2c0000400:1281) [ 1904.501888] Lustre: DEBUG MARKER: oleg439-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 1906.618036] Lustre: lustre-MDT0000: Denying connection for new client 16e3ce53-6c9a-40f1-8a66-bc785aa6095f (at 192.168.204.39@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 0:59 [ 1906.642801] Lustre: Skipped 11 previous similar messages [ 1966.500287] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 1966.507279] Lustre: 45345:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client ead62d1a-3ffe-4854-ac58-57a9f6e28e77@ [ 1966.519355] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 1966.571068] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:177 to 0x280000401:321) [ 1966.574580] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:177 to 0x2c0000401:321) [ 1978.170624] Lustre: DEBUG MARKER: == replay-single test 111a: DNE: unlink striped dir, fail MDT1 ========================================================== 08:37:19 (1788871039) [ 1985.516374] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1987.500092] Lustre: Failing over lustre-MDT0000 [ 1987.843269] Lustre: server umount lustre-MDT0000 complete [ 2010.954805] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2010.958315] LDISKFS-fs (dm-0): recovery complete [ 2010.969612] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2015.202904] LustreError: 3643:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff98a9e7d91c00 x1875765326701312/t0(0) o250->MGC192.168.204.139@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 0 ref 1 fl Rpc:NQU/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2020.294967] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2020.974945] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:177 to 0x2c0000401:353) [ 2020.975364] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:177 to 0x280000401:353) [ 2028.898344] Lustre: DEBUG MARKER: oleg439-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2030.275499] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2038.225898] Lustre: DEBUG MARKER: == replay-single test 111b: DNE: unlink striped dir, fail MDT2 ========================================================== 08:38:20 (1788871100) [ 2045.914430] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 2048.239554] Lustre: Failing over lustre-MDT0001 [ 2048.640638] Lustre: server umount lustre-MDT0001 complete [ 2069.495540] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 2069.503524] LDISKFS-fs (dm-1): recovery complete [ 2069.522345] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2069.798493] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 2069.802428] Lustre: Skipped 6 previous similar messages [ 2074.502854] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2083.891260] Lustre: DEBUG MARKER: oleg439-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 2145.500841] Lustre: lustre-MDT0001: recovery is timed out, evict stale exports [ 2145.510269] Lustre: 49534:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0001: disconnect stale client 16e3ce53-6c9a-40f1-8a66-bc785aa6095f@ [ 2145.524391] Lustre: lustre-MDT0001: disconnecting 1 stale clients [ 2145.567953] Lustre: lustre-MDT0001-osp-MDT0000: Connection restored to 0@lo (at 0@lo) [ 2145.577638] Lustre: Skipped 20 previous similar messages [ 2145.606265] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:1137 to 0x2c0000400:1313) [ 2145.614488] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:1138 to 0x280000400:1313) [ 2154.796756] Lustre: DEBUG MARKER: == replay-single test 111c: DNE: unlink striped dir, uncommit on MDT1, fail client/MDT1/MDT2 ========================================================== 08:40:16 (1788871216) [ 2162.110476] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2170.032266] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 2172.483189] Lustre: Failing over lustre-MDT0000 [ 2172.855203] Lustre: server umount lustre-MDT0000 complete [ 2176.869442] LustreError: 26197:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788871239 with bad export cookie 16494126457843155994 [ 2176.881062] LustreError: MGC192.168.204.139@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2176.886474] LustreError: Skipped 1 previous similar message [ 2176.890442] Lustre: Failing over lustre-MDT0001 [ 2177.504289] 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 [ 2177.508398] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 2177.519174] Lustre: Skipped 20 previous similar messages [ 2181.540564] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 2181.548369] Lustre: Skipped 2 previous similar messages [ 2183.351480] Lustre: server umount lustre-MDT0001 complete [ 2208.014901] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2208.018975] LDISKFS-fs (dm-0): recovery complete [ 2208.026728] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2208.059085] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 2208.062776] LDISKFS-fs (dm-1): recovery complete [ 2208.086210] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2221.541938] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xe4e6e89fb01d0f6c [ 2227.181583] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2227.412605] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2228.757541] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:1138 to 0x280000400:1345) [ 2228.775905] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:1137 to 0x2c0000400:1345) [ 2238.742371] Lustre: DEBUG MARKER: oleg439-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 2241.313469] Lustre: lustre-MDT0000: Denying connection for new client ff72a60e-49f7-4e85-8a8c-e869ffa89f76 (at 192.168.204.39@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 0:56 [ 2241.334161] Lustre: Skipped 23 previous similar messages [ 2297.500198] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 2297.512278] Lustre: 52543:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 661d5115-0663-4e27-ae0a-7daf5f97f3df@ [ 2297.532180] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 2297.592042] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:177 to 0x280000401:385) [ 2297.593258] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:177 to 0x2c0000401:385) [ 2307.519930] Lustre: DEBUG MARKER: == replay-single test 111d: DNE: unlink striped dir, uncommit on MDT2, fail client/MDT1/MDT2 ========================================================== 08:42:49 (1788871369) [ 2316.684380] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 2324.515669] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2326.738742] Lustre: Failing over lustre-MDT0000 [ 2327.069634] Lustre: server umount lustre-MDT0000 complete [ 2331.016884] LustreError: 6505:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788871393 with bad export cookie 16494126457843158892 [ 2331.030966] Lustre: Failing over lustre-MDT0001 [ 2331.108627] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 2331.363229] Lustre: server umount lustre-MDT0001 complete [ 2355.376027] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2355.378360] LDISKFS-fs (dm-0): recovery complete [ 2355.390531] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2355.679668] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 2355.681638] LDISKFS-fs (dm-1): recovery complete [ 2355.683357] LustreError: 3643:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff98a8c1eed180 x1875765326866688/t0(0) o250->MGC192.168.204.139@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 0 ref 1 fl Rpc:NQU/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2355.716877] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2355.965110] LustreError: 8447:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 2355.986078] LustreError: 8447:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 75 previous similar messages [ 2356.287084] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_connect to node 0@lo failed: rc = -114 [ 2356.294622] LustreError: Skipped 4 previous similar messages [ 2361.645926] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2361.646051] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2362.233808] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 2362.243897] Lustre: Skipped 6 previous similar messages [ 2362.294915] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:177 to 0x2c0000401:417) [ 2362.295370] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:177 to 0x280000401:417) [ 2371.824715] Lustre: DEBUG MARKER: oleg439-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 2431.501852] Lustre: lustre-MDT0001: recovery is timed out, evict stale exports [ 2431.517296] Lustre: 55970:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0001: disconnect stale client ff72a60e-49f7-4e85-8a8c-e869ffa89f76@ [ 2431.527175] Lustre: lustre-MDT0001: disconnecting 1 stale clients [ 2431.603180] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:1138 to 0x280000400:1377) [ 2431.605334] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:1137 to 0x2c0000400:1377) [ 2444.443852] Lustre: DEBUG MARKER: == replay-single test 111e: DNE: unlink striped dir, uncommit on MDT2, fail MDT1/MDT2 ========================================================== 08:45:06 (1788871506) [ 2453.718384] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 2461.539929] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2463.379466] Lustre: Failing over lustre-MDT0000 [ 2463.577210] Lustre: server umount lustre-MDT0000 complete [ 2466.752466] Lustre: Failing over lustre-MDT0001 [ 2466.754230] LustreError: 19657:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788871529 with bad export cookie 16494126457843161090 [ 2466.771686] LustreError: 19657:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 2466.880876] Lustre: lustre-MDT0001: Not available for connect from 192.168.204.39@tcp (stopping) [ 2466.891744] Lustre: Skipped 1 previous similar message [ 2467.139686] Lustre: server umount lustre-MDT0001 complete [ 2485.669321] Lustre: 3645:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788871532/real 1788871532] req@ffff98a8c5a4bb80 x1875765326934912/t0(0) o400->lustre-MDT0001-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788871548 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2485.708504] Lustre: 3645:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 18 previous similar messages [ 2491.235889] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2491.238435] LDISKFS-fs (dm-0): recovery complete [ 2491.247730] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2491.528225] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 2491.532726] LDISKFS-fs (dm-1): recovery complete [ 2491.545677] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2491.872028] LustreError: 3643:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff98a8c5a48380 x1875765326937344/t0(0) o250->MGC192.168.204.139@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 0 ref 1 fl Rpc:NQU/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2492.323692] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 2492.340144] Lustre: Skipped 7 previous similar messages [ 2495.724241] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 2495.733739] Lustre: Skipped 6 previous similar messages [ 2497.608241] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2497.686641] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2507.003319] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:1138 to 0x280000400:1409) [ 2507.010716] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:177 to 0x280000401:449) [ 2507.014903] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:177 to 0x2c0000401:449) [ 2507.023971] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:1137 to 0x2c0000400:1409) [ 2513.510196] Lustre: DEBUG MARKER: oleg439-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 2515.066760] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2516.763889] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2526.306221] Lustre: DEBUG MARKER: == replay-single test 111f: DNE: unlink striped dir, uncommit on MDT1, fail MDT1/MDT2 ========================================================== 08:46:27 (1788871587) [ 2534.840615] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2542.850475] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 2544.914096] Lustre: Failing over lustre-MDT0000 [ 2545.683915] Lustre: server umount lustre-MDT0000 complete [ 2550.300025] LustreError: 6505:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788871613 with bad export cookie 16494126457843163400 [ 2550.300656] Lustre: Failing over lustre-MDT0001 [ 2550.313420] LustreError: 6505:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 2550.698800] Lustre: server umount lustre-MDT0001 complete [ 2573.323723] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 2573.326564] LDISKFS-fs (dm-1): recovery complete [ 2573.344134] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2573.352727] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2573.357081] LDISKFS-fs (dm-0): recovery complete [ 2573.362627] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2573.587899] LustreError: 62727:0:(llog.c:1655:llog_backup()) MGC192.168.204.139@tcp: failed to open log lustre-sptlrpc: rc = -108 [ 2573.596781] Lustre: 62727:0:(mgc_request_server.c:770:mgc_llog_local_copy()) MGC192.168.204.139@tcp: failed to copy new config lustre-sptlrpc: rc = -108 [ 2575.519124] LustreError: 62729:0:(import.c:339:ptlrpc_invalidate_import()) MGS: timeout waiting for callback (1 != 0) [ 2575.526817] LustreError: 62729:0:(import.c:363:ptlrpc_invalidate_import()) @@@ still on sending list req@ffff98a8c4a17100 x1875765326990336/t0(0) o250->MGC192.168.204.139@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 1788871638 ref 1 fl Rpc:NQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2575.572913] LustreError: 62729:0:(import.c:373:ptlrpc_invalidate_import()) MGS: Unregistering RPCs found (0). Network is sluggish? Waiting for them to error out. [ 2579.517621] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:1137 to 0x2c0000400:1441) [ 2579.522609] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:1138 to 0x280000400:1441) [ 2580.197957] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2580.617111] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2588.742991] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:177 to 0x280000401:481) [ 2588.748796] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:177 to 0x2c0000401:481) [ 2593.969835] Lustre: DEBUG MARKER: oleg439-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 2595.502591] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2596.882536] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2604.683864] Lustre: DEBUG MARKER: == replay-single test 111g: DNE: unlink striped dir, fail MDT1/MDT2 ========================================================== 08:47:46 (1788871666) [ 2611.283764] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2619.077982] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 2621.792036] Lustre: Failing over lustre-MDT0000 [ 2622.028709] Lustre: server umount lustre-MDT0000 complete [ 2626.138616] LustreError: 6506:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788871689 with bad export cookie 16494126457843165738 [ 2626.139379] Lustre: Failing over lustre-MDT0001 [ 2626.146648] LustreError: 6506:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 3 previous similar messages [ 2626.628702] Lustre: server umount lustre-MDT0001 complete [ 2649.103093] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 2649.105679] LDISKFS-fs (dm-1): recovery complete [ 2649.114745] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2649.311135] LustreError: 66163:0:(llog.c:1655:llog_backup()) MGC192.168.204.139@tcp: failed to open log lustre-sptlrpc: rc = -108 [ 2649.324143] Lustre: 66163:0:(mgc_request_server.c:770:mgc_llog_local_copy()) MGC192.168.204.139@tcp: failed to copy new config lustre-sptlrpc: rc = -108 [ 2649.325941] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2649.334014] LDISKFS-fs (dm-0): recovery complete [ 2649.342891] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2651.487659] LustreError: 66196:0:(import.c:339:ptlrpc_invalidate_import()) MGS: timeout waiting for callback (1 != 0) [ 2651.498147] LustreError: 66196:0:(import.c:363:ptlrpc_invalidate_import()) @@@ still on sending list req@ffff98a9f080a680 x1875765327046528/t0(0) o250->MGC192.168.204.139@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 1788871714 ref 1 fl Rpc:NQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2651.513176] LustreError: 66196:0:(import.c:373:ptlrpc_invalidate_import()) MGS: Unregistering RPCs found (0). Network is sluggish? Waiting for them to error out. [ 2655.447394] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:1137 to 0x2c0000400:1473) [ 2655.448826] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:1138 to 0x280000400:1473) [ 2656.795794] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2657.084758] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2664.721334] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:177 to 0x2c0000401:513) [ 2664.721787] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:177 to 0x280000401:513) [ 2669.622639] Lustre: DEBUG MARKER: oleg439-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 2670.999630] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2672.688190] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2681.602201] Lustre: DEBUG MARKER: == replay-single test 112a: DNE: cross MDT rename, fail MDT1 ========================================================== 08:49:03 (1788871743) [ 2683.203359] Lustre: DEBUG MARKER: SKIP: replay-single test_112a needs >= 4 MDTs [ 2684.751980] Lustre: DEBUG MARKER: == replay-single test 112b: DNE: cross MDT rename, fail MDT2 ========================================================== 08:49:06 (1788871746) [ 2686.808984] Lustre: DEBUG MARKER: SKIP: replay-single test_112b needs >= 4 MDTs [ 2688.507897] Lustre: DEBUG MARKER: == replay-single test 112c: DNE: cross MDT rename, fail MDT3 ========================================================== 08:49:10 (1788871750) [ 2690.198550] Lustre: DEBUG MARKER: SKIP: replay-single test_112c needs >= 4 MDTs [ 2692.466846] Lustre: DEBUG MARKER: == replay-single test 112d: DNE: cross MDT rename, fail MDT4 ========================================================== 08:49:13 (1788871753) [ 2694.406725] Lustre: DEBUG MARKER: SKIP: replay-single test_112d needs >= 4 MDTs [ 2696.195565] Lustre: DEBUG MARKER: == replay-single test 112e: DNE: cross MDT rename, fail MDT1 and MDT2 ========================================================== 08:49:17 (1788871757) [ 2697.864588] Lustre: DEBUG MARKER: SKIP: replay-single test_112e needs >= 4 MDTs [ 2699.575201] Lustre: DEBUG MARKER: == replay-single test 112f: DNE: cross MDT rename, fail MDT1 and MDT3 ========================================================== 08:49:21 (1788871761) [ 2701.187813] Lustre: DEBUG MARKER: SKIP: replay-single test_112f needs >= 4 MDTs [ 2703.178556] Lustre: DEBUG MARKER: == replay-single test 112g: DNE: cross MDT rename, fail MDT1 and MDT4 ========================================================== 08:49:24 (1788871764) [ 2705.001687] Lustre: DEBUG MARKER: SKIP: replay-single test_112g needs >= 4 MDTs [ 2706.953944] Lustre: DEBUG MARKER: == replay-single test 112h: DNE: cross MDT rename, fail MDT2 and MDT3 ========================================================== 08:49:28 (1788871768) [ 2708.529225] Lustre: DEBUG MARKER: SKIP: replay-single test_112h needs >= 4 MDTs [ 2710.723548] Lustre: DEBUG MARKER: == replay-single test 112i: DNE: cross MDT rename, fail MDT2 and MDT4 ========================================================== 08:49:32 (1788871772) [ 2712.640014] Lustre: DEBUG MARKER: SKIP: replay-single test_112i needs >= 4 MDTs [ 2714.774671] Lustre: DEBUG MARKER: == replay-single test 112j: DNE: cross MDT rename, fail MDT3 and MDT4 ========================================================== 08:49:36 (1788871776) [ 2716.181246] Lustre: DEBUG MARKER: SKIP: replay-single test_112j needs >= 4 MDTs [ 2718.208611] Lustre: DEBUG MARKER: == replay-single test 112k: DNE: cross MDT rename, fail MDT1,MDT2,MDT3 ========================================================== 08:49:39 (1788871779) [ 2719.722362] Lustre: DEBUG MARKER: SKIP: replay-single test_112k needs >= 4 MDTs [ 2721.410750] Lustre: DEBUG MARKER: == replay-single test 112l: DNE: cross MDT rename, fail MDT1,MDT2,MDT4 ========================================================== 08:49:43 (1788871783) [ 2722.982189] Lustre: DEBUG MARKER: SKIP: replay-single test_112l needs >= 4 MDTs [ 2724.937765] Lustre: DEBUG MARKER: == replay-single test 112m: DNE: cross MDT rename, fail MDT1,MDT3,MDT4 ========================================================== 08:49:46 (1788871786) [ 2726.748764] Lustre: DEBUG MARKER: SKIP: replay-single test_112m needs >= 4 MDTs [ 2728.118736] Lustre: DEBUG MARKER: == replay-single test 112n: DNE: cross MDT rename, fail MDT2,MDT3,MDT4 ========================================================== 08:49:50 (1788871790) [ 2729.782972] Lustre: DEBUG MARKER: SKIP: replay-single test_112n needs >= 4 MDTs [ 2731.389736] Lustre: DEBUG MARKER: == replay-single test 115: failover for create/unlink striped directory ========================================================== 08:49:53 (1788871793) [ 2738.913132] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 2741.413059] Lustre: Failing over lustre-MDT0001 [ 2741.819146] Lustre: lustre-MDT0001: Not available for connect from 192.168.204.39@tcp (stopping) [ 2747.147886] Lustre: server umount lustre-MDT0001 complete [ 2770.552558] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 2770.555518] LDISKFS-fs (dm-1): recovery complete [ 2770.567743] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2771.102046] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 2771.108201] Lustre: Skipped 10 previous similar messages [ 2776.393349] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2776.561242] Lustre: lustre-MDT0001-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 2776.570567] Lustre: Skipped 31 previous similar messages [ 2776.794744] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:1137 to 0x2c0000400:1505) [ 2776.794892] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:1138 to 0x280000400:1505) [ 2785.559762] Lustre: DEBUG MARKER: oleg439-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 2787.075939] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2796.572298] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2800.067691] Lustre: Failing over lustre-MDT0000 [ 2800.509943] Lustre: server umount lustre-MDT0000 complete [ 2801.632974] 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 [ 2801.649816] Lustre: Skipped 26 previous similar messages [ 2819.058221] LustreError: MGC192.168.204.139@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2819.068038] LustreError: Skipped 4 previous similar messages [ 2821.815107] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2821.821927] LDISKFS-fs (dm-0): recovery complete [ 2821.834426] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2828.259176] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xe4e6e89fb01d45f9 [ 2831.904829] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2834.065918] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:177 to 0x2c0000401:545) [ 2834.066200] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:177 to 0x280000401:545) [ 2841.614225] Lustre: DEBUG MARKER: oleg439-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2843.687952] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2853.722649] Lustre: DEBUG MARKER: == replay-single test 116a: large update log master MDT recovery ========================================================== 08:51:55 (1788871915) [ 2861.779622] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2863.050456] Lustre: *** cfs_fail_loc=1702, val=0*** [ 2865.369763] Lustre: Failing over lustre-MDT0000 [ 2865.635447] Lustre: server umount lustre-MDT0000 complete [ 2889.269358] LDISKFS-fs (dm-0): 4 truncates cleaned up [ 2889.271855] LDISKFS-fs (dm-0): recovery complete [ 2889.282344] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2900.543589] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2901.170400] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:177 to 0x2c0000401:577) [ 2901.171353] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:177 to 0x280000401:577) [ 2910.297665] Lustre: DEBUG MARKER: oleg439-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2912.129708] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2922.703192] Lustre: DEBUG MARKER: == replay-single test 116b: large update log slave MDT recovery ========================================================== 08:53:04 (1788871984) [ 2931.058685] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 2932.319434] Lustre: *** cfs_fail_loc=1702, val=0*** [ 2935.087228] Lustre: Failing over lustre-MDT0001 [ 2935.537548] Lustre: server umount lustre-MDT0001 complete [ 2957.286369] LustreError: 68674:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 2957.315679] LustreError: 68674:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 127 previous similar messages [ 2960.746817] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 2960.753822] LDISKFS-fs (dm-1): recovery complete [ 2960.776700] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2966.592541] Lustre: lustre-MDT0001: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 2966.607402] Lustre: Skipped 10 previous similar messages [ 2966.662654] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:1138 to 0x280000400:1537) [ 2966.674156] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:1137 to 0x2c0000400:1537) [ 2966.776969] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2975.901421] Lustre: DEBUG MARKER: oleg439-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 2977.270578] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2985.883774] Lustre: DEBUG MARKER: == replay-single test 117: DNE: cross MDT unlink, fail MDT1 and MDT2 ========================================================== 08:54:07 (1788872047) [ 2987.590710] Lustre: DEBUG MARKER: SKIP: replay-single test_117 needs >= 4 MDTs [ 2989.242460] Lustre: DEBUG MARKER: == replay-single test 118: invalidate osp update will not cause update log corruption ========================================================== 08:54:11 (1788872051) [ 2990.560149] Lustre: *** cfs_fail_loc=1705, val=0*** [ 3000.856080] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3003.168329] Lustre: Failing over lustre-MDT0000 [ 3003.576915] Lustre: server umount lustre-MDT0000 complete [ 3006.948967] LustreError: 6505:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788872069 with bad export cookie 16494126457843176707 [ 3006.979958] LustreError: 6505:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 3027.805203] LDISKFS-fs (dm-0): 3 truncates cleaned up [ 3027.817237] LDISKFS-fs (dm-0): recovery complete [ 3027.830891] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3039.257953] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3039.948536] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:177 to 0x280000401:609) [ 3039.950526] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:177 to 0x2c0000401:609) [ 3049.857686] Lustre: DEBUG MARKER: oleg439-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3052.078668] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3061.652192] Lustre: DEBUG MARKER: == replay-single test 119: timeout of normal replay does not cause DNE replay fails ========================================================== 08:55:23 (1788872123) [ 3072.461101] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3076.385501] Lustre: Failing over lustre-MDT0000 [ 3076.715381] Lustre: server umount lustre-MDT0000 complete [ 3092.964835] LDISKFS-fs (dm-0): 3 truncates cleaned up [ 3092.970226] LDISKFS-fs (dm-0): recovery complete [ 3092.979975] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3093.420408] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 3093.435082] Lustre: Skipped 10 previous similar messages [ 3097.143804] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 3097.151179] Lustre: Skipped 10 previous similar messages [ 3097.154482] Lustre: 66192:0:(ldlm_lib.c:2084:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 60, extend: 0 [ 3098.409426] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3098.598919] Lustre: 8447:0:(ldlm_lib.c:2084:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 60, extend: 0 [ 3098.622890] LustreError: 79877:0:(ldlm_lib.c:2689:replay_request_or_update()) cfs_fail_timeout id 714 sleeping for 65000ms [ 3106.044957] Lustre: DEBUG MARKER: oleg439-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3163.647183] LustreError: 79877:0:(ldlm_lib.c:2689:replay_request_or_update()) cfs_fail_timeout id 714 awake [ 3163.661830] Lustre: 79877:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 2a005fe2-2a3d-4ca6-8402-a633d5d16eb3@192.168.204.39@tcp [ 3163.672646] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 3163.677916] Lustre: 79877:0:(ldlm_lib.c:1913:abort_req_replay_queue()) @@@ aborted: req@ffff98a8c5a40e00 x1875765310954496/t0(85899345925) o36->2a005fe2-2a3d-4ca6-8402-a633d5d16eb3@192.168.204.39@tcp:147/0 lens 528/0 e 6 to 0 dl 1788872232 ref 1 fl Complete:/204/ffffffff rc 0/-1 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 3163.708943] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 3163.717145] Lustre: 79877:0:(ldlm_lib.c:2084:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 60, extend: 1 [ 3163.733672] Lustre: lustre-MDT0000: Denying connection for new client 2a005fe2-2a3d-4ca6-8402-a633d5d16eb3 (at 192.168.204.39@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 1 evicted) already passed deadline 0:06 [ 3163.755291] Lustre: Skipped 22 previous similar messages [ 3163.840967] Lustre: 79877:0:(ldlm_lib.c:2393:target_recovery_overseer()) lustre-MDT0000 recovery is aborted by hard timeout [ 3163.849749] Lustre: 79877:0:(ldlm_lib.c:2403:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 3163.854671] Lustre: 79877:0:(ldlm_lib.c:2403:target_recovery_overseer()) Skipped 2 previous similar messages [ 3163.867389] Lustre: lustre-MDT0000-osd: cancel update llog [0x200002340:0x1:0x0] [ 3163.893555] Lustre: lustre-MDT0001-osp-MDT0000: cancel update llog [0x240002342:0x1:0x0] [ 3163.928720] Lustre: 79877:0:(ldlm_lib.c:2950:target_recovery_thread()) too long recovery - read logs [ 3163.936087] LustreError: dumping log to /tmp/lustre-log.1788872226.79877 [ 3164.141746] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:177 to 0x280000401:641) [ 3164.143183] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:177 to 0x2c0000401:641) [ 3171.965934] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 58 sec [ 3182.193906] Lustre: DEBUG MARKER: == replay-single test 120: DNE fail abort should stop both normal and DNE replay ========================================================== 08:57:24 (1788872244) [ 3189.668242] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3195.966864] Lustre: Failing over lustre-MDT0000 [ 3196.278477] Lustre: server umount lustre-MDT0000 complete [ 3199.968862] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3199.986699] LustreError: Skipped 5 previous similar messages [ 3210.189773] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3210.195563] LDISKFS-fs (dm-0): recovery complete [ 3210.209974] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3210.691921] Lustre: lustre-MDT0000: Aborting client recovery [ 3210.703960] LustreError: 81838:0:(ldlm_lib.c:3003:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 3210.718159] Lustre: 81870:0:(ldlm_lib.c:2403:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 3210.729200] Lustre: 81870:0:(ldlm_lib.c:2403:target_recovery_overseer()) Skipped 1 previous similar message [ 3210.744560] Lustre: lustre-MDT0000-osd: cancel update llog [0x20000a040:0x3:0x0] [ 3210.759202] Lustre: lustre-MDT0001-osp-MDT0000: cancel update llog [0x2400088d2:0x1:0x0] [ 3210.805987] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:177 to 0x280000401:673) [ 3210.812849] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:177 to 0x2c0000401:673) [ 3215.674299] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3215.843185] LustreError: lustre-MDT0000-osp-MDT0001: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 3237.889471] Lustre: DEBUG MARKER: == replay-single test 121: lock replay timed out and race ========================================================== 08:58:19 (1788872299) [ 3241.153770] Lustre: Failing over lustre-MDT0000 [ 3241.439898] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3241.444082] Lustre: Skipped 4 previous similar messages [ 3241.575249] Lustre: server umount lustre-MDT0000 complete [ 3248.607646] Lustre: *** cfs_fail_loc=721, val=0*** [ 3248.611094] Lustre: Skipped 6 previous similar messages [ 3251.250821] Lustre: *** cfs_fail_loc=721, val=0*** [ 3251.254227] Lustre: Skipped 2 previous similar messages [ 3253.728370] Lustre: *** cfs_fail_loc=721, val=0*** [ 3253.730399] Lustre: Skipped 8 previous similar messages [ 3255.221784] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3255.729878] Lustre: *** cfs_fail_loc=721, val=0*** [ 3255.738245] Lustre: Skipped 32 previous similar messages [ 3260.898250] Lustre: *** cfs_fail_loc=721, val=1*** [ 3260.905260] Lustre: *** cfs_fail_loc=721, val=1*** [ 3260.905862] Lustre: Skipped 68 previous similar messages [ 3260.927382] Lustre: Skipped 5 previous similar messages [ 3260.951679] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3269.087571] Lustre: *** cfs_fail_loc=721, val=1*** [ 3269.096267] Lustre: Skipped 33 previous similar messages [ 3271.790619] Lustre: lustre-MDT0000: Client 2a005fe2-2a3d-4ca6-8402-a633d5d16eb3 (at 192.168.204.39@tcp) reconnected, waiting for 2 clients in recovery for 0:54 [ 3286.497182] Lustre: *** cfs_fail_loc=721, val=1*** [ 3286.501782] Lustre: Skipped 69 previous similar messages [ 3288.130898] Lustre: lustre-MDT0000: Client 2a005fe2-2a3d-4ca6-8402-a633d5d16eb3 (at 192.168.204.39@tcp) reconnected, waiting for 2 clients in recovery for 0:38 [ 3291.103294] Lustre: 3643:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788872323/real 1788872323] req@ffff98a8c5ae1180 x1875765327515520/t0(0) o400->lustre-MDT0000-osp-MDT0001@0@lo:24/4 lens 224/224 e 0 to 1 dl 1788872353 ref 1 fl Rpc:XQr/2c0/ffffffff rc 0/-1 job:'ldlm_lock_repla.0' uid:0 gid:0 projid:4294967295 [ 3291.147688] Lustre: 3643:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 40 previous similar messages [ 3291.156367] Lustre: lustre-MDT0000: Received new MDS connection from 0@lo, keep former export from same NID [ 3291.171957] Lustre: *** cfs_fail_loc=721, val=1*** [ 3291.176980] Lustre: 83291:0:(tgt_handler.c:581:tgt_handle_recovery()) @@@ obsoleted, rq_xid=1875765311096832, exp_last_xid=1875765311098751 req@ffff98a9f85c5180 x1875765311096832/t0(0) o101->2a005fe2-2a3d-4ca6-8402-a633d5d16eb3@192.168.204.39@tcp:0/0 lens 328/0 e 0 to 0 dl 1788872330 ref 1 fl Complete:/240/ffffffff rc 0/-1 job:'ldlm_lock_repla.0' uid:0 gid:0 projid:4294967295 [ 3304.512034] Lustre: lustre-MDT0000: Client 2a005fe2-2a3d-4ca6-8402-a633d5d16eb3 (at 192.168.204.39@tcp) reconnected, waiting for 2 clients in recovery for 0:21 [ 3319.860034] Lustre: *** cfs_fail_loc=721, val=1*** [ 3319.865620] Lustre: Skipped 119 previous similar messages [ 3319.875198] Lustre: lustre-MDT0000: Client 2a005fe2-2a3d-4ca6-8402-a633d5d16eb3 (at 192.168.204.39@tcp) reconnected, waiting for 2 clients in recovery for 0:06 [ 3321.325421] Lustre: lustre-MDT0000: Received new MDS connection from 0@lo, keep former export from same NID [ 3321.342426] Lustre: *** cfs_fail_loc=721, val=1*** [ 3321.356468] Lustre: 83291:0:(tgt_handler.c:581:tgt_handle_recovery()) @@@ obsoleted, rq_xid=1875765311096704, exp_last_xid=1875765311098751 req@ffff98a9f85c4000 x1875765311096704/t0(0) o101->2a005fe2-2a3d-4ca6-8402-a633d5d16eb3@192.168.204.39@tcp:0/0 lens 328/0 e 0 to 0 dl 1788872330 ref 1 fl Complete:/240/ffffffff rc 0/-1 job:'ldlm_lock_repla.0' uid:0 gid:0 projid:4294967295 [ 3336.259257] Lustre: lustre-MDT0000: Client 2a005fe2-2a3d-4ca6-8402-a633d5d16eb3 (at 192.168.204.39@tcp) reconnected, waiting for 2 clients in recovery for 0:05 [ 3351.523351] Lustre: lustre-MDT0000: Received new MDS connection from 0@lo, keep former export from same NID [ 3351.536763] Lustre: *** cfs_fail_loc=721, val=1*** [ 3351.541317] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 3352.629839] Lustre: lustre-MDT0000: Client 2a005fe2-2a3d-4ca6-8402-a633d5d16eb3 (at 192.168.204.39@tcp) reconnected, waiting for 2 clients in recovery for 0:29 [ 3381.730287] Lustre: lustre-MDT0000: Received new MDS connection from 0@lo, keep former export from same NID [ 3381.750389] Lustre: *** cfs_fail_loc=721, val=1*** [ 3384.413619] Lustre: *** cfs_fail_loc=721, val=1*** [ 3384.420893] Lustre: Skipped 252 previous similar messages [ 3384.426455] Lustre: lustre-MDT0000: Client 2a005fe2-2a3d-4ca6-8402-a633d5d16eb3 (at 192.168.204.39@tcp) reconnected, waiting for 2 clients in recovery for 0:18 [ 3384.434383] Lustre: Skipped 1 previous similar message [ 3411.937508] Lustre: lustre-MDT0000: Received new MDS connection from 0@lo, keep former export from same NID [ 3411.951990] Lustre: *** cfs_fail_loc=721, val=1*** [ 3411.963236] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 3411.970830] Lustre: 83291:0:(ldlm_lib.c:2084:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3412.002146] Lustre: 83291:0:(ldlm_lib.c:2084:extend_recovery_timer()) Skipped 20 previous similar messages [ 3432.537465] Lustre: lustre-MDT0000: Client 2a005fe2-2a3d-4ca6-8402-a633d5d16eb3 (at 192.168.204.39@tcp) reconnected, waiting for 2 clients in recovery for 0:03 [ 3432.554659] Lustre: Skipped 2 previous similar messages [ 3442.143684] Lustre: lustre-MDT0000: Received new MDS connection from 0@lo, keep former export from same NID [ 3442.164205] Lustre: 83291:0:(ldlm_lib.c:2084:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3442.172771] Lustre: 83291:0:(ldlm_lib.c:2393:target_recovery_overseer()) lustre-MDT0000 recovery is aborted by hard timeout [ 3442.180330] Lustre: 83291:0:(ldlm_lib.c:2393:target_recovery_overseer()) Skipped 1 previous similar message [ 3442.190125] Lustre: 83291:0:(ldlm_lib.c:2403:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 3442.202032] Lustre: 83291:0:(ldlm_lib.c:2403:target_recovery_overseer()) Skipped 2 previous similar messages [ 3442.209079] Lustre: 83291:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 2a005fe2-2a3d-4ca6-8402-a633d5d16eb3@192.168.204.39@tcp [ 3442.224250] Lustre: 83291:0:(genops.c:1622:class_disconnect_stale_exports()) Skipped 2 previous similar messages [ 3442.233667] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 3442.242621] Lustre: Skipped 1 previous similar message [ 3442.250532] LustreError: 83291:0:(ldlm_lib.c:1933:abort_lock_replay_queue()) @@@ aborted: req@ffff98a9df5ae680 x1875765311103232/t0(0) o101->2a005fe2-2a3d-4ca6-8402-a633d5d16eb3@192.168.204.39@tcp:0/0 lens 328/0 e 0 to 0 dl 1788872378 ref 1 fl Complete:/240/ffffffff rc 0/-1 job:'ldlm_lock_repla.0' uid:0 gid:0 projid:4294967295 [ 3442.281712] Lustre: lustre-MDT0000-osd: cancel update llog [0x20000a810:0x1:0x0] [ 3442.309808] Lustre: lustre-MDT0001-osp-MDT0000: cancel update llog [0x2400088d3:0x1:0x0] [ 3442.337915] Lustre: 83291:0:(ldlm_lib.c:2950:target_recovery_thread()) too long recovery - read logs [ 3442.343287] LustreError: dumping log to /tmp/lustre-log.1788872505.83291 [ 3442.497914] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:177 to 0x280000401:705) [ 3442.500022] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:675 to 0x2c0000401:705) [ 3443.171737] Lustre: lustre-MDT0000-osp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 3443.193414] Lustre: Skipped 29 previous similar messages [ 3460.507844] Lustre: DEBUG MARKER: == replay-single test 130a: DoM file create (setstripe) replay ========================================================== 09:02:02 (1788872522) [ 3470.136930] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3472.189533] Lustre: Failing over lustre-MDT0000 [ 3472.864857] 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 [ 3472.882169] Lustre: Skipped 28 previous similar messages [ 3474.483586] Lustre: server umount lustre-MDT0000 complete [ 3493.343848] LustreError: MGC192.168.204.139@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3493.356363] LustreError: Skipped 5 previous similar messages [ 3500.786429] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3500.804892] LDISKFS-fs (dm-0): recovery complete [ 3500.831959] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3503.898997] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3503.908784] Lustre: Skipped 7 previous similar messages [ 3509.390441] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:177 to 0x280000401:737) [ 3509.395092] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:675 to 0x2c0000401:737) [ 3509.408599] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3521.990230] Lustre: DEBUG MARKER: oleg439-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3524.792839] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3535.783614] Lustre: DEBUG MARKER: == replay-single test 130b: DoM file create (inherited) replay ========================================================== 09:03:17 (1788872597) [ 3545.177066] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3548.160910] Lustre: Failing over lustre-MDT0000 [ 3548.724163] Lustre: server umount lustre-MDT0000 complete [ 3560.416121] LustreError: 66192:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3560.441201] LustreError: 66192:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 123 previous similar messages [ 3575.323311] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3575.328452] LDISKFS-fs (dm-0): recovery complete [ 3575.338651] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3576.671173] LustreError: 87059:0:(import.c:339:ptlrpc_invalidate_import()) MGS: timeout waiting for callback (1 != 0) [ 3576.690183] LustreError: 87059:0:(import.c:363:ptlrpc_invalidate_import()) @@@ still on sending list req@ffff98a9c77a4000 x1875765327646848/t0(0) o250->MGC192.168.204.139@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 1788872639 ref 1 fl Rpc:NQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3576.737305] LustreError: 87059:0:(import.c:373:ptlrpc_invalidate_import()) MGS: Unregistering RPCs found (0). Network is sluggish? Waiting for them to error out. [ 3576.808481] LustreError: 3643:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff98a9f5eebb80 x1875765327649792/t0(0) o250->MGC192.168.204.139@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 0 ref 1 fl Rpc:NQU/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3582.650240] Lustre: lustre-MDT0000: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 3582.660136] Lustre: Skipped 4 previous similar messages [ 3582.732397] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:177 to 0x280000401:769) [ 3582.741258] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:675 to 0x2c0000401:769) [ 3584.256351] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3594.429727] Lustre: DEBUG MARKER: oleg439-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3596.306202] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3606.793277] Lustre: DEBUG MARKER: == replay-single test 131a: DoM file write lock replay === 09:04:27 (1788872667) [ 3618.863421] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3621.501800] Lustre: Failing over lustre-MDT0000 [ 3621.908397] Lustre: server umount lustre-MDT0000 complete [ 3647.481532] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3647.486136] LDISKFS-fs (dm-0): recovery complete [ 3647.505504] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3649.823742] LustreError: 89002:0:(import.c:339:ptlrpc_invalidate_import()) MGS: timeout waiting for callback (1 != 0) [ 3649.836845] LustreError: 89002:0:(import.c:363:ptlrpc_invalidate_import()) @@@ still on sending list req@ffff98a8c1eed500 x1875765327687552/t0(0) o250->MGC192.168.204.139@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 1788872712 ref 1 fl Rpc:NQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3649.884919] LustreError: 89002:0:(import.c:373:ptlrpc_invalidate_import()) MGS: Unregistering RPCs found (0). Network is sluggish? Waiting for them to error out. [ 3650.017418] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xe4e6e89fb01da0f9 [ 3655.841832] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:675 to 0x2c0000401:801) [ 3655.848159] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:177 to 0x280000401:801) [ 3656.633717] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3668.659581] Lustre: DEBUG MARKER: oleg439-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3670.501301] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3679.722652] Lustre: DEBUG MARKER: SKIP: replay-single test_131b skipping excluded test 131b [ 3682.239425] Lustre: DEBUG MARKER: == replay-single test 132a: PFL new component instantiate replay ========================================================== 09:05:43 (1788872743) [ 3691.688557] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3693.740978] Lustre: Failing over lustre-MDT0000 [ 3694.338279] Lustre: server umount lustre-MDT0000 complete [ 3718.384778] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3718.386972] LDISKFS-fs (dm-0): recovery complete [ 3718.394424] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3722.723683] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xe4e6e89fb01da70b [ 3723.127388] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 3723.148491] Lustre: Skipped 7 previous similar messages [ 3723.344499] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 3723.358853] Lustre: Skipped 4 previous similar messages [ 3728.587972] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:804 to 0x280000401:833) [ 3728.590918] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:803 to 0x2c0000401:833) [ 3728.612918] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3738.616958] Lustre: DEBUG MARKER: oleg439-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3740.383673] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3749.894262] Lustre: DEBUG MARKER: == replay-single test 133: check resend of ongoing requests for lwp during failover ========================================================== 09:06:51 (1788872811) [ 3755.516840] Lustre: *** cfs_fail_loc=123, val=2147483648*** [ 3755.519462] Lustre: Skipped 283 previous similar messages [ 3758.348655] Lustre: Failing over lustre-MDT0000 [ 3758.617687] Lustre: server umount lustre-MDT0000 complete [ 3770.939541] Lustre: lustre-MDT0001: Client 0804304d-5904-48ad-87f2-bcbc7642a62a (at 192.168.204.39@tcp) reconnecting [ 3779.041386] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3791.168391] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3791.380382] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000300000400-0x0000000340000400]:1:mdt [ 3791.404613] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000300000400-0x0000000340000400]:1:mdt] [ 3791.482256] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:804 to 0x280000401:865) [ 3791.495771] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:803 to 0x2c0000401:865) [ 3801.187595] Lustre: DEBUG MARKER: == replay-single test 134: replay creation of a file created in a pool ========================================================== 09:07:42 (1788872862) [ 3821.134438] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3823.302592] Lustre: Failing over lustre-MDT0000 [ 3823.518444] Lustre: server umount lustre-MDT0000 complete [ 3827.169792] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3827.182607] LustreError: Skipped 2 previous similar messages [ 3847.295463] LDISKFS-fs (dm-0): 4 truncates cleaned up [ 3847.298855] LDISKFS-fs (dm-0): recovery complete [ 3847.307455] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3853.791656] LustreError: 3643:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff98a8c5af7480 x1875765327829120/t0(0) o250->MGC192.168.204.139@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 0 ref 1 fl Rpc:NQU/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3859.584611] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:803 to 0x2c0000401:897) [ 3859.586519] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:804 to 0x280000401:897) [ 3860.345633] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3872.292540] Lustre: DEBUG MARKER: oleg439-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3873.949505] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3897.029880] Lustre: DEBUG MARKER: == replay-single test 135: Server failure in lock replay phase ========================================================== 09:09:18 (1788872958) [ 3911.803887] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 3914.821677] Lustre: Failing over lustre-OST0000 [ 3915.083667] Lustre: server umount lustre-OST0000 complete [ 3923.476935] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing load_module ../libcfs/libcfs/libcfs [ 3935.295634] LDISKFS-fs (dm-2): 3 truncates cleaned up [ 3935.301061] LDISKFS-fs (dm-2): recovery complete [ 3935.309713] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3937.289594] Lustre: *** cfs_fail_loc=32d, val=20*** [ 3937.297130] Lustre: Skipped 1 previous similar message [ 3941.554517] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3948.638273] Lustre: DEBUG MARKER: oleg439-client.virtnet: executing wait_import_state_mount REPLAY_LOCKS osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 3950.150904] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in REPLAY_LOCKS state after 0 sec [ 3951.794172] Lustre: DEBUG MARKER: replay-single test_135: @@@@@@ FAIL: Unexpected sync success [ 3952.748350] Lustre: lustre-OST0000: Client 0804304d-5904-48ad-87f2-bcbc7642a62a (at 192.168.204.39@tcp) reconnected, waiting for 3 clients in recovery for 1:24 [ 3959.910178] Lustre: DEBUG MARKER: == replay-single test 136: MDS to disconnect all OSPs first, then cleanup ldlm ========================================================== 09:10:21 (1788873021) [ 3961.439767] Lustre: DEBUG MARKER: SKIP: replay-single test_136 needs > 2 MDTs [ 3963.089106] Lustre: DEBUG MARKER: == replay-single test 137a: DNE: create under striped dir, fail MDT1 ========================================================== 09:10:25 (1788873025) [ 3975.790048] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3977.759857] Lustre: Failing over lustre-MDT0000 [ 3978.363893] Lustre: server umount lustre-MDT0000 complete [ 3998.175439] Lustre: 3645:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788873045/real 1788873045] req@ffff98a8c5ae2d80 x1875765327918976/t0(0) o400->MGC192.168.204.139@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1788873061 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3998.205027] Lustre: 3645:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 11 previous similar messages [ 4001.601096] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 4001.603599] LDISKFS-fs (dm-0): recovery complete [ 4001.610959] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4008.437995] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xe4e6e89fb01dc875 [ 4013.608322] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4014.187141] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:803 to 0x2c0000401:929) [ 4014.192200] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:918 to 0x280000401:961) [ 4023.636194] Lustre: DEBUG MARKER: oleg439-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4025.195599] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4035.127117] Lustre: DEBUG MARKER: == replay-single test 137b: DNE: create under striped dir, fail MDT2 ========================================================== 09:11:36 (1788873096) [ 4043.396707] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 4045.383162] Lustre: Failing over lustre-MDT0001 [ 4045.585810] Lustre: server umount lustre-MDT0001 complete [ 4069.391378] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 4069.398689] LDISKFS-fs (dm-1): recovery complete [ 4069.418710] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4074.846152] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4074.997786] Lustre: lustre-MDT0001-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 4075.016711] Lustre: Skipped 33 previous similar messages [ 4075.150798] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:1539 to 0x280000400:1569) [ 4075.154476] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:1540 to 0x2c0000400:1569) [ 4085.531757] Lustre: DEBUG MARKER: oleg439-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 4087.853803] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4097.217387] Lustre: DEBUG MARKER: == replay-single test 137c: DNE: create under striped dir, fail MDT1/MDT2 ========================================================== 09:12:38 (1788873158) [ 4108.092275] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4116.462714] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 4118.381479] Lustre: Failing over lustre-MDT0001 [ 4118.706327] Lustre: server umount lustre-MDT0001 complete [ 4121.057695] 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 [ 4121.081864] Lustre: Skipped 31 previous similar messages [ 4122.340651] Lustre: Failing over lustre-MDT0000 [ 4122.799452] Lustre: server umount lustre-MDT0000 complete [ 4142.560384] LustreError: MGC192.168.204.139@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4142.573372] LustreError: Skipped 6 previous similar messages [ 4146.291939] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 4146.299573] LDISKFS-fs (dm-0): recovery complete [ 4146.323920] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4146.525902] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 4146.528434] LDISKFS-fs (dm-1): recovery complete [ 4146.537248] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4153.211829] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4153.217765] Lustre: Skipped 8 previous similar messages [ 4158.326530] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4158.527501] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:918 to 0x280000401:993) [ 4158.532479] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:803 to 0x2c0000401:961) [ 4158.844754] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4162.723121] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:1539 to 0x280000400:1601) [ 4162.725415] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:1540 to 0x2c0000400:1601) [ 4169.298252] Lustre: DEBUG MARKER: oleg439-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 4171.021842] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4172.680634] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4182.635203] Lustre: DEBUG MARKER: == replay-single test 200: Dropping one OBD_PING should not cause disconnect ========================================================== 09:14:04 (1788873244) [ 4184.325328] Lustre: DEBUG MARKER: SKIP: replay-single test_200 Need remote client [ 4186.333896] Lustre: DEBUG MARKER: == replay-single test 201: MDT umount cascading disconnects timeouts ========================================================== 09:14:07 (1788873247) [ 4191.271167] LustreError: 104055:0:(tgt_handler.c:1143:tgt_disconnect()) cfs_fail_timeout id 245 sleeping for 8000ms [ 4199.311446] LustreError: 104055:0:(tgt_handler.c:1143:tgt_disconnect()) cfs_fail_timeout id 245 awake [ 4199.334371] Lustre: Failing over lustre-MDT0001 [ 4199.351069] LustreError: 8437:0:(tgt_handler.c:1143:tgt_disconnect()) cfs_fail_timeout id 245 sleeping for 8000ms [ 4199.360932] LustreError: 8437:0:(tgt_handler.c:1143:tgt_disconnect()) Skipped 2 previous similar messages [ 4203.576785] Lustre: lustre-MDT0001: Not available for connect from 192.168.204.39@tcp (stopping) [ 4203.587801] Lustre: Skipped 3 previous similar messages [ 4207.361046] LustreError: 26196:0:(tgt_handler.c:1143:tgt_disconnect()) cfs_fail_timeout id 245 awake [ 4207.369711] LustreError: 26196:0:(tgt_handler.c:1143:tgt_disconnect()) Skipped 1 previous similar message [ 4207.490453] Lustre: server umount lustre-MDT0001 complete [ 4208.691734] LustreError: 104054:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0001: not available for connect from 192.168.204.39@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4208.717763] LustreError: 104054:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 224 previous similar messages [ 4216.757130] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4222.452534] Lustre: lustre-MDT0001: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 4222.460157] Lustre: Skipped 9 previous similar messages [ 4222.523961] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:1539 to 0x280000400:1633) [ 4222.525853] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:1540 to 0x2c0000400:1633) [ 4222.598428] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4233.102233] Lustre: DEBUG MARKER: == replay-single test 202: pfl replay should recovery layout generation ========================================================== 09:14:54 (1788873294) [ 4242.817955] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4245.085322] Lustre: Failing over lustre-MDT0000 [ 4245.344768] Lustre: server umount lustre-MDT0000 complete [ 4268.889477] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 4268.892901] LDISKFS-fs (dm-0): recovery complete [ 4268.904489] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4273.635477] LustreError: 3643:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff98a8c6ffd180 x1875765328091008/t0(0) o250->MGC192.168.204.139@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 0 ref 1 fl Rpc:NQU/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4278.555756] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4279.446546] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:918 to 0x280000401:1025) [ 4279.447773] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:963 to 0x2c0000401:993) [ 4288.015426] Lustre: DEBUG MARKER: oleg439-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4289.626984] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4298.127901] Lustre: DEBUG MARKER: == replay-single test 203: resend can hit original request ========================================================== 09:16:00 (1788873360) [ 4299.526613] LustreError: 104055:0:(mdt_handler.c:2126:mdt_getattr_name_lock()) cfs_fail_timeout id 2403 sleeping for 2000ms [ 4301.623130] LustreError: 104055:0:(mdt_handler.c:2126:mdt_getattr_name_lock()) cfs_fail_timeout id 2403 awake [ 4301.628744] LustreError: 104055:0:(mdt_handler.c:2126:mdt_getattr_name_lock()) Skipped 1 previous similar message [ 4301.635643] Lustre: 104055:0:(service.c:2628:ptlrpc_server_handle_request()) @@@ pause req after reply req@ffff98a9df455f80 x1875765311402880/t0(0) o101->0804304d-5904-48ad-87f2-bcbc7642a62a@192.168.204.39@tcp:572/0 lens 592/1888 e 0 to 0 dl 1788873412 ref 1 fl Complete:/600/0 rc 0/0 job:'stat.0' uid:0 gid:0 projid:0 [ 4304.673253] Lustre: 104055:0:(service.c:2630:ptlrpc_server_handle_request()) @@@ continue req@ffff98a9df455f80 x1875765311402880/t0(0) o101->0804304d-5904-48ad-87f2-bcbc7642a62a@192.168.204.39@tcp:572/0 lens 592/1888 e 0 to 0 dl 1788873412 ref 1 fl Complete:/600/0 rc 0/0 job:'stat.0' uid:0 gid:0 projid:0 [ 4310.511565] Lustre: DEBUG MARKER: == replay-single test complete, duration 3936 sec ======== 09:16:12 (1788873372) [ 4312.276327] Lustre: DEBUG MARKER: === replay-single: start cleanup 09:16:13 (1788873373) === [ 4319.476348] Lustre: DEBUG MARKER: === replay-single: finish cleanup 09:16:21 (1788873381) === [ 4321.261803] Lustre: Failing over lustre-MDT0000 [ 4321.495341] Lustre: server umount lustre-MDT0000 complete [ 4346.514074] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4351.988465] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xe4e6e89fb01e0a62 [ 4352.003248] LustreError: 109978:0:(ldlm_resource.c:1207:ldlm_resource_complain()) MGC192.168.204.139@tcp: namespace resource [0x65727473756c:0x5:0x0].0x0 (ffff98a9d00b4200) refcount nonzero (2) after lock cleanup; forcing cleanup. [ 4352.592326] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4352.599463] Lustre: Skipped 9 previous similar messages [ 4353.299551] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4353.308619] Lustre: Skipped 9 previous similar messages [ 4357.524182] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4357.837947] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:995 to 0x2c0000401:1025) [ 4357.841947] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1027 to 0x280000401:1057) [ 4366.249292] Lustre: DEBUG MARKER: oleg439-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4367.970224] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4378.087442] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4378.107221] Lustre: Skipped 6 previous similar messages [ 4380.307337] Lustre: server umount lustre-MDT0000 complete [ 4390.120845] LustreError: 26197:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788873452 with bad export cookie 16494126457843223138 [ 4390.133894] LustreError: 26197:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 4390.494053] Lustre: server umount lustre-MDT0001 complete [ 4409.475880] Lustre: server umount lustre-OST0000 complete [ 4428.198404] Lustre: server umount lustre-OST0001 complete [ 4444.632491] Lustre: DEBUG MARKER: oleg439-server.virtnet: executing unload_modules_local [ 4447.870724] Key type lgssc unregistered [ 4448.260437] LNet: 112899:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 4448.279410] LNetError: 112899:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 4448.321710] LNet: Removed LNI 192.168.204.139@tcp [ 4449.306171] Key type .llcrypt unregistered [ 4449.311757] Key type ._llcrypt unregistered