[ 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 462384259 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, 524588K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] ftrace: allocating 41240 entries in 162 pages [ 0.000000] ftrace: allocated 162 pages with 3 groups [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] rcu: RCU event tracing is enabled. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ 0.000000] rcu: RCU callback double-/use-after-free debug enabled. [ 0.000000] Rude variant of Tasks RCU enabled. [ 0.000000] Tracing variant of Tasks RCU enabled. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 0.000000] NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16 [ 0.000000] random: get_random_bytes called from start_kernel+0x622/0x9a8 with crng_init=0 [ 0.001000] Console: colour *CGA 80x25 [ 0.001000] printk: console [ttyS1] enabled [ 0.001000] ACPI: Core revision 20220331 [ 0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.001015] APIC: Switch to symmetric I/O mode setup [ 0.002336] x2apic enabled [ 0.003000] Switched APIC routing to physical x2apic. [ 0.003024] kvm-guest: setup PV IPIs [ 0.005875] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.006000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.006043] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.007027] pid_max: default: 32768 minimum: 301 [ 0.008245] LSM: Security Framework initializing [ 0.010002] Yama: becoming mindful. [ 0.010787] SELinux: Initializing. [ 0.012088] *** VALIDATE selinux *** [ 0.020015] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.024554] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.026108] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.027096] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.028022] *** VALIDATE tmpfs *** [ 0.029518] *** VALIDATE proc *** [ 0.030233] *** VALIDATE cgroup *** [ 0.031000] *** VALIDATE cgroup2 *** [ 0.031282] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.033118] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.034004] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.035018] Spectre V2 : User space: Vulnerable [ 0.036005] Speculative Store Bypass: Vulnerable [ 0.039582] debug: unmapping init [mem 0xffffffffb9c59000-0xffffffffb9c60fff] [ 0.041295] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.042576] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.043011] ... version: 2 [ 0.044010] ... bit width: 48 [ 0.045009] ... generic registers: 4 [ 0.046007] ... value mask: 0000ffffffffffff [ 0.047007] ... max period: 00007fffffffffff [ 0.048007] ... fixed-purpose events: 3 [ 0.048906] ... event mask: 000000070000000f [ 0.049282] rcu: Hierarchical SRCU implementation. [ 0.051318] smp: Bringing up secondary CPUs ... [ 0.052506] x86: Booting SMP configuration: [ 0.053024] .... node #0, CPUs: #1 #2 #3 [ 0.057243] smp: Brought up 1 node, 4 CPUs [ 0.059019] smpboot: Max logical packages: 1 [ 0.060009] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.273417] node 0 deferred pages initialised in 211ms [ 0.277300] devtmpfs: initialized [ 0.278233] x86/mm: Memory block size: 128MB [ 0.280794] gcov: version magic: 0x41383552 [ 0.282308] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.283084] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.284351] pinctrl core: initialized pinctrl subsystem [ 0.285201] [ 0.285821] ************************************************************* [ 0.286014] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.287109] ** ** [ 0.288016] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.289013] ** ** [ 0.290014] ** This means that this kernel is built to expose internal ** [ 0.291015] ** IOMMU data structures, which may compromise security on ** [ 0.292011] ** your system. ** [ 0.293011] ** ** [ 0.294011] ** If you see this message and you are not debugging the ** [ 0.295029] ** kernel, report this immediately to your vendor! ** [ 0.296011] ** ** [ 0.297011] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.298013] ************************************************************* [ 0.300017] NET: Registered protocol family 16 [ 0.301359] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.302049] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.303035] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.304414] cpuidle: using governor menu [ 0.306987] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.309659] PCI: Using configuration type 1 for base access [ 0.311098] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.327214] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.328026] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.331033] cryptd: max_cpu_qlen set to 1000 [ 0.333421] ACPI: Added _OSI(Module Device) [ 0.336019] ACPI: Added _OSI(Processor Device) [ 0.337008] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.339013] ACPI: Added _OSI(Processor Aggregator Device) [ 0.345636] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.353613] ACPI: Interpreter enabled [ 0.355055] ACPI: PM: (supports S0 S3 S4 S5) [ 0.356013] ACPI: Using IOAPIC for interrupt routing [ 0.358794] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.363587] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.376724] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.379050] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.381144] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.385132] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.391096] acpiphp: Slot [2] registered [ 0.393153] acpiphp: Slot [5] registered [ 0.395131] acpiphp: Slot [6] registered [ 0.396125] acpiphp: Slot [7] registered [ 0.398140] acpiphp: Slot [8] registered [ 0.399143] acpiphp: Slot [9] registered [ 0.400319] acpiphp: Slot [10] registered [ 0.402148] acpiphp: Slot [3] registered [ 0.404113] acpiphp: Slot [4] registered [ 0.405103] acpiphp: Slot [11] registered [ 0.407102] acpiphp: Slot [12] registered [ 0.408139] acpiphp: Slot [13] registered [ 0.410099] acpiphp: Slot [14] registered [ 0.411163] acpiphp: Slot [15] registered [ 0.413090] acpiphp: Slot [16] registered [ 0.414097] acpiphp: Slot [17] registered [ 0.416082] acpiphp: Slot [18] registered [ 0.417124] acpiphp: Slot [19] registered [ 0.419292] acpiphp: Slot [20] registered [ 0.421257] acpiphp: Slot [21] registered [ 0.422150] acpiphp: Slot [22] registered [ 0.424096] acpiphp: Slot [23] registered [ 0.426099] acpiphp: Slot [24] registered [ 0.428067] acpiphp: Slot [25] registered [ 0.429276] acpiphp: Slot [26] registered [ 0.430074] acpiphp: Slot [27] registered [ 0.432078] acpiphp: Slot [28] registered [ 0.433062] acpiphp: Slot [29] registered [ 0.434062] acpiphp: Slot [30] registered [ 0.436071] acpiphp: Slot [31] registered [ 0.437076] PCI host bridge to bus 0000:00 [ 0.439017] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.441019] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.443013] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.445015] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.447015] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.449016] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.450176] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.453736] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.456661] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.468082] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.473039] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.476018] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.478016] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.483019] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.484579] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.486451] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.488024] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.490750] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.496015] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.505015] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.508808] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.512499] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.518026] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.525018] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.548021] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.563245] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.572014] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.578014] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.596017] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.610381] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.617014] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.624015] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.644017] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.659501] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.667012] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.673014] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.696017] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.707996] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.717017] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.726031] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.746076] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 0.758452] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.774016] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.784021] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.804018] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 0.821173] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.823468] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.825306] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.828390] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.830195] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.836041] iommu: Default domain type: Passthrough [ 0.838600] SCSI subsystem initialized [ 0.839129] ACPI: bus type USB registered [ 0.841097] usbcore: registered new interface driver usbfs [ 0.843070] usbcore: registered new interface driver hub [ 0.844121] usbcore: registered new device driver usb [ 0.846226] pps_core: LinuxPPS API ver. 1 registered [ 0.847006] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.849055] PTP clock support registered [ 0.851173] EDAC MC: Ver: 3.0.0 [ 0.852333] PCI: Using ACPI for IRQ routing [ 0.853760] NetLabel: Initializing [ 0.854007] NetLabel: domain hash size = 128 [ 0.855009] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.858118] NetLabel: unlabeled traffic allowed by default [ 0.861072] vgaarb: loaded [ 0.863409] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.865016] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.871268] clocksource: Switched to clocksource kvm-clock [ 1.006145] VFS: Disk quotas dquot_6.6.0 [ 1.007451] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 1.010418] *** VALIDATE ramfs *** [ 1.011704] *** VALIDATE hugetlbfs *** [ 1.013040] pnp: PnP ACPI init [ 1.015402] pnp: PnP ACPI: found 6 devices [ 1.031996] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 1.034980] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 1.036909] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 1.038821] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 1.040812] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 1.042883] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 1.045302] NET: Registered protocol family 2 [ 1.047457] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 1.052282] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 1.055520] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 1.060268] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 1.063314] TCP: Hash tables configured (established 65536 bind 65536) [ 1.065981] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 1.079876] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 1.082610] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 1.086797] NET: Registered protocol family 1 [ 1.090441] RPC: Registered named UNIX socket transport module. [ 1.092290] RPC: Registered udp transport module. [ 1.093650] RPC: Registered tcp transport module. [ 1.095098] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 1.097176] NET: Registered protocol family 44 [ 1.098572] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 1.100571] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 1.102882] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 1.104927] PCI: CLS 0 bytes, default 64 [ 1.106365] Unpacking initramfs... [ 2.654402] debug: unmapping init [mem 0xffff8a297cc54000-0xffff8a297ffbffff] [ 2.663891] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.665934] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.670174] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 3.324669] Initialise system trusted keyrings [ 3.326022] Key type blacklist registered [ 3.328723] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 3.337748] zbud: loaded [ 3.340432] *** VALIDATE nfs *** [ 3.341504] *** VALIDATE nfs4 *** [ 3.342917] pstore: using deflate compression [ 3.346859] Platform Keyring initialized [ 3.448927] NET: Registered protocol family 38 [ 3.453208] Key type asymmetric registered [ 3.457274] Asymmetric key parser 'x509' registered [ 3.459246] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 3.461944] io scheduler mq-deadline registered [ 3.463365] io scheduler kyber registered [ 3.464856] io scheduler bfq registered [ 3.470262] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 3.472812] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 3.476289] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 3.479864] ACPI: Power Button [PWRF] [ 3.488436] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 3.497468] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 3.530296] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 3.546865] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 3.590885] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 3.617982] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.647224] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.651939] Non-volatile memory driver v1.3 [ 3.652855] Linux agpgart interface v0.103 [ 3.693899] virtio_blk virtio1: [vda] 146656 512-byte logical blocks (75.1 MB/71.6 MiB) [ 3.698996] vda: detected capacity change from 0 to 75087872 [ 3.723305] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.728121] vdb: detected capacity change from 0 to 1073741824 [ 3.749496] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.752395] vdc: detected capacity change from 0 to 2621440000 [ 3.770293] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.772596] vdd: detected capacity change from 0 to 2621440000 [ 3.798590] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.801025] vde: detected capacity change from 0 to 4294967296 [ 3.828645] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.831777] vdf: detected capacity change from 0 to 4294967296 [ 3.844375] libphy: Fixed MDIO Bus: probed [ 3.851510] usbcore: registered new interface driver usbserial_generic [ 3.853402] usbserial: USB Serial support registered for generic [ 3.855735] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.860605] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.862569] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.865336] mousedev: PS/2 mouse device common for all mice [ 3.874604] rtc_cmos 00:05: RTC can wake from S4 [ 3.877585] rtc_cmos 00:05: registered as rtc0 [ 3.878117] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.881075] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.887085] intel_pstate: CPU model not supported [ 3.891242] hid: raw HID events driver (C) Jiri Kosina [ 3.894202] usbcore: registered new interface driver usbhid [ 3.896306] usbhid: USB HID core driver [ 3.897793] drop_monitor: Initializing network drop monitor service [ 3.899380] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.906972] Initializing XFRM netlink socket [ 3.907426] NET: Registered protocol family 10 [ 3.908692] Segment Routing with IPv6 [ 3.908736] NET: Registered protocol family 17 [ 3.909020] mpls_gso: MPLS GSO support [ 3.928214] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.933831] RAS: Correctable Errors collector initialized. [ 3.936189] AVX version of gcm_enc/dec engaged. [ 3.937884] AES CTR mode by8 optimization enabled [ 4.018579] sched_clock: Marking stable (4018498698, 0)->(4894924950, -876426252) [ 4.022386] registered taskstats version 1 [ 4.024399] Loading compiled-in X.509 certificates [ 4.026716] zswap: loaded using pool lzo/zbud [ 4.061505] Key type big_key registered [ 4.081678] Key type encrypted registered [ 4.083431] ima: No TPM chip found, activating TPM-bypass! [ 4.085299] ima: Allocated hash algorithm: sha1 [ 4.086854] ima: No architecture policies found [ 4.088350] evm: Initialising EVM extended attributes: [ 4.090670] evm: security.selinux [ 4.091513] evm: security.ima [ 4.092253] evm: security.capability [ 4.093557] evm: HMAC attrs: 0x1 [ 4.096652] rtc_cmos 00:05: setting system clock to 2026-09-13 01:39:22 UTC (1789263562) [ 4.104523] debug: unmapping init [mem 0xffffffffbac03000-0xffffffffbadfffff] [ 4.107599] debug: unmapping init [mem 0xffffffffb9982000-0xffffffffb9c58fff] [ 4.113123] Write protecting the kernel read-only data: 28672k [ 4.116857] debug: unmapping init [mem 0xffffffffb8003000-0xffffffffb81fffff] [ 4.120201] debug: unmapping init [mem 0xffffffffb8914000-0xffffffffb89fffff] [ 4.170886] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 4.185423] systemd[1]: Detected virtualization kvm. [ 4.187762] systemd[1]: Detected architecture x86-64. [ 4.190343] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 4.221948] systemd[1]: No hostname configured. [ 4.223889] systemd[1]: Set hostname to . [ 4.226454] random: systemd: uninitialized urandom read (16 bytes read) [ 4.230810] systemd[1]: Initializing machine ID from random generator. [ 4.340258] random: ln: uninitialized urandom read (6 bytes read) [ 4.567369] random: systemd: uninitialized urandom read (16 bytes read) [ 4.573976] systemd[1]: Listening on Journal Socket (/dev/log). [ OK ] Listening on Journal Socket (/dev/log). [ 4.597686] systemd[1]: Reached target Local File Systems. [ OK ] Reached target Local File Systems. [ 4.615261] systemd[1]: Listening on Journal Socket. [ OK ] Listening on Journal Socket. Starting Setup Virtual Console... Starting Apply Kernel Variables... Starting Journal Service... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Swap. [ OK ] Reached target Paths. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Listening on udev Control Socket. [ OK ] Reached target Slices. [ OK ] Listening on udev Kernel Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Timers. [ OK ] Reached target Initrd Root Device. Starting Create Volatile Files and Directories... [ OK ] Started Memstrack Anylazing Service. [ OK ] Started Setup Virtual Console. [ OK ] Started Apply Kernel Variables. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Create Volatile Files and Directories. 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... [ 5.767219] device-mapper: uevent: version 1.0.3 [ 5.774375] 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. [ 6.900667] virtio_net virtio0 ens2: renamed from eth0 [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting dracut initqueue hook... [ 6.953778] random: fast init done [ 7.130707] scsi host0: ata_piix [ 7.167946] scsi host1: ata_piix [ 7.169608] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 7.175786] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 11.602660] random: crng init done [ 11.604466] random: 7 urandom warning(s) missed due to ratelimiting [ 11.613163] dracut-initqueue[585]: 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... [ 13.065354] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped dracut pre-pivot and cleanup hook. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped target Timers. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Sockets. [ OK ] Stopped target Slices. [ OK ] Stopped target System Initialization. [ OK ] Stopped target Swap. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. Stopping udev Kernel Device Manager... [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped target Paths. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Closed udev Kernel Socket. [ OK ] Closed udev Control Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 14.853352] printk: systemd: 26 output lines suppressed due to ratelimiting [ 15.322595] SELinux: Disabled at runtime. [ 15.417646] 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) [ 15.431700] systemd[1]: Detected virtualization kvm. [ 15.437285] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 16.368870] systemd[1]: initrd-switch-root.service: Succeeded. [ 16.374773] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 16.384383] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 16.389694] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 16.396444] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 16.419612] systemd[1]: Starting Journal Service... Starting Journal Service... [ 16.459719] systemd[1]: Listening on Process Core Dump Socket. [ OK ] Listening on Process Core Dump Socket. [ OK ] Listening on udev Control Socket. Activating swap /dev/disk/by-label/SWAP... Starting Create list of required st…ce nodes for the current kernel... Mounting Kernel Debug File System... Mounting POSIX Message Queue File System... [ 16.557069] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd Root File System. [ OK ] Reached target rpc_pipefs.target. [ OK ] Created slice User and Session Slice. [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Reached target Slices. [ OK ] Stopped target Initrd File Systems. [ OK ] Listening on udev Kernel Socket. Mounting Huge Pages File System... [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Reached target Paths. Starting Remount Root and Kernel File Systems... Starting udev Coldplug all Devices... [ OK ] Reached target Local Encrypted Volumes. [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Listening on initctl Compatibility Named Pipe. Starting Apply Kernel Variables... [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Reached target RPC Port Mapper. [ OK ] Created slice system-getty.slice. [ OK ] Started Journal Service. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Mounted Kernel Debug File System. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Mounted Huge Pages File System. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Started Apply Kernel Variables. Starting Configure read-only root support... Starting Create Static Device Nodes in /dev... [ OK ] Reached target Swap. Starting Flush Journal to Persistent Storage... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. Starting udev Kernel Device Manager... [ OK ] Reached target Local File Systems (Pre). Mounting /mnt... Mounting /home/green/git/lustre-release... [ OK ] Started udev Coldplug all Devices. [ OK ] Mounted /mnt. [ 17.188266] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 17.713060] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 17.767646] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 17.965600] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 17.985436] EDAC sbridge: Ver: 1.1.2 [ 21.752481] Key type dns_resolver registered [ 22.430816] NFS: Registering the id_resolver key type [ 22.433476] Key type id_resolver registered [ 22.435415] Key type id_legacy registered [* ] A start job is running for Configur…-only root support (6s / no limit) [ OK ] Started Configure read-only root support. Starting Load/Save Random Seed... [ OK ] Reached target Local File Systems. Starting Rebuild Dynamic Linker Cache... Starting Mark the need to relabel after reboot... Starting Create Volatile Files and Directories... [ OK ] Started Load/Save Random Seed. [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Create Volatile Files and Directories. Starting Update UTMP about System Boot/Shutdown... Starting RPC Bind... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. [ OK ] Started irqbalance daemon. Starting Login Service... [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Started daily update of the root trust anchor for DNSSEC. Starting Restore /run/initramfs on shutdown... [ OK ] Started D-Bus System Message Bus. Starting Network Manager... [ OK ] Started dnf makecache --timer. [ OK ] Reached target Timers. [ OK ] Reached target sshd-keygen.target. [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Login Service. [ OK ] Started Network Manager. Starting Network Manager Wait Online... [ OK ] Reached target Network. Starting OpenSSH server daemon... Starting Dynamic System Tuning Daemon... Starting GSSAPI Proxy Daemon... Starting Hostname Service... [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... [ OK ] Started OpenSSH server daemon. [ OK ] Started Permit User Sessions. [ OK ] Started Command Scheduler. [ OK ] Started Serial Getty on ttyS1. [ OK ] Started Serial Getty on ttyS0. [ 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 System Logging Service... Starting Notify NFS peers of a restart... Starting Crash recovery kernel arming... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Starting Authorization Manager... [ OK ] Started Authorization Manager. [ OK ] Started Dynamic System Tuning Daemon. [ OK ] Reached target Multi-User System. [ OK ] Reached target Graphical Interface. Starting Update UTMP about System Runlevel Changes... [ OK ] Started Update UTMP about System Runlevel Changes. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg411-server login: [ 46.876037] libcfs: loading out-of-tree module taints kernel. [ 46.893358] Key type ._llcrypt registered [ 46.894679] Key type .llcrypt registered [ 46.932896] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_hostid [ 55.280877] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing load_modules_local [ 55.912516] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 55.920915] alg: No test for adler32 (adler32-zlib) [ 56.947534] Lustre: Lustre: Build Version: 2.17.57_103_g3c4c45f [ 57.302703] LNet: Added LNI 192.168.204.111@tcp [8/256/0/180] [ 58.920287] Key type lgssc registered [ 59.658784] Lustre: Echo OBD driver; http://www.lustre.org/ [ 67.377751] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 82.283846] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing load_modules_local [ 86.719669] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 86.725724] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 87.808048] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 87.819878] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 87.858290] Lustre: lustre-MDT0000: new disk, initializing [ 87.881070] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 87.887633] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 89.269211] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 94.393830] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 94.429803] Lustre: 6487: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 [ 94.440912] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 94.443986] Lustre: Skipped 1 previous similar message [ 94.478067] Lustre: lustre-MDT0001: new disk, initializing [ 94.501511] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 94.511098] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 94.516392] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 95.750777] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 97.987275] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 101.110463] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 101.188140] Lustre: lustre-OST0000: new disk, initializing [ 101.190574] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 101.192514] Lustre: 8422:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 101.207483] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 102.978541] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 103.916666] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 103.919907] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 103.944068] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 108.709606] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 108.766782] Lustre: lustre-OST0001: new disk, initializing [ 108.769433] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 108.772900] Lustre: 9499:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 108.800347] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 110.254736] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 110.258340] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 110.276979] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 110.934023] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 117.047335] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 123.740146] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 125.785047] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing check_logdir /tmp/testlogs/ [ 127.320728] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing yml_node [ 128.826090] Lustre: DEBUG MARKER: Client: 2.17.57.103 [ 129.646423] Lustre: DEBUG MARKER: MDS: 2.17.57.103 [ 130.486812] Lustre: DEBUG MARKER: OSS: 2.17.57.103 [ 131.030984] Lustre: DEBUG MARKER: -----============= acceptance-small: replay-dual ============----- Sat Sep 12 21:41:29 EDT 2026 [ 136.473091] Lustre: DEBUG MARKER: excepting tests: 14b 21b [ 137.001415] Lustre: DEBUG MARKER: skipping tests SLOW=no: 21b [ 137.547874] Lustre: DEBUG MARKER: === replay-dual: start setup 21:41:35 (1789263695) === [ 139.441715] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing check_config_client /mnt/lustre [ 145.548817] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 146.764831] Lustre: 13350:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 147.965873] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug -1 all [ 149.821135] Lustre: DEBUG MARKER: === replay-dual: finish setup 21:41:47 (1789263707) === [ 150.376682] Lustre: DEBUG MARKER: == replay-dual test 0a: expired recovery with lost client ========================================================== 21:41:48 (1789263708) [ 152.980789] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 154.283320] Lustre: Failing over lustre-MDT0000 [ 154.594195] Lustre: server umount lustre-MDT0000 complete [ 156.128922] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 156.131045] 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 [ 156.642191] 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 [ 156.647109] Lustre: Skipped 2 previous similar messages [ 161.761194] LustreError: 6499:0:(ldlm_lib.c:1190: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. [ 161.765863] LustreError: 6499:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 10 previous similar messages [ 163.275751] LustreError: 7535:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.204.11@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 163.281674] LustreError: 7535:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 1 previous similar message [ 166.881090] LustreError: 6498:0:(ldlm_lib.c:1190: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. [ 166.886698] LustreError: 6498:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 3 previous similar messages [ 169.059538] LDISKFS-fs (dm-0): 10 truncates cleaned up [ 169.061240] LDISKFS-fs (dm-0): recovery complete [ 169.066047] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 169.085717] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 169.202498] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 170.688110] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug -1 all [ 173.513817] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 174.568354] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 275.500110] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 275.503058] Lustre: 14888:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 05adea0f-c800-4bbf-a156-0865b929e16d@192.168.204.11@tcp [ 275.507175] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 275.513831] Lustre: lustre-MDT0000-osp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 275.515772] Lustre: 14888:0:(ldlm_lib.c:2976:target_recovery_thread()) too long recovery - read logs [ 275.517187] Lustre: Skipped 2 previous similar messages [ 275.522587] LustreError: dumping log to /tmp/lustre-log.1789263833.14888 [ 275.582114] Lustre: lustre-MDT0000: Recovery over after 1:42, of 3 clients 2 recovered and 1 was evicted. [ 275.601207] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:28 to 0x280000401:65) [ 275.601249] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:28 to 0x2c0000401:65) [ 290.540605] Lustre: DEBUG MARKER: == replay-dual test 0b: lost client during waiting for next transno ========================================================== 21:44:08 (1789263848) [ 293.095745] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 293.882064] Lustre: Failing over lustre-MDT0000 [ 294.000094] Lustre: server umount lustre-MDT0000 complete [ 295.395057] 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 [ 295.397058] LustreError: 6494:0:(ldlm_lib.c:1190: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. [ 295.400677] Lustre: Skipped 3 previous similar messages [ 295.407447] LustreError: 6494:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 4 previous similar messages [ 300.513142] LustreError: 7534:0:(ldlm_lib.c:1190: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. [ 300.519630] LustreError: 7534:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 4 previous similar messages [ 308.111087] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 308.112492] LDISKFS-fs (dm-0): recovery complete [ 308.115223] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 308.156614] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 308.291752] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 309.620411] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug -1 all [ 313.314044] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 313.317493] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 320.657826] Lustre: lustre-MDT0000: Denying connection for new client eb907c3a-1b69-4dd4-9bf1-a5608962e631 (at 192.168.204.11@tcp), waiting for 3 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 1:02 [ 326.089778] Lustre: lustre-MDT0000: Denying connection for new client eb907c3a-1b69-4dd4-9bf1-a5608962e631 (at 192.168.204.11@tcp), waiting for 3 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 0:57 [ 331.209713] Lustre: lustre-MDT0000: Denying connection for new client eb907c3a-1b69-4dd4-9bf1-a5608962e631 (at 192.168.204.11@tcp), waiting for 3 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 0:52 [ 336.329479] Lustre: lustre-MDT0000: Denying connection for new client eb907c3a-1b69-4dd4-9bf1-a5608962e631 (at 192.168.204.11@tcp), waiting for 3 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 0:47 [ 341.449819] Lustre: lustre-MDT0000: Denying connection for new client eb907c3a-1b69-4dd4-9bf1-a5608962e631 (at 192.168.204.11@tcp), waiting for 3 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 0:42 [ 351.690223] Lustre: lustre-MDT0000: Denying connection for new client eb907c3a-1b69-4dd4-9bf1-a5608962e631 (at 192.168.204.11@tcp), waiting for 3 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 0:31 [ 351.697686] Lustre: Skipped 1 previous similar message [ 372.180630] Lustre: lustre-MDT0000: Denying connection for new client eb907c3a-1b69-4dd4-9bf1-a5608962e631 (at 192.168.204.11@tcp), waiting for 3 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 0:11 [ 372.219148] Lustre: Skipped 3 previous similar messages [ 374.758130] Lustre: lustre-MDT0001: haven't heard from client 05adea0f-c800-4bbf-a156-0865b929e16d (at 192.168.204.11@tcp) in 103 seconds. I think it's dead, and I am evicting it. exp ffff8a28c37e0800, cur 1789263933 deadline 1789263930 last 1789263830 [ 383.517592] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 383.543308] Lustre: 16620:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 7cffa810-c026-4891-9505-b290ee84d0a8@ [ 383.555877] Lustre: lustre-MDT0000: disconnecting 2 stale clients [ 383.569720] Lustre: lustre-MDT0000: Recovery over after 1:10, of 3 clients 1 recovered and 2 were evicted. [ 383.574282] Lustre: lustre-MDT0000-osp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 383.582247] Lustre: Skipped 2 previous similar messages [ 383.604167] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:28 to 0x280000401:97) [ 383.607478] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:28 to 0x2c0000401:97) [ 399.832157] Lustre: DEBUG MARKER: == replay-dual test 1: |X| simple create ================= 21:45:56 (1789263956) [ 401.486885] hrtimer: interrupt took 7071713 ns [ 408.446781] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 408.604337] Lustre: lustre-OST0000: haven't heard from client 0e4feb27-f1ac-42b1-8b7f-1d7cfca2ec18 (at 192.168.204.11@tcp) in 101 seconds. I think it's dead, and I am evicting it. exp ffff8a29d059b800, cur 1789263967 deadline 1789263966 last 1789263866 [ 410.458533] Lustre: Failing over lustre-MDT0000 [ 410.611046] 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 [ 410.622739] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 410.628791] Lustre: Skipped 3 previous similar messages [ 410.640210] Lustre: Skipped 3 previous similar messages [ 410.861968] Lustre: server umount lustre-MDT0000 complete [ 414.194528] LustreError: 6495:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.204.11@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 414.217342] LustreError: 6495:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 6 previous similar messages [ 429.126935] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 429.129455] LDISKFS-fs (dm-0): recovery complete [ 429.136915] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 429.203321] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 429.422318] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 429.527731] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 432.147361] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug -1 all [ 434.663406] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 434.745159] Lustre: lustre-MDT0000: Recovery over after 0:05, of 3 clients 3 recovered and 0 were evicted. [ 434.770047] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:129) [ 434.770947] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:129) [ 437.840941] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 438.685420] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 444.346405] Lustre: DEBUG MARKER: == replay-dual test 2: |X| mkdir adir ==================== 21:46:41 (1789264001) [ 448.851861] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 449.813179] Lustre: Failing over lustre-MDT0000 [ 449.966790] Lustre: server umount lustre-MDT0000 complete [ 450.022829] 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 [ 450.024647] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 450.024863] LustreError: 6495:0:(ldlm_lib.c:1190: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. [ 450.024869] LustreError: 6495:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 16 previous similar messages [ 450.030419] Lustre: Skipped 1 previous similar message [ 466.400150] Lustre: 3626:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789264008/real 1789264008] req@ffff8a28c3d3ad80 x1876178884591744/t0(0) o400->MGC192.168.204.111@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789264024 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 466.417393] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 466.736817] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 466.738676] LDISKFS-fs (dm-0): recovery complete [ 466.742420] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 475.619270] LustreError: 3623:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8a28c452ea00 x1876178884600448/t0(0) o250->MGC192.168.204.111@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 [ 475.798277] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 477.152273] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 478.344561] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug -1 all [ 481.256740] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 481.260203] Lustre: Skipped 3 previous similar messages [ 481.303574] Lustre: lustre-MDT0000: Recovery over after 0:04, of 3 clients 3 recovered and 0 were evicted. [ 481.342385] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:161) [ 481.342630] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:161) [ 484.666320] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 485.701619] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 491.168985] Lustre: DEBUG MARKER: == replay-dual test 3: |X| mkdir adir, mkdir adir/bdir === 21:47:28 (1789264048) [ 495.446368] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 496.709221] Lustre: Failing over lustre-MDT0000 [ 496.852136] Lustre: server umount lustre-MDT0000 complete [ 498.145671] LustreError: 6494:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.204.11@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 498.157436] LustreError: 6494:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 44 previous similar messages [ 501.729625] 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 [ 501.731598] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 501.737665] Lustre: Skipped 4 previous similar messages [ 513.572982] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 513.575074] LDISKFS-fs (dm-0): recovery complete [ 513.580272] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 513.651424] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 514.533784] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 516.046465] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug -1 all [ 519.149460] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 519.154210] Lustre: Skipped 3 previous similar messages [ 519.216379] Lustre: lustre-MDT0000: Recovery over after 0:05, of 3 clients 3 recovered and 0 were evicted. [ 519.242074] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:193) [ 519.242480] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:193) [ 522.523520] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 523.337716] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 528.824145] Lustre: DEBUG MARKER: == replay-dual test 4: |X| mkdir adir (-EEXIST), mkdir adir/bdir ========================================================== 21:48:06 (1789264086) [ 533.578137] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 534.886850] Lustre: Failing over lustre-MDT0000 [ 535.015852] Lustre: lustre-MDT0000: Not available for connect from 192.168.204.11@tcp (stopping) [ 535.021542] Lustre: Skipped 1 previous similar message [ 535.096606] Lustre: server umount lustre-MDT0000 complete [ 539.619611] 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 [ 539.620872] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 539.634876] Lustre: Skipped 2 previous similar messages [ 553.309120] LDISKFS-fs (dm-0): 4 truncates cleaned up [ 553.311649] LDISKFS-fs (dm-0): recovery complete [ 553.320418] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 553.408681] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 553.603384] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 553.608464] Lustre: Skipped 1 previous similar message [ 555.470969] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 556.581538] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug -1 all [ 559.096448] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 559.101742] Lustre: Skipped 3 previous similar messages [ 559.199156] Lustre: lustre-MDT0000: Recovery over after 0:04, of 3 clients 3 recovered and 0 were evicted. [ 559.227174] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:225) [ 559.235763] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:225) [ 563.323608] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 564.360438] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 570.016219] Lustre: DEBUG MARKER: == replay-dual test 5: open, unlink |X| close ============ 21:48:47 (1789264127) [ 575.113089] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 576.246424] Lustre: Failing over lustre-MDT0000 [ 576.406568] Lustre: server umount lustre-MDT0000 complete [ 579.555985] 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 [ 579.557795] LustreError: 10076:0:(ldlm_lib.c:1190: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. [ 579.563338] Lustre: Skipped 3 previous similar messages [ 579.574510] LustreError: 10076:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 38 previous similar messages [ 593.913308] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 593.917662] LDISKFS-fs (dm-0): recovery complete [ 593.923635] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 594.011385] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 596.430942] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 596.654583] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug -1 all [ 599.633776] Lustre: lustre-MDT0000: Recovery over after 0:03, of 3 clients 3 recovered and 0 were evicted. [ 599.664180] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:257) [ 599.664427] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:257) [ 603.101403] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 604.052778] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 609.064134] Lustre: DEBUG MARKER: == replay-dual test 6: open1, open2, unlink |X| close1 [fail mds1] close2 ========================================================== 21:49:26 (1789264166) [ 613.346510] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 614.361812] Lustre: Failing over lustre-MDT0000 [ 614.511342] Lustre: server umount lustre-MDT0000 complete [ 614.881075] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 631.798755] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 631.800888] LDISKFS-fs (dm-0): recovery complete [ 631.807388] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 631.900201] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 632.152089] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 632.270771] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 634.756324] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug -1 all [ 637.425394] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 637.438114] Lustre: Skipped 7 previous similar messages [ 637.528750] Lustre: lustre-MDT0000: Recovery over after 0:05, of 3 clients 3 recovered and 0 were evicted. [ 637.559058] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:289) [ 637.559453] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:289) [ 640.978832] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 641.891987] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 647.333283] Lustre: DEBUG MARKER: == replay-dual test 8: replay of resent request ========== 21:50:05 (1789264205) [ 652.015235] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 652.692635] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 652.697676] LustreError: 6493:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff8a29ecb05f80 x1876178876209024/t38654705670(0) o36->eb907c3a-1b69-4dd4-9bf1-a5608962e631@192.168.204.11@tcp:292/0 lens 512/448 e 0 to 0 dl 1789264222 ref 1 fl Interpret:/200/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 669.148308] Lustre: lustre-MDT0000: Client eb907c3a-1b69-4dd4-9bf1-a5608962e631 (at 192.168.204.11@tcp) reconnecting [ 669.161653] Lustre: 9507:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff8a29fc912d80 x1876178876209024/t38654705670(0) o36->eb907c3a-1b69-4dd4-9bf1-a5608962e631@192.168.204.11@tcp:308/0 lens 512/2880 e 0 to 0 dl 1789264238 ref 1 fl Interpret:/202/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 670.831536] Lustre: Failing over lustre-MDT0000 [ 670.945964] Lustre: server umount lustre-MDT0000 complete [ 673.250525] 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 [ 673.265444] Lustre: Skipped 7 previous similar messages [ 688.232986] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 688.235694] LDISKFS-fs (dm-0): recovery complete [ 688.241415] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 688.541933] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 688.545516] Lustre: Skipped 2 previous similar messages [ 688.574257] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 690.766583] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug -1 all [ 693.810780] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:321) [ 693.810829] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:321) [ 697.040430] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 697.967695] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 703.271721] Lustre: DEBUG MARKER: == replay-dual test 9: resending a replayed create ======= 21:51:00 (1789264260) [ 707.590406] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 709.288525] Lustre: Failing over lustre-MDT0000 [ 709.422426] Lustre: server umount lustre-MDT0000 complete [ 714.192760] LustreError: 7535:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.204.11@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 714.209842] LustreError: 7535:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 54 previous similar messages [ 714.213061] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 728.219533] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 728.223104] LDISKFS-fs (dm-0): recovery complete [ 728.230965] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 728.330712] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 728.337348] LustreError: Skipped 1 previous similar message [ 728.581265] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 729.549925] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 729.555422] Lustre: Skipped 1 previous similar message [ 731.271310] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug -1 all [ 733.711086] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 733.715726] LustreError: 32074:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff8a29fc61b100 x1876178876223744/t42949672962(42949672962) o36->eb907c3a-1b69-4dd4-9bf1-a5608962e631@192.168.204.11@tcp:368/0 lens 528/448 e 0 to 0 dl 1789264298 ref 1 fl Complete:/204/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 745.953291] Lustre: lustre-MDT0000: Client eb907c3a-1b69-4dd4-9bf1-a5608962e631 (at 192.168.204.11@tcp) reconnected, waiting for 3 clients in recovery for 1:28 [ 746.007813] Lustre: lustre-MDT0000: Recovery over after 0:17, of 3 clients 3 recovered and 0 were evicted. [ 746.015495] Lustre: Skipped 1 previous similar message [ 746.037467] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:353) [ 746.037581] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:353) [ 749.305829] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 750.148912] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 755.516309] Lustre: DEBUG MARKER: == replay-dual test 10: resending a replayed unlink ====== 21:51:53 (1789264313) [ 760.179128] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 761.949313] Lustre: Failing over lustre-MDT0000 [ 762.098321] Lustre: server umount lustre-MDT0000 complete [ 778.625398] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 778.629093] LDISKFS-fs (dm-0): recovery complete [ 778.636336] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 778.889737] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 781.051185] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug -1 all [ 784.363453] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 784.369509] Lustre: Skipped 11 previous similar messages [ 784.391481] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 784.394993] LustreError: 34127:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff8a29fc961180 x1876178876239872/t47244640260(47244640260) o36->eb907c3a-1b69-4dd4-9bf1-a5608962e631@192.168.204.11@tcp:423/0 lens 528/448 e 0 to 0 dl 1789264353 ref 1 fl Complete:/204/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 800.169930] Lustre: lustre-MDT0000: Client eb907c3a-1b69-4dd4-9bf1-a5608962e631 (at 192.168.204.11@tcp) reconnected, waiting for 3 clients in recovery for 1:24 [ 800.235361] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:385) [ 800.235623] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:385) [ 803.262893] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 804.073194] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 809.211475] Lustre: DEBUG MARKER: == replay-dual test 11: both clients timeout during replay ========================================================== 21:52:47 (1789264367) [ 813.010392] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 814.714165] Lustre: Failing over lustre-MDT0000 [ 814.858674] Lustre: server umount lustre-MDT0000 complete [ 815.077784] 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 [ 815.085036] Lustre: Skipped 11 previous similar messages [ 831.456526] Lustre: 3626:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789264373/real 1789264373] req@ffff8a29dfc68380 x1876178884848128/t0(0) o400->MGC192.168.204.111@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789264389 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 831.510053] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 831.511722] LDISKFS-fs (dm-0): recovery complete [ 831.517114] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 840.673022] LustreError: 3623:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8a29f4480000 x1876178884856576/t0(0) o250->MGC192.168.204.111@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 [ 840.839359] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 842.926862] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug -1 all [ 846.344421] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 846.348425] LustreError: 36183:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff8a29f79a3100 x1876178876256000/t51539607554(51539607554) o36->eb907c3a-1b69-4dd4-9bf1-a5608962e631@192.168.204.11@tcp:482/0 lens 528/448 e 0 to 0 dl 1789264412 ref 1 fl Complete:/204/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 847.229802] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 859.098425] Lustre: lustre-MDT0000: Client eb907c3a-1b69-4dd4-9bf1-a5608962e631 (at 192.168.204.11@tcp) reconnected, waiting for 3 clients in recovery for 1:27 [ 859.182830] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:417) [ 859.186339] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:417) [ 860.825867] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 12 sec [ 865.448372] Lustre: DEBUG MARKER: == replay-dual test 12: open resend timeout ============== 21:53:42 (1789264422) [ 869.770084] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 871.285443] Lustre: Failing over lustre-MDT0000 [ 871.438668] Lustre: server umount lustre-MDT0000 complete [ 887.693836] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 887.697600] LDISKFS-fs (dm-0): recovery complete [ 887.705789] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 887.797975] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 887.805591] LustreError: Skipped 2 previous similar messages [ 887.971694] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 888.266071] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 888.270046] Lustre: Skipped 2 previous similar messages [ 889.909707] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug -1 all [ 893.513724] Lustre: lustre-MDT0000: Recovery over after 0:05, of 3 clients 3 recovered and 0 were evicted. [ 893.522888] Lustre: Skipped 2 previous similar messages [ 893.548054] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:449) [ 893.548935] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:449) [ 897.357260] Lustre: DEBUG MARKER: == replay-dual test 13: close resend timeout ============= 21:54:15 (1789264455) [ 901.431084] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 902.760906] Lustre: Failing over lustre-MDT0000 [ 902.978255] Lustre: server umount lustre-MDT0000 complete [ 903.652885] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 918.643246] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 918.644960] LDISKFS-fs (dm-0): recovery complete [ 918.650189] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 918.866144] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 920.608864] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug -1 all [ 924.227182] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:481) [ 924.229418] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:481) [ 927.456449] Lustre: DEBUG MARKER: SKIP: replay-dual test_14b skipping ALWAYS excluded test 14b [ 928.373692] Lustre: DEBUG MARKER: == replay-dual test 15a: timeout waiting for lost client during replay, 1 client completes ========================================================== 21:54:46 (1789264486) [ 932.220453] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 933.800164] Lustre: Failing over lustre-MDT0000 [ 934.007286] Lustre: server umount lustre-MDT0000 complete [ 949.728158] Lustre: 3627:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789264492/real 1789264492] req@ffff8a29fc9dad80 x1876178884929664/t0(0) o400->MGC192.168.204.111@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789264508 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 950.059665] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 950.062278] LDISKFS-fs (dm-0): recovery complete [ 950.068604] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 959.971162] LustreError: 3623:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8a28c37d7800 x1876178884937984/t0(0) o250->MGC192.168.204.111@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 [ 960.121187] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 960.126853] Lustre: Skipped 5 previous similar messages [ 960.163175] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 961.924150] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug -1 all [ 1030.500365] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 1030.504039] Lustre: 41815:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client e6dcef1a-28f7-4858-a989-335d24402936@ [ 1030.512584] Lustre: 41815:0:(genops.c:1601:class_disconnect_stale_exports()) Skipped 1 previous similar message [ 1030.517206] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 1030.883684] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:495 to 0x2c0000401:513) [ 1030.883829] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:494 to 0x280000401:513) [ 1034.018861] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1034.850842] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1040.369696] Lustre: DEBUG MARKER: == replay-dual test 15c: remove multiple OST orphans ===== 21:56:38 (1789264598) [ 1044.499610] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1106.957208] Lustre: Failing over lustre-MDT0000 [ 1107.194349] Lustre: server umount lustre-MDT0000 complete [ 1107.936974] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1107.943036] LustreError: Skipped 1 previous similar message [ 1107.946098] 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 [ 1107.953427] Lustre: Skipped 12 previous similar messages [ 1107.956604] LustreError: 6499:0:(ldlm_lib.c:1190: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. [ 1107.964988] LustreError: 6499:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 143 previous similar messages [ 1123.486139] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1123.488054] LDISKFS-fs (dm-0): recovery complete [ 1123.492859] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1123.755053] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1125.779792] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug -1 all [ 1128.938504] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1128.941155] Lustre: Skipped 19 previous similar messages [ 1194.500214] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 1194.506268] Lustre: 43822:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 4eaff1d9-7920-47a8-95f9-12e63ad62b89@ [ 1194.511786] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 1194.556602] Lustre: lustre-MDT0000: Recovery over after 1:10, of 3 clients 2 recovered and 1 was evicted. [ 1194.562277] Lustre: Skipped 2 previous similar messages [ 1194.580993] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:494 to 0x280000401:1537) [ 1194.581675] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:495 to 0x2c0000401:1537) [ 1197.685584] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1198.486457] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1203.213879] Lustre: DEBUG MARKER: == replay-dual test 16: fail MDS during recovery (3571) == 21:59:21 (1789264761) [ 1206.934800] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1208.513486] Lustre: Failing over lustre-MDT0000 [ 1208.688699] Lustre: server umount lustre-MDT0000 complete [ 1209.827544] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1224.544439] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1224.547842] LDISKFS-fs (dm-0): recovery complete [ 1224.554681] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1224.626455] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1224.630816] LustreError: Skipped 3 previous similar messages [ 1225.574264] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 1225.582373] Lustre: Skipped 3 previous similar messages [ 1226.752797] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug -1 all [ 1248.755558] Lustre: Failing over lustre-MDT0000 [ 1248.763977] LustreError: 46259:0:(ldlm_lib.c:3029:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 1248.767842] Lustre: 45786:0:(ldlm_lib.c:2429:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 1248.772360] Lustre: 45786:0:(ldlm_lib.c:1939:abort_req_replay_queue()) @@@ aborted: req@ffff8a28c5161180 x1876178878692224/t0(73014444033) o36->eb907c3a-1b69-4dd4-9bf1-a5608962e631@192.168.204.11@tcp:134/0 lens 528/0 e 2 to 0 dl 1789264819 ref 1 fl Complete:/204/ffffffff rc 0/-1 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 1248.782636] Lustre: lustre-MDT0000-osd: cancel update llog [0x200000400:0x1:0x0] [ 1248.793362] Lustre: lustre-MDT0001-osp-MDT0000: cancel update llog [0x240000401:0x1:0x0] [ 1248.798285] LustreError: 45786:0:(client.c:1394:ptlrpc_import_delay_req()) @@@ IMP_CLOSED req@ffff8a29fc41aa00 x1876178885099008/t0(0) o1000->lustre-MDT0001-osp-MDT0000@0@lo:24/4 lens 336/33016 e 0 to 0 dl 0 ref 2 fl Rpc:QU/200/ffffffff rc 0/-1 job:'tgt_recover_0.0' uid:0 gid:0 projid:4294967295 [ 1248.799190] Lustre: lustre-MDT0000: Not available for connect from 192.168.204.11@tcp (stopping) [ 1248.810279] LustreError: 45786:0:(llog_osd.c:1178:llog_osd_next_block()) lustre-MDT0001-osp-MDT0000: can't read llog block from log [0x240000401:0x1:0x0] offset 32768: rc = -5 [ 1248.821730] LustreError: 45786:0:(llog.c:875:llog_process_thread()) lustre-MDT0001-osp-MDT0000 retry remote llog process [ 1248.826720] LustreError: 45786:0:(fid_request.c:217:seq_client_alloc_seq()) cli-cli-lustre-MDT0001-osp-MDT0000: Cannot allocate new meta-sequence: rc = -5 [ 1248.834604] LustreError: 45786:0:(fid_request.c:321:seq_client_alloc_fid()) cli-cli-lustre-MDT0001-osp-MDT0000: Can't allocate new sequence: rc = -5 [ 1248.993728] Lustre: server umount lustre-MDT0000 complete [ 1262.853097] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1263.139301] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1263.143858] Lustre: Skipped 1 previous similar message [ 1265.072271] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug -1 all [ 1270.240443] Lustre: 3623:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789264788/real 1789264788] req@ffff8a28c5161500 x1876178885091968/t0(0) o400->lustre-MDT0000-osp-MDT0001@0@lo:24/4 lens 224/224 e 2 to 1 dl 1789264828 ref 1 fl Rpc:XQr/2c0/ffffffff rc 0/-1 job:'ldlm_lock_repla.0' uid:0 gid:0 projid:4294967295 [ 1334.500504] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 1334.502887] Lustre: 46714:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 8e5386b7-4d4c-4158-9f41-4c05d244970d@ [ 1334.508136] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 1334.927529] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1550 to 0x280000401:1569) [ 1334.927659] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1551 to 0x2c0000401:1569) [ 1337.907796] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1338.656760] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1343.812331] Lustre: DEBUG MARKER: == replay-dual test 17: fail OST during recovery (3571) == 22:01:41 (1789264901) [ 1347.647600] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 1348.522660] Lustre: Failing over lustre-OST0000 [ 1348.583941] Lustre: server umount lustre-OST0000 complete [ 1350.625886] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 1350.632156] LustreError: Skipped 1 previous similar message [ 1364.998404] LDISKFS-fs (dm-2): 3 truncates cleaned up [ 1365.000459] LDISKFS-fs (dm-2): recovery complete [ 1365.008409] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 1368.132491] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug -1 all [ 1391.217689] Lustre: Failing over lustre-OST0000 [ 1391.239615] LustreError: 49240:0:(ldlm_lib.c:3029:target_stop_recovery_thread()) lustre-OST0000: Aborting recovery [ 1391.250214] Lustre: 48675:0:(ldlm_lib.c:2429:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 1391.259611] Lustre: 48675:0:(ldlm_lib.c:2429:target_recovery_overseer()) Skipped 2 previous similar messages [ 1391.267267] LustreError: 48675:0:(ofd_obd.c:1325:ofd_iocontrol()) lustre-OST0000: iocontrol from 'tgt_recover_0' cmd=c00866c1 _IOWR('f', 193, 8) unrecognized: rc = -25 [ 1391.434939] Lustre: server umount lustre-OST0000 complete [ 1407.458032] Lustre: 3623:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789264924/real 1789264924] req@ffff8a29f1028700 x1876178885165952/t0(0) o400->lustre-OST0000-osc-MDT0001@0@lo:28/4 lens 224/224 e 2 to 1 dl 1789264965 ref 1 fl Rpc:XQr/2c0/ffffffff rc 0/-1 job:'ldlm_lock_repla.0' uid:0 gid:0 projid:4294967295 [ 1414.333523] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 1424.318863] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug -1 all [ 1486.501332] Lustre: lustre-OST0000: recovery is timed out, evict stale exports [ 1486.508055] Lustre: 49680:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-OST0000: disconnect stale client 6e44a369-368b-4263-a052-7ace1b874a53@ [ 1486.513505] Lustre: lustre-OST0000: disconnecting 1 stale clients [ 1494.229205] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 1497.284160] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 1512.712277] Lustre: DEBUG MARKER: == replay-dual test 18: ldlm_handle_enqueue succeeds on evicted export (3822) ========================================================== 22:04:28 (1789265068) [ 1518.101087] LustreError: 7535:0:(ldlm_lockd.c:1361:ldlm_handle_enqueue()) cfs_fail_timeout id 30b sleeping for 40000ms [ 1558.192205] LustreError: 7535:0:(ldlm_lockd.c:1361:ldlm_handle_enqueue()) cfs_fail_timeout id 30b awake [ 1576.139439] Lustre: DEBUG MARKER: == replay-dual test 19: resend of open request =========== 22:05:32 (1789265132) [ 1584.796283] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1586.260717] Lustre: *** cfs_fail_loc=157, val=2147483648*** [ 1586.270043] LustreError: 6494:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff8a28cb530000 x1876178878812928/t0(0) o101->eb907c3a-1b69-4dd4-9bf1-a5608962e631@192.168.204.11@tcp:540/0 lens 576/688 e 0 to 0 dl 1789265225 ref 1 fl Interpret:/600/0 rc 0/0 job:'createmany.0' uid:0 gid:0 projid:0 [ 1672.146763] Lustre: lustre-MDT0000: Client eb907c3a-1b69-4dd4-9bf1-a5608962e631 (at 192.168.204.11@tcp) reconnecting [ 1675.811868] Lustre: Failing over lustre-MDT0000 [ 1676.076108] Lustre: server umount lustre-MDT0000 complete [ 1677.280874] LustreError: 6494:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.204.11@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1677.296341] LustreError: 6494:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 59 previous similar messages [ 1678.308160] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1678.313575] 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 [ 1678.327664] Lustre: Skipped 15 previous similar messages [ 1693.665715] Lustre: 3626:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789265236/real 1789265236] req@ffff8a29f7b5c000 x1876178885312000/t0(0) o400->MGC192.168.204.111@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789265252 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1693.703668] Lustre: 3626:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 1699.343409] LDISKFS-fs (dm-0): 4 truncates cleaned up [ 1699.345574] LDISKFS-fs (dm-0): recovery complete [ 1699.360574] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1703.908648] LustreError: 3623:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8a29f7724000 x1876178885319424/t0(0) o250->MGC192.168.204.111@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 [ 1704.286381] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1704.294681] Lustre: Skipped 5 previous similar messages [ 1704.346645] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1704.360968] Lustre: Skipped 2 previous similar messages [ 1709.122777] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug -1 all [ 1709.549250] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1709.569721] Lustre: Skipped 12 previous similar messages [ 1709.650343] Lustre: 52331:0:(ldlm_lib.c:2110:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 1709.798127] Lustre: lustre-MDT0000: Recovery over after 0:04, of 3 clients 3 recovered and 0 were evicted. [ 1709.808032] Lustre: Skipped 4 previous similar messages [ 1709.852600] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1584 to 0x280000401:1601) [ 1709.870802] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1584 to 0x2c0000401:1601) [ 1721.218423] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1723.180714] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1733.518826] Lustre: DEBUG MARKER: == replay-dual test 20: recovery time is not increasing == 22:08:10 (1789265290) [ 1742.098710] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1744.532910] Lustre: Failing over lustre-MDT0000 [ 1744.911635] Lustre: server umount lustre-MDT0000 complete [ 1760.736165] Lustre: 3625:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789265303/real 1789265303] req@ffff8a29f10db480 x1876178885352064/t0(0) o400->MGC192.168.204.111@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789265319 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1760.804188] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1760.816182] LustreError: Skipped 2 previous similar messages [ 1769.871474] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1769.873695] LDISKFS-fs (dm-0): recovery complete [ 1769.887112] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1772.523599] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 1772.542924] Lustre: Skipped 4 previous similar messages [ 1777.417447] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug -1 all [ 1912.500167] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 1912.519726] Lustre: 54272:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client ab31d110-1806-4e43-98db-98dc0023f837@ [ 1912.536604] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 1912.648724] Lustre: 54272:0:(ldlm_lib.c:2110:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 1912.668939] Lustre: 54272:0:(ldlm_lib.c:2110:extend_recovery_timer()) Skipped 6 previous similar messages [ 1912.821485] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1603 to 0x2c0000401:1633) [ 1912.822053] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1584 to 0x280000401:1633) [ 1920.230225] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1922.204318] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1931.778583] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1934.112502] Lustre: Failing over lustre-MDT0000 [ 1934.373246] Lustre: server umount lustre-MDT0000 complete [ 1950.689113] Lustre: 3626:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789265493/real 1789265493] req@ffff8a29c12ea680 x1876178885435520/t0(0) o400->MGC192.168.204.111@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789265509 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1954.463385] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1954.469782] LDISKFS-fs (dm-0): recovery complete [ 1954.475882] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1965.370724] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug -1 all [ 2101.501287] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 2101.513813] Lustre: 56059:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 64109ad6-9ce4-4993-91f5-d95a8c3e66d2@ [ 2101.526399] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 2101.612073] Lustre: 56059:0:(ldlm_lib.c:2110:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 2101.633993] Lustre: 56059:0:(ldlm_lib.c:2110:extend_recovery_timer()) Skipped 4 previous similar messages [ 2101.822872] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1584 to 0x280000401:1665) [ 2101.824849] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1635 to 0x2c0000401:1665) [ 2108.903407] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2110.443505] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2119.816835] Lustre: DEBUG MARKER: == replay-dual test 21a: commit on sharing =============== 22:14:36 (1789265676) [ 2128.655465] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2130.976142] Lustre: Failing over lustre-MDT0000 [ 2131.207123] Lustre: server umount lustre-MDT0000 complete [ 2151.918497] Lustre: 3626:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789265693/real 1789265693] req@ffff8a29f443f480 x1876178885523200/t0(0) o400->MGC192.168.204.111@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789265709 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2156.252567] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2156.258736] LDISKFS-fs (dm-0): recovery complete [ 2156.271256] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2169.371523] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug -1 all [ 2304.500817] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 2304.510282] Lustre: 58089:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 8457dc7b-c2d3-431f-963b-0602d030b967@ [ 2304.527765] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 2304.581534] Lustre: 58089:0:(ldlm_lib.c:2110:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 2304.594759] Lustre: 58089:0:(ldlm_lib.c:2110:extend_recovery_timer()) Skipped 4 previous similar messages [ 2304.665108] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1635 to 0x2c0000401:1697) [ 2304.665948] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1667 to 0x280000401:1697) [ 2314.173520] Lustre: DEBUG MARKER: SKIP: replay-dual test_21b skipping SLOW test 21b [ 2315.657554] Lustre: DEBUG MARKER: == replay-dual test 22a: c1 lfs mkdir -i 1 dir1, M1 drop reply [ 2316.873077] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 2316.877630] LustreError: 10076:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff8a29f446a680 x1876178878934528/t4294967341(0) o36->eb907c3a-1b69-4dd4-9bf1-a5608962e631@192.168.204.11@tcp:515/0 lens 560/448 e 0 to 0 dl 1789265955 ref 1 fl Interpret:/200/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 2319.350676] Lustre: Failing over lustre-MDT0001 [ 2319.662300] Lustre: server umount lustre-MDT0001 complete [ 2320.873614] LustreError: 9507:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 192.168.204.11@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 2320.897635] LustreError: 9507:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 134 previous similar messages [ 2322.408767] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 2322.415243] Lustre: lustre-MDT0001-osp-MDT0000: Connection to lustre-MDT0001 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 2322.418360] LustreError: Skipped 1 previous similar message [ 2322.433699] Lustre: Skipped 12 previous similar messages [ 2338.521606] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2338.927076] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 2338.933741] Lustre: Skipped 3 previous similar messages [ 2338.975818] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 2338.988437] Lustre: Skipped 3 previous similar messages [ 2344.203680] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug -1 all [ 2344.445827] Lustre: lustre-MDT0001-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 2344.454612] Lustre: Skipped 15 previous similar messages [ 2344.506937] Lustre: lustre-MDT0001: Recovery over after 0:04, of 3 clients 3 recovered and 0 were evicted. [ 2344.528314] Lustre: Skipped 3 previous similar messages [ 2344.562469] Lustre: 6495:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff8a29c7d03480 x1876178878934528/t4294967341(0) o36->eb907c3a-1b69-4dd4-9bf1-a5608962e631@192.168.204.11@tcp:542/0 lens 560/2880 e 0 to 0 dl 1789265982 ref 1 fl Interpret:/202/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 2354.539031] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 2356.493591] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2366.593724] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2369.074414] Lustre: Failing over lustre-MDT0000 [ 2369.446455] Lustre: server umount lustre-MDT0000 complete [ 2386.385365] Lustre: 3626:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789265928/real 1789265928] req@ffff8a29ea204700 x1876178885635584/t0(0) o400->MGC192.168.204.111@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789265944 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2386.439084] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2386.447881] LustreError: Skipped 2 previous similar messages [ 2395.234362] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2395.236363] LDISKFS-fs (dm-0): recovery complete [ 2395.271989] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2395.617751] LustreError: 3623:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8a28cadf6a00 x1876178885643776/t0(0) o250->MGC192.168.204.111@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 [ 2396.630146] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 2396.641618] Lustre: Skipped 3 previous similar messages [ 2400.070772] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug -1 all [ 2401.322743] Lustre: 61155:0:(ldlm_lib.c:2110:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 2401.408835] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1667 to 0x280000401:1729) [ 2401.412815] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1635 to 0x2c0000401:1729) [ 2410.028936] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2411.901212] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2419.840171] Lustre: DEBUG MARKER: == replay-dual test 22b: c1 lfs mkdir -i 1 d1, M1 drop reply [ 2421.124779] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 2421.131885] LustreError: 9507:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff8a29d09ff100 x1876178878973696/t8589934617(0) o36->eb907c3a-1b69-4dd4-9bf1-a5608962e631@192.168.204.11@tcp:619/0 lens 560/448 e 0 to 0 dl 1789266059 ref 1 fl Interpret:/200/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 2423.756321] Lustre: Failing over lustre-MDT0000 [ 2424.100989] Lustre: server umount lustre-MDT0000 complete [ 2427.649636] LustreError: 10373:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1789265986 with bad export cookie 5228480209349328818 [ 2427.667143] Lustre: Failing over lustre-MDT0001 [ 2427.674726] LustreError: 10373:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 2427.705916] LustreError: 62298:0:(client.c:1394:ptlrpc_import_delay_req()) @@@ IMP_CLOSED req@ffff8a29fcc70700 x1876178885678592/t0(0) o1000->lustre-MDT0000-osp-MDT0001@0@lo:24/4 lens 304/4320 e 0 to 0 dl 0 ref 2 fl Rpc:QU/200/ffffffff rc 0/-1 job:'umount.0' uid:0 gid:0 projid:4294967295 [ 2427.723416] LustreError: 62298:0:(client.c:1394:ptlrpc_import_delay_req()) Skipped 1 previous similar message [ 2427.730382] LustreError: 62298:0:(osp_object.c:618:osp_attr_get()) lustre-MDT0000-osp-MDT0001: osp_attr_get update error [0x200000401:0x1:0x0]: rc = -5 [ 2428.211271] Lustre: server umount lustre-MDT0001 complete [ 2449.876853] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2450.178543] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2453.475642] LustreError: 3623:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8a29ed72c380 x1876178885681152/t0(0) o250->MGC192.168.204.111@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 [ 2459.472833] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug -1 all [ 2459.946495] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug -1 all [ 2460.010131] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:36 to 0x2c0000400:65) [ 2460.029676] Lustre: 63020:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff8a29c556ce00 x1876178878973696/t8589934617(0) o36->eb907c3a-1b69-4dd4-9bf1-a5608962e631@192.168.204.11@tcp:658/0 lens 560/2880 e 0 to 0 dl 1789266098 ref 1 fl Interpret:/202/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 2460.064678] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:36 to 0x280000400:65) [ 2467.079101] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1667 to 0x280000401:1761) [ 2467.082283] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1635 to 0x2c0000401:1761) [ 2473.923229] Lustre: DEBUG MARKER: oleg411-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 [ 2475.969408] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2477.442684] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2486.638626] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2489.266657] Lustre: Failing over lustre-MDT0000 [ 2489.649953] Lustre: server umount lustre-MDT0000 complete [ 2515.080192] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2515.083502] LDISKFS-fs (dm-0): recovery complete [ 2515.098618] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2518.505773] LustreError: 3623:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8a29ed72d880 x1876178885729408/t0(0) o250->MGC192.168.204.111@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 [ 2524.107421] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug -1 all [ 2524.223570] Lustre: 65224:0:(ldlm_lib.c:2110:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 2524.240783] Lustre: 65224:0:(ldlm_lib.c:2110:extend_recovery_timer()) Skipped 4 previous similar messages [ 2524.374815] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1667 to 0x280000401:1793) [ 2524.375592] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1635 to 0x2c0000401:1793) [ 2534.300705] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2535.904759] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2545.767600] Lustre: DEBUG MARKER: == replay-dual test 22c: c1 lfs mkdir -i 1 d1, M1 drop update [ 2547.120303] Lustre: *** cfs_fail_loc=1701, val=2147483648*** [ 2547.123721] LustreError: 8417:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff8a29d0cd5880 x1876178885758592/t107374182411(0) o1000->lustre-MDT0001-mdtlov_UUID@0@lo:676/0 lens 2520/4320 e 0 to 0 dl 1789266116 ref 1 fl Interpret:/200/0 rc 0/0 job:'osp_up0-1.0' uid:0 gid:0 projid:4294967295 [ 2550.707535] Lustre: Failing over lustre-MDT0000 [ 2550.995305] Lustre: server umount lustre-MDT0000 complete [ 2570.646056] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2580.966264] LustreError: 3623:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8a29dfc22680 x1876178885770112/t0(0) o250->MGC192.168.204.111@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 [ 2586.762647] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1667 to 0x280000401:1825) [ 2586.766467] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1635 to 0x2c0000401:1825) [ 2587.279275] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug -1 all [ 2597.646622] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2599.609840] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2610.093552] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2612.558471] Lustre: Failing over lustre-MDT0000 [ 2612.703684] Lustre: lustre-MDT0000: Not available for connect from 192.168.204.11@tcp (stopping) [ 2612.712043] Lustre: Skipped 2 previous similar messages [ 2612.939805] Lustre: server umount lustre-MDT0000 complete [ 2635.232686] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2635.239285] LDISKFS-fs (dm-0): recovery complete [ 2635.249824] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2642.935045] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x488f4b0c796d5daa [ 2647.760389] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug -1 all [ 2648.637975] Lustre: 68412:0:(ldlm_lib.c:2110:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 2648.659579] Lustre: 68412:0:(ldlm_lib.c:2110:extend_recovery_timer()) Skipped 4 previous similar messages [ 2648.765138] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1635 to 0x2c0000401:1857) [ 2648.768133] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1667 to 0x280000401:1857) [ 2656.738731] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2657.998747] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2666.618452] Lustre: DEBUG MARKER: == replay-dual test 22d: c1 lfs mkdir -i 1 d1, M1 drop update [ 2671.047483] Lustre: *** cfs_fail_loc=1701, val=2147483648*** [ 2671.049940] LustreError: 8416:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff8a29d0cd7800 x1876178885840000/t115964117001(0) o1000->lustre-MDT0001-mdtlov_UUID@0@lo:45/0 lens 2520/4320 e 0 to 0 dl 1789266240 ref 1 fl Interpret:/200/0 rc 0/0 job:'osp_up0-1.0' uid:0 gid:0 projid:4294967295 [ 2674.271619] Lustre: Failing over lustre-MDT0000 [ 2674.700429] Lustre: server umount lustre-MDT0000 complete [ 2678.735310] LustreError: 6523:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1789266237 with bad export cookie 5228480209349336490 [ 2678.743740] Lustre: Failing over lustre-MDT0001 [ 2678.749575] LustreError: 6523:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 2678.765127] LustreError: 69650:0:(ldlm_resource.c:1207:ldlm_resource_complain()) lustre-MDT0000-osp-MDT0001: namespace resource [0x2000013a1:0x78:0x0].0xf7117594 (ffff8a29ea1eb200) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 2678.822152] Lustre: lustre-MDT0001: Not available for connect from 192.168.204.11@tcp (stopping) [ 2683.298507] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 2683.309327] Lustre: Skipped 5 previous similar messages [ 2685.136037] Lustre: server umount lustre-MDT0001 complete [ 2704.972140] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2704.980423] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2705.214508] LustreError: 70362:0:(llog.c:1655:llog_backup()) MGC192.168.204.111@tcp: failed to open log lustre-sptlrpc: rc = -108 [ 2705.220662] Lustre: 70362:0:(mgc_request_server.c:770:mgc_llog_local_copy()) MGC192.168.204.111@tcp: failed to copy new config lustre-sptlrpc: rc = -108 [ 2729.925026] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug -1 all [ 2730.645953] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1667 to 0x280000401:1889) [ 2730.651406] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1635 to 0x2c0000401:1889) [ 2730.856432] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:70 to 0x280000400:97) [ 2730.857220] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:70 to 0x2c0000400:97) [ 2730.872904] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug -1 all [ 2730.878983] Lustre: 70369:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff8a29f0c02d80 x1876178879062144/t12884901939(0) o36->eb907c3a-1b69-4dd4-9bf1-a5608962e631@192.168.204.11@tcp:174/0 lens 560/2880 e 0 to 0 dl 1789266369 ref 1 fl Interpret:/202/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 2743.164018] Lustre: DEBUG MARKER: oleg411-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 [ 2744.920366] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2746.441098] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2757.394582] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2760.559930] Lustre: Failing over lustre-MDT0000 [ 2760.981570] Lustre: server umount lustre-MDT0000 complete [ 2778.081275] Lustre: 3626:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789266319/real 1789266319] req@ffff8a28cb77ad80 x1876178885885824/t0(0) o400->MGC192.168.204.111@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789266335 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2778.120803] Lustre: 3626:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 20 previous similar messages [ 2784.746678] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2784.750383] LDISKFS-fs (dm-0): recovery complete [ 2784.761263] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2788.321424] LustreError: 3623:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8a29c7ca1500 x1876178885894656/t0(0) o250->MGC192.168.204.111@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 [ 2791.974831] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug -1 all [ 2794.020816] Lustre: 72583:0:(ldlm_lib.c:2110:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 2794.032953] Lustre: 72583:0:(ldlm_lib.c:2110:extend_recovery_timer()) Skipped 4 previous similar messages [ 2794.151639] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1667 to 0x280000401:1921) [ 2794.152552] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1635 to 0x2c0000401:1921) [ 2801.151211] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2802.814028] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2812.107897] Lustre: DEBUG MARKER: == replay-dual test 23a: c1 rmdir d1, M1 drop reply and fail, client2 mkdir d1 ========================================================== 22:26:09 (1789266369) [ 2813.342280] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 2813.345051] LustreError: 71160:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff8a29ecb05f80 x1876178879109504/t17179869210(0) o36->eb907c3a-1b69-4dd4-9bf1-a5608962e631@192.168.204.11@tcp:256/0 lens 496/456 e 0 to 0 dl 1789266451 ref 1 fl Interpret:/200/0 rc 0/0 job:'rmdir.0' uid:0 gid:0 projid:4294967295 [ 2816.715891] Lustre: Failing over lustre-MDT0001 [ 2819.560191] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 2819.569423] Lustre: Skipped 4 previous similar messages [ 2823.371075] Lustre: server umount lustre-MDT0001 complete [ 2841.472587] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2846.133287] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug -1 all [ 2847.282057] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:100 to 0x280000400:129) [ 2847.291509] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:100 to 0x2c0000400:129) [ 2847.297277] Lustre: 70374:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff8a28c56b2a00 x1876178879109504/t17179869210(0) o36->eb907c3a-1b69-4dd4-9bf1-a5608962e631@192.168.204.11@tcp:290/0 lens 496/2888 e 0 to 0 dl 1789266485 ref 1 fl Interpret:/202/0 rc 0/0 job:'rmdir.0' uid:0 gid:0 projid:4294967295 [ 2854.543462] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 2856.331683] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2865.630671] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2868.122805] Lustre: Failing over lustre-MDT0000 [ 2868.489305] Lustre: server umount lustre-MDT0000 complete [ 2892.323683] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2892.325483] LDISKFS-fs (dm-0): recovery complete [ 2892.329648] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2899.426217] LustreError: 3623:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8a29c83c5180 x1876178885968000/t0(0) o250->MGC192.168.204.111@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 [ 2903.621368] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug -1 all [ 2905.183907] Lustre: 75758:0:(ldlm_lib.c:2110:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 2905.197568] Lustre: 75758:0:(ldlm_lib.c:2110:extend_recovery_timer()) Skipped 4 previous similar messages [ 2905.407607] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1923 to 0x280000401:1953) [ 2905.407644] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1923 to 0x2c0000401:1953) [ 2913.309837] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2915.039958] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2924.917900] Lustre: DEBUG MARKER: == replay-dual test 23b: c1 rmdir d1, M1 drop reply and fail M0/M1, c2 mkdir d1 ========================================================== 22:28:01 (1789266481) [ 2926.536617] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 2926.550173] LustreError: 70373:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff8a29d0565f80 x1876178879146752/t21474836483(0) o36->eb907c3a-1b69-4dd4-9bf1-a5608962e631@192.168.204.11@tcp:369/0 lens 496/456 e 0 to 0 dl 1789266564 ref 1 fl Interpret:/200/0 rc 0/0 job:'rmdir.0' uid:0 gid:0 projid:4294967295 [ 2930.269153] Lustre: Failing over lustre-MDT0000 [ 2930.304435] LustreError: 9498:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1789266488 with bad export cookie 5228480209349343854 [ 2930.333581] 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 [ 2930.352910] Lustre: Skipped 39 previous similar messages [ 2930.360487] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2930.371751] Lustre: Skipped 2 previous similar messages [ 2930.571236] Lustre: server umount lustre-MDT0000 complete [ 2930.659375] LustreError: 70373:0:(ldlm_lib.c:1190: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. [ 2930.688236] LustreError: 70373:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 325 previous similar messages [ 2934.845375] LustreError: 6523:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1789266493 with bad export cookie 5228480209349343756 [ 2934.847014] Lustre: Failing over lustre-MDT0001 [ 2934.865944] LustreError: 6523:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 2935.214482] Lustre: server umount lustre-MDT0001 complete [ 2956.770902] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2956.917663] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2960.356520] LustreError: 3623:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8a29ee566680 x1876178886004352/t0(0) o250->MGC192.168.204.111@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 [ 2960.983909] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 2960.991888] Lustre: Skipped 11 previous similar messages [ 2961.024954] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 2961.034796] Lustre: Skipped 11 previous similar messages [ 2961.239374] Lustre: lustre-MDT0001-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 2961.244116] Lustre: Skipped 42 previous similar messages [ 2966.042844] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug -1 all [ 2966.205239] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug -1 all [ 2967.222114] Lustre: lustre-MDT0001: Recovery over after 0:06, of 3 clients 3 recovered and 0 were evicted. [ 2967.228918] Lustre: Skipped 11 previous similar messages [ 2967.254496] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:100 to 0x280000400:161) [ 2967.254604] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:100 to 0x2c0000400:161) [ 2967.266398] Lustre: 77669:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff8a28cb530700 x1876178879146752/t21474836483(0) o36->eb907c3a-1b69-4dd4-9bf1-a5608962e631@192.168.204.11@tcp:410/0 lens 496/2888 e 0 to 0 dl 1789266605 ref 1 fl Interpret:/202/0 rc 0/0 job:'rmdir.0' uid:0 gid:0 projid:4294967295 [ 2971.282977] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1923 to 0x2c0000401:1985) [ 2971.283320] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1923 to 0x280000401:1985) [ 2978.101170] Lustre: DEBUG MARKER: oleg411-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 [ 2980.176154] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2981.813941] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2991.529710] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2993.906934] Lustre: Failing over lustre-MDT0000 [ 2994.157455] Lustre: server umount lustre-MDT0000 complete [ 2997.230527] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 2997.249341] LustreError: Skipped 6 previous similar messages [ 3013.600532] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3013.620438] LustreError: Skipped 8 previous similar messages [ 3014.712239] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3014.718673] LDISKFS-fs (dm-0): recovery complete [ 3014.730123] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3023.862893] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x488f4b0c796d895c [ 3025.261512] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 3025.277225] Lustre: Skipped 12 previous similar messages [ 3028.273949] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug -1 all [ 3029.654633] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1987 to 0x280000401:2017) [ 3029.654800] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1987 to 0x2c0000401:2017) [ 3036.700970] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3038.584443] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3048.319311] Lustre: DEBUG MARKER: == replay-dual test 23c: c1 rmdir d1, M0 drop update reply and fail M0, c2 mkdir d1 ========================================================== 22:30:05 (1789266605) [ 3049.807730] Lustre: *** cfs_fail_loc=1701, val=2147483648*** [ 3049.812273] LustreError: 8417:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff8a29df9e5c00 x1876178886075008/t137438953491(0) o1000->lustre-MDT0001-mdtlov_UUID@0@lo:424/0 lens 1984/4320 e 0 to 0 dl 1789266619 ref 1 fl Interpret:/200/0 rc 0/0 job:'osp_up0-1.0' uid:0 gid:0 projid:4294967295 [ 3053.585199] Lustre: Failing over lustre-MDT0000 [ 3053.950992] Lustre: server umount lustre-MDT0000 complete [ 3073.022737] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3081.231976] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x488f4b0c796d9094 [ 3086.950754] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1987 to 0x2c0000401:2049) [ 3086.959370] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1987 to 0x280000401:2049) [ 3087.468317] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug -1 all [ 3098.049581] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3099.796821] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3108.592456] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3110.683219] Lustre: Failing over lustre-MDT0000 [ 3110.977624] Lustre: server umount lustre-MDT0000 complete [ 3132.014123] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3132.018531] LDISKFS-fs (dm-0): recovery complete [ 3132.025598] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3138.532349] LustreError: 3623:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8a29f519e680 x1876178886122752/t0(0) o250->MGC192.168.204.111@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 [ 3142.708672] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug -1 all [ 3144.270283] Lustre: 83061:0:(ldlm_lib.c:2110:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3144.290408] Lustre: 83061:0:(ldlm_lib.c:2110:extend_recovery_timer()) Skipped 17 previous similar messages [ 3144.476316] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2051 to 0x2c0000401:2081) [ 3144.482462] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2051 to 0x280000401:2081) [ 3151.838946] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3153.633839] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3161.272076] Lustre: DEBUG MARKER: == replay-dual test 23d: c1 rmdir d1, M0 drop update reply and fail M0/M1, c2 mkdir d1 ========================================================== 22:31:58 (1789266718) [ 3165.951845] Lustre: *** cfs_fail_loc=1701, val=2147483648*** [ 3165.955928] LustreError: 8416:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff8a29ed95ca80 x1876178886151040/t146028888081(0) o1000->lustre-MDT0001-mdtlov_UUID@0@lo:540/0 lens 1984/4320 e 0 to 0 dl 1789266735 ref 1 fl Interpret:/200/0 rc 0/0 job:'osp_up0-1.0' uid:0 gid:0 projid:4294967295 [ 3169.654512] Lustre: Failing over lustre-MDT0000 [ 3169.773729] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3169.780229] Lustre: Skipped 3 previous similar messages [ 3169.967731] Lustre: server umount lustre-MDT0000 complete [ 3174.152918] LustreError: 6480:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1789266732 with bad export cookie 5228480209349351001 [ 3174.153289] Lustre: Failing over lustre-MDT0001 [ 3174.170248] LustreError: 6480:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 3174.184696] LustreError: 84297:0:(ldlm_resource.c:1207:ldlm_resource_complain()) lustre-MDT0000-osp-MDT0001: namespace resource [0x2000013a1:0x80:0x0].0x0 (ffff8a29d0ab1200) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 3180.492687] Lustre: server umount lustre-MDT0001 complete [ 3199.214074] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3199.272319] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3199.337679] Lustre: MGS: Not available for connect from 0@lo (not set up) [ 3199.344706] Lustre: Skipped 7 previous similar messages [ 3203.934915] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2051 to 0x2c0000401:2113) [ 3203.939963] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2051 to 0x280000401:2113) [ 3204.427938] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug -1 all [ 3204.449558] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug -1 all [ 3217.502239] Lustre: 85022:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff8a29ee565c00 x1876178879225216/t25769803783(0) o36->eb907c3a-1b69-4dd4-9bf1-a5608962e631@192.168.204.11@tcp:660/0 lens 496/2888 e 0 to 0 dl 1789266855 ref 1 fl Interpret:/202/0 rc 0/0 job:'rmdir.0' uid:0 gid:0 projid:4294967295 [ 3217.509210] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:100 to 0x2c0000400:193) [ 3217.509655] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:100 to 0x280000400:193) [ 3224.138896] Lustre: DEBUG MARKER: oleg411-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 [ 3225.936892] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3227.589552] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3236.860466] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3238.733531] Lustre: Failing over lustre-MDT0000 [ 3238.987896] Lustre: server umount lustre-MDT0000 complete [ 3260.353248] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3260.356020] LDISKFS-fs (dm-0): recovery complete [ 3260.361989] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3264.994639] LustreError: 3623:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8a28cb532300 x1876178886202496/t0(0) o250->MGC192.168.204.111@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 [ 3270.550630] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug -1 all [ 3271.003284] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2115 to 0x280000401:2145) [ 3271.007490] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2115 to 0x2c0000401:2145) [ 3281.592313] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3283.328866] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3292.788547] Lustre: DEBUG MARKER: == replay-dual test 24: reconstruct on non-existing object ========================================================== 22:34:09 (1789266849) [ 3294.028614] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 3294.039750] LustreError: 85441:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff8a29e9415f80 x1876178879262592/t154618822673(0) o36->eb907c3a-1b69-4dd4-9bf1-a5608962e631@192.168.204.11@tcp:737/0 lens 488/456 e 0 to 0 dl 1789266932 ref 1 fl Interpret:/200/0 rc 0/0 job:'truncate.0' uid:0 gid:0 projid:4294967295 [ 3379.147186] Lustre: lustre-MDT0000: Client eb907c3a-1b69-4dd4-9bf1-a5608962e631 (at 192.168.204.11@tcp) reconnecting [ 3379.176996] Lustre: 85023:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff8a29c68c7b80 x1876178879262592/t154618822673(0) o36->eb907c3a-1b69-4dd4-9bf1-a5608962e631@192.168.204.11@tcp:67/0 lens 488/3152 e 0 to 0 dl 1789267017 ref 1 fl Interpret:/202/0 rc 0/0 job:'truncate.0' uid:0 gid:0 projid:4294967295 [ 3386.852271] Lustre: DEBUG MARKER: == replay-dual test 25: replay|resend ==================== 22:35:43 (1789266943) [ 3389.117597] Lustre: *** cfs_fail_loc=304, val=0*** [ 3391.159932] Lustre: Failing over lustre-OST0000 [ 3391.269449] Lustre: server umount lustre-OST0000 complete [ 3410.693222] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3418.177593] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug -1 all [ 3431.108378] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 3433.136951] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 3444.027738] Lustre: DEBUG MARKER: == replay-dual test 26: dbench and tar with mds failover ========================================================== 22:36:40 (1789267000) [ 3454.957981] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3459.523052] Lustre: DEBUG MARKER: test_26 fail mds1 1 times [ 3462.151725] Lustre: Failing over lustre-MDT0000 [ 3462.228568] Lustre: lustre-MDT0000: Not available for connect from 192.168.204.11@tcp (stopping) [ 3462.572168] Lustre: server umount lustre-MDT0000 complete [ 3484.131920] Lustre: 3624:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789267026/real 1789267026] req@ffff8a29fc932680 x1876178886353536/t0(0) o400->MGC192.168.204.111@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789267042 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3484.157219] Lustre: 3624:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 22 previous similar messages [ 3485.879293] LDISKFS-fs (dm-0): 3 truncates cleaned up [ 3485.881524] LDISKFS-fs (dm-0): recovery complete [ 3485.898178] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3494.392295] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x488f4b0c796deba9 [ 3499.921474] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug -1 all [ 3500.057774] Lustre: 91176:0:(ldlm_lib.c:2110:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3500.079286] Lustre: 91176:0:(ldlm_lib.c:2110:extend_recovery_timer()) Skipped 17 previous similar messages [ 3502.352332] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2183 to 0x280000401:2209) [ 3502.358092] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2182 to 0x2c0000401:2209) [ 3511.325204] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3513.556209] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3526.859934] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 3531.001635] Lustre: DEBUG MARKER: test_26 fail mds2 2 times [ 3533.580352] Lustre: Failing over lustre-MDT0001 [ 3533.782025] Lustre: lustre-MDT0001: Not available for connect from 192.168.204.11@tcp (stopping) [ 3533.786518] Lustre: Skipped 1 previous similar message [ 3535.859715] Lustre: lustre-MDT0001-osp-MDT0000: Connection to lustre-MDT0001 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 3535.874544] Lustre: Skipped 34 previous similar messages [ 3539.412755] Lustre: server umount lustre-MDT0001 complete [ 3540.955887] LustreError: 88007:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 192.168.204.11@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3540.976045] LustreError: 88007:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 229 previous similar messages [ 3562.414670] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 3562.418799] LDISKFS-fs (dm-1): recovery complete [ 3562.437049] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3562.900908] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 3562.907021] Lustre: Skipped 9 previous similar messages [ 3562.966875] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 3562.975707] Lustre: Skipped 9 previous similar messages [ 3567.569298] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug -1 all [ 3568.141472] Lustre: lustre-MDT0001-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 3568.154673] Lustre: Skipped 36 previous similar messages [ 3569.708745] Lustre: lustre-MDT0001: Recovery over after 0:05, of 3 clients 3 recovered and 0 were evicted. [ 3569.718660] Lustre: Skipped 9 previous similar messages [ 3569.787854] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:244 to 0x2c0000400:289) [ 3569.790760] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:244 to 0x280000400:289) [ 3579.381383] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 3581.822884] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3596.854327] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3601.216891] Lustre: DEBUG MARKER: test_26 fail mds1 3 times [ 3604.309040] Lustre: Failing over lustre-MDT0000 [ 3605.125402] Lustre: server umount lustre-MDT0000 complete [ 3609.078384] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3609.091351] LustreError: Skipped 4 previous similar messages [ 3625.441048] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3625.456859] LustreError: Skipped 5 previous similar messages [ 3629.668640] LDISKFS-fs (dm-0): 3 truncates cleaned up [ 3629.675199] LDISKFS-fs (dm-0): recovery complete [ 3629.686294] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3634.658948] LustreError: 3623:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8a28cea84a80 x1876178886750336/t0(0) o250->MGC192.168.204.111@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 [ 3634.697469] Lustre: MGS: Client b0e5feb2-4164-4fa7-b629-110dbdf9b04d (at 0@lo) reconnecting [ 3635.659356] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 3635.676097] Lustre: Skipped 8 previous similar messages [ 3640.565625] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug -1 all [ 3643.615569] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2301 to 0x280000401:2337) [ 3643.620717] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2302 to 0x2c0000401:2337) [ 3643.645229] Lustre: 88007:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff8a29df780e00 x1876178880713216/t158913791489(0) o36->eb907c3a-1b69-4dd4-9bf1-a5608962e631@192.168.204.11@tcp:332/0 lens 552/2880 e 0 to 0 dl 1789267282 ref 1 fl Interpret:/202/0 rc 0/0 job:'tar.0' uid:0 gid:0 projid:4294967295 [ 3656.603922] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3659.193077] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3723.042324] Lustre: DEBUG MARKER: == replay-dual test 28: lock replay should be ordered: waiting after granted ========================================================== 22:41:19 (1789267279) [ 3737.050184] Lustre: Failing over lustre-OST0000 [ 3737.276287] Lustre: server umount lustre-OST0000 complete [ 3755.710517] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3757.838492] Lustre: *** cfs_fail_loc=32a, val=0*** [ 3762.180634] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug -1 all [ 3771.623873] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 3773.342625] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 3784.527368] Lustre: DEBUG MARKER: == replay-dual test 29: replay vs update with the same xid ========================================================== 22:42:21 (1789267341) [ 3786.035137] Lustre: DEBUG MARKER: SKIP: replay-dual test_29 needs >= 2 clients [ 3787.881705] Lustre: DEBUG MARKER: == replay-dual test 30: layout lock replay is not blocked on IO ========================================================== 22:42:24 (1789267344) [ 3791.453922] Lustre: Failing over lustre-MDT0000 [ 3791.926895] Lustre: server umount lustre-MDT0000 complete [ 3810.505391] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3815.979163] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug -1 all [ 3819.126899] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2365 to 0x2c0000401:2401) [ 3819.135330] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2367 to 0x280000401:2401) [ 3826.654807] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3828.967075] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3839.696774] Lustre: DEBUG MARKER: == replay-dual test 31: deadlock on file_remove_privs and occupied mod rpc slots ========================================================== 22:43:16 (1789267396) [ 3843.657312] Lustre: Failing over lustre-OST0000 [ 3843.777649] Lustre: server umount lustre-OST0000 complete [ 3864.629633] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3872.938534] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug -1 all [ 3884.618159] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 3886.530646] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL [ 3898.859328] Lustre: DEBUG MARKER: == replay-dual test 32: gap in update llog shouldn't break recovery ========================================================== 22:44:15 (1789267455) [ 3900.271743] Lustre: *** cfs_fail_loc=131d, val=10*** [ 3900.794671] Lustre: *** cfs_fail_loc=131d, val=0*** [ 3900.797760] Lustre: Skipped 9 previous similar messages [ 3901.892938] Lustre: *** cfs_fail_loc=131d, val=4294967278*** [ 3901.897657] Lustre: Skipped 17 previous similar messages [ 3904.709122] Lustre: Failing over lustre-MDT0001 [ 3904.949925] Lustre: server umount lustre-MDT0001 complete [ 3908.949805] Lustre: Failing over lustre-MDT0000 [ 3909.470627] Lustre: server umount lustre-MDT0000 complete [ 3917.401910] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3917.911683] Lustre: *** cfs_fail_loc=131d, val=4294967266*** [ 3917.916628] Lustre: Skipped 11 previous similar messages [ 3923.401565] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug -1 all [ 3932.804749] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3933.008956] Lustre: *** cfs_fail_loc=131d, val=4294967262*** [ 3933.013613] Lustre: Skipped 3 previous similar messages [ 3933.132100] Lustre: lustre-MDT0001: Not available for connect from 192.168.204.11@tcp (not set up) [ 3933.143762] Lustre: Skipped 8 previous similar messages [ 3938.943181] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:346 to 0x280000400:385) [ 3938.943333] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:346 to 0x2c0000400:385) [ 3939.069154] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2365 to 0x2c0000401:2433) [ 3939.071368] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug -1 all [ 3939.072729] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2441 to 0x280000401:2497) [ 3952.327736] Lustre: DEBUG MARKER: == replay-dual test 33: Check for OBD_INCOMPAT_MULTI_RPCS in last_rcvd after abort_recovery ========================================================== 22:45:09 (1789267509) [ 3959.441453] Lustre: Failing over lustre-MDT0001 [ 3959.844099] Lustre: server umount lustre-MDT0001 complete [ 3982.352613] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3988.264433] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug -1 all [ 3997.923838] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount REPLAY_WAIT mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 4000.048894] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in REPLAY_WAIT state after 0 sec [ 4001.186191] Lustre: lustre-MDT0001: Aborting client recovery [ 4001.193049] LustreError: 103861:0:(ldlm_lib.c:3029:target_stop_recovery_thread()) lustre-MDT0001: Aborting recovery [ 4001.200426] Lustre: 103226:0:(ldlm_lib.c:2429:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 4001.219151] Lustre: 103226:0:(ldlm_lib.c:2429:target_recovery_overseer()) Skipped 2 previous similar messages [ 4001.231748] Lustre: 103226:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0001: disconnect stale client a24e50d6-3696-4907-9745-a6bf9e01d309@ [ 4001.247347] Lustre: lustre-MDT0001: disconnecting 1 stale clients [ 4001.272459] Lustre: lustre-MDT0001-osd: cancel update llog [0x240000400:0x1:0x0] [ 4001.302205] Lustre: lustre-MDT0000-osp-MDT0001: cancel update llog [0x200000401:0x1:0x0] [ 4001.379278] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:346 to 0x280000400:417) [ 4001.391534] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:346 to 0x2c0000400:417) [ 4008.481893] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 4010.557448] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4015.472556] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0001.recovery_status 1475 [ 4022.986245] Lustre: Failing over lustre-MDT0001 [ 4023.504602] Lustre: server umount lustre-MDT0001 complete [ 4035.035979] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4041.289830] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:346 to 0x2c0000400:449) [ 4041.291526] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:346 to 0x280000400:449) [ 4041.862187] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug -1 all [ 4049.694874] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 4051.535761] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4055.827797] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0001.recovery_status 1475 [ 4065.051226] Lustre: DEBUG MARKER: == replay-dual test complete, duration 3932 sec ========== 22:47:01 (1789267621) [ 4066.943606] Lustre: DEBUG MARKER: === replay-dual: start cleanup 22:47:03 (1789267623) === [ 4081.225814] Lustre: DEBUG MARKER: === replay-dual: finish cleanup 22:47:17 (1789267637) === [ 4083.496238] Lustre: Failing over lustre-MDT0000 [ 4083.820874] Lustre: server umount lustre-MDT0000 complete [ 4104.160182] Lustre: 3624:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789267645/real 1789267645] req@ffff8a29f0a40700 x1876178887541760/t0(0) o400->MGC192.168.204.111@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789267661 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4104.203752] Lustre: 3624:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 5 previous similar messages [ 4111.002516] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4114.401163] LustreError: 3623:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8a29df9d0700 x1876178887550464/t0(0) o250->MGC192.168.204.111@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 [ 4120.141269] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4255.502535] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 4255.514079] Lustre: 107030:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client a24e50d6-3696-4907-9745-a6bf9e01d309@ [ 4255.538550] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 4255.560222] Lustre: lustre-MDT0000: Recovery over after 2:20, of 3 clients 2 recovered and 1 was evicted. [ 4255.561563] Lustre: lustre-MDT0000-osp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4255.573898] Lustre: Skipped 8 previous similar messages [ 4255.575905] Lustre: Skipped 30 previous similar messages [ 4255.648285] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2441 to 0x280000401:2529) [ 4255.649336] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2365 to 0x2c0000401:2465) [ 4263.045133] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4265.486774] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4273.633891] 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 [ 4273.638486] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4273.661184] Lustre: Skipped 31 previous similar messages [ 4273.673528] Lustre: Skipped 3 previous similar messages [ 4278.763434] LustreError: 101279:0:(ldlm_lib.c:1190: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. [ 4278.790828] LustreError: 101279:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 204 previous similar messages [ 4279.094742] Lustre: server umount lustre-MDT0000 complete [ 4290.517157] LustreError: 6479:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1789267848 with bad export cookie 5228480209349542577 [ 4290.519160] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4290.528624] LustreError: 6479:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 4290.544418] LustreError: Skipped 4 previous similar messages [ 4291.212423] Lustre: server umount lustre-MDT0001 complete [ 4312.379962] Lustre: server umount lustre-OST0000 complete [ 4332.371822] Lustre: server umount lustre-OST0001 complete [ 4352.767443] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing unload_modules_local [ 4356.080305] Key type lgssc unregistered [ 4356.640699] LNet: 109969:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 4356.650328] LNetError: 109969:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 4356.675934] LNet: Removed LNI 192.168.204.111@tcp [ 4357.822132] Key type .llcrypt unregistered [ 4357.824316] Key type ._llcrypt unregistered