[ 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 449518656 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2399.998 MHz processor [ 0.000000] last_pfn = 0x146e00 max_arch_pfn = 0x400000000 [ 0.000000] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT [ 0.000000] last_pfn = 0xbffce max_arch_pfn = 0x400000000 [ 0.000000] found SMP MP-table at [mem 0x000f54b0-0x000f54bf] [ 0.000000] RAMDISK: [mem 0xbcc54000-0xbffbffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F52D0 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE247C 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE2318 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 0022D8 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE238C 000090 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE241C 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE2454 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe2318-0xbffe238b] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe2317] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe238c-0xbffe241b] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe241c-0xbffe2453] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe2454-0xbffe247b] [ 0.000000] No NUMA configuration found [ 0.000000] Faking a node at [mem 0x0000000000000000-0x0000000146dfffff] [ 0.000000] NODE_DATA(0) allocated [mem 0x1465a3000-0x1465cdfff] [ 0.000000] Reserving 256MB of memory at 2752MB for crashkernel (System RAM: 4205MB) [ 0.000000] Zone ranges: [ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.000000] DMA32 [mem 0x0000000001000000-0x00000000ffffffff] [ 0.000000] Normal [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Device empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff] [ 0.000000] node 0: [mem 0x0000000000100000-0x00000000bffcdfff] [ 0.000000] node 0: [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Zeroed struct page in unavailable ranges: 4756 pages [ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x0000000146dfffff] [ 0.000000] ACPI: PM-Timer IO Port: 0x608 [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) [ 0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) [ 0.000000] Using ACPI (MADT) for SMP configuration information [ 0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000] TSC deadline timer available [ 0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs [ 0.000000] kvm-guest: KVM setup pv remote TLB flush [ 0.000000] kvm-guest: setup PV sched yield [ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff] [ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff] [ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff] [ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff] [ 0.000000] PM: Registered nosave memory: [mem 0xbffce000-0xbfffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xc0000000-0xfeffbfff] [ 0.000000] PM: Registered nosave memory: [mem 0xfeffc000-0xfeffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xff000000-0xfffbffff] [ 0.000000] PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff] [ 0.000000] [mem 0xc0000000-0xfeffbfff] available for PCI devices [ 0.000000] Booting paravirtualized kernel on KVM [ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns [ 0.000000] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1 [ 0.000000] percpu: Embedded 63 pages/cpu s221184 r8192 d28672 u524288 [ 0.000000] kvm-guest: PV spinlocks enabled [ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1059606 [ 0.000000] Policy zone: Normal [ 0.000000] Kernel command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] Specific versions of hardware are certified with Red Hat Enterprise Linux 8. Please see the list of hardware certified with Red Hat Enterprise Linux 8 at https://catalog.redhat.com. [ 0.000000] audit: disabled (until reboot) [ 0.000000] software IO TLB: area num 4. [ 0.000000] Memory: 2829652K/4306352K available (18435K kernel code, 11221K rwdata, 7248K rodata, 2908K init, 18040K bss, 524580K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] ftrace: allocating 41240 entries in 162 pages [ 0.000000] ftrace: allocated 162 pages with 3 groups [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] rcu: RCU event tracing is enabled. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ 0.000000] rcu: RCU callback double-/use-after-free debug enabled. [ 0.000000] Rude variant of Tasks RCU enabled. [ 0.000000] Tracing variant of Tasks RCU enabled. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 0.000000] NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16 [ 0.000000] random: get_random_bytes called from start_kernel+0x622/0x9a8 with crng_init=0 [ 0.001000] Console: colour *CGA 80x25 [ 0.001000] printk: console [ttyS1] enabled [ 0.001000] ACPI: Core revision 20220331 [ 0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.001014] APIC: Switch to symmetric I/O mode setup [ 0.002382] x2apic enabled [ 0.003020] Switched APIC routing to physical x2apic. [ 0.004031] kvm-guest: setup PV IPIs [ 0.006747] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.007000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.007025] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.008015] pid_max: default: 32768 minimum: 301 [ 0.010151] LSM: Security Framework initializing [ 0.011061] Yama: becoming mindful. [ 0.012041] SELinux: Initializing. [ 0.013074] *** VALIDATE selinux *** [ 0.022183] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.026817] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.028135] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.029125] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.030118] *** VALIDATE tmpfs *** [ 0.032064] *** VALIDATE proc *** [ 0.033273] *** VALIDATE cgroup *** [ 0.034011] *** VALIDATE cgroup2 *** [ 0.036265] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.038168] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.039009] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.040027] Spectre V2 : User space: Vulnerable [ 0.041007] Speculative Store Bypass: Vulnerable [ 0.043812] debug: unmapping init [mem 0xffffffffaa259000-0xffffffffaa260fff] [ 0.045185] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.046724] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.047028] ... version: 2 [ 0.048014] ... bit width: 48 [ 0.049020] ... generic registers: 4 [ 0.050014] ... value mask: 0000ffffffffffff [ 0.051015] ... max period: 00007fffffffffff [ 0.052018] ... fixed-purpose events: 3 [ 0.053028] ... event mask: 000000070000000f [ 0.054330] rcu: Hierarchical SRCU implementation. [ 0.056416] smp: Bringing up secondary CPUs ... [ 0.057602] x86: Booting SMP configuration: [ 0.058027] .... node #0, CPUs: #1 #2 #3 [ 0.061647] smp: Brought up 1 node, 4 CPUs [ 0.063016] smpboot: Max logical packages: 1 [ 0.064023] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.133598] node 0 deferred pages initialised in 67ms [ 0.136160] devtmpfs: initialized [ 0.137261] x86/mm: Memory block size: 128MB [ 0.139863] gcov: version magic: 0x41383552 [ 0.143322] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.146112] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.148365] pinctrl core: initialized pinctrl subsystem [ 0.149170] [ 0.149566] ************************************************************* [ 0.152015] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.154012] ** ** [ 0.155010] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.158013] ** ** [ 0.160009] ** This means that this kernel is built to expose internal ** [ 0.162016] ** IOMMU data structures, which may compromise security on ** [ 0.163014] ** your system. ** [ 0.165011] ** ** [ 0.167013] ** If you see this message and you are not debugging the ** [ 0.170013] ** kernel, report this immediately to your vendor! ** [ 0.172011] ** ** [ 0.174016] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.176010] ************************************************************* [ 0.178634] NET: Registered protocol family 16 [ 0.179440] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.182064] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.185057] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.188149] cpuidle: using governor menu [ 0.189608] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.191507] PCI: Using configuration type 1 for base access [ 0.193153] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.202147] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.204047] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.207127] cryptd: max_cpu_qlen set to 1000 [ 0.209236] ACPI: Added _OSI(Module Device) [ 0.210029] ACPI: Added _OSI(Processor Device) [ 0.211013] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.212011] ACPI: Added _OSI(Processor Aggregator Device) [ 0.217084] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.222338] ACPI: Interpreter enabled [ 0.224071] ACPI: PM: (supports S0 S3 S4 S5) [ 0.225014] ACPI: Using IOAPIC for interrupt routing [ 0.226122] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.229571] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.241717] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.244037] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.246025] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.249084] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.254390] acpiphp: Slot [2] registered [ 0.255139] acpiphp: Slot [5] registered [ 0.257104] acpiphp: Slot [6] registered [ 0.258117] acpiphp: Slot [7] registered [ 0.260101] acpiphp: Slot [8] registered [ 0.261114] acpiphp: Slot [9] registered [ 0.262112] acpiphp: Slot [10] registered [ 0.264077] acpiphp: Slot [3] registered [ 0.265177] acpiphp: Slot [4] registered [ 0.267129] acpiphp: Slot [11] registered [ 0.269123] acpiphp: Slot [12] registered [ 0.270154] acpiphp: Slot [13] registered [ 0.272126] acpiphp: Slot [14] registered [ 0.274114] acpiphp: Slot [15] registered [ 0.275109] acpiphp: Slot [16] registered [ 0.277112] acpiphp: Slot [17] registered [ 0.279108] acpiphp: Slot [18] registered [ 0.280147] acpiphp: Slot [19] registered [ 0.282120] acpiphp: Slot [20] registered [ 0.283123] acpiphp: Slot [21] registered [ 0.285103] acpiphp: Slot [22] registered [ 0.286119] acpiphp: Slot [23] registered [ 0.288107] acpiphp: Slot [24] registered [ 0.290106] acpiphp: Slot [25] registered [ 0.291120] acpiphp: Slot [26] registered [ 0.292095] acpiphp: Slot [27] registered [ 0.294098] acpiphp: Slot [28] registered [ 0.295107] acpiphp: Slot [29] registered [ 0.297104] acpiphp: Slot [30] registered [ 0.298085] acpiphp: Slot [31] registered [ 0.299055] PCI host bridge to bus 0000:00 [ 0.300018] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.302020] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.304023] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.306020] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.308020] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.310025] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.312166] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.314084] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.317178] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.326022] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.331012] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.332016] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.334016] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.336033] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.338604] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.341827] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.345048] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.347876] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.353016] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.365000] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.371017] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.377000] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.387015] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.396015] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.411018] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.423027] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.431019] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.437019] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.454020] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.464012] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.474019] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.479019] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.496017] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.505474] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.527016] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.538016] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.554017] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.563432] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.570017] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.576014] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.590019] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 0.596229] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.601016] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.605017] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.623016] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 0.629944] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.634403] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.635323] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.637337] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.639189] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.644040] iommu: Default domain type: Passthrough [ 0.645351] SCSI subsystem initialized [ 0.646096] ACPI: bus type USB registered [ 0.646740] usbcore: registered new interface driver usbfs [ 0.648058] usbcore: registered new interface driver hub [ 0.649067] usbcore: registered new device driver usb [ 0.649861] pps_core: LinuxPPS API ver. 1 registered [ 0.650007] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.652052] PTP clock support registered [ 0.653130] EDAC MC: Ver: 3.0.0 [ 0.654108] PCI: Using ACPI for IRQ routing [ 0.655697] NetLabel: Initializing [ 0.656010] NetLabel: domain hash size = 128 [ 0.657007] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.658024] NetLabel: unlabeled traffic allowed by default [ 0.660105] vgaarb: loaded [ 0.661224] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.662007] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.667420] clocksource: Switched to clocksource kvm-clock [ 0.758314] VFS: Disk quotas dquot_6.6.0 [ 0.759599] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.762080] *** VALIDATE ramfs *** [ 0.763301] *** VALIDATE hugetlbfs *** [ 0.765505] pnp: PnP ACPI init [ 0.768066] pnp: PnP ACPI: found 6 devices [ 0.784635] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.787400] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.789095] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.791202] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.793776] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.796325] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.799406] NET: Registered protocol family 2 [ 0.801688] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.806403] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.809470] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.814145] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.817305] TCP: Hash tables configured (established 65536 bind 65536) [ 0.819453] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.821876] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.824699] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.827564] NET: Registered protocol family 1 [ 0.829672] RPC: Registered named UNIX socket transport module. [ 0.831281] RPC: Registered udp transport module. [ 0.832590] RPC: Registered tcp transport module. [ 0.833967] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.836066] NET: Registered protocol family 44 [ 0.837123] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.838782] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.840195] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.841983] PCI: CLS 0 bytes, default 64 [ 0.843128] Unpacking initramfs... [ 2.113878] debug: unmapping init [mem 0xffff9ef0fcc54000-0xffff9ef0fffbffff] [ 2.116898] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.118325] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.121128] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 2.634256] Initialise system trusted keyrings [ 2.636048] Key type blacklist registered [ 2.638104] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.645516] zbud: loaded [ 2.648134] *** VALIDATE nfs *** [ 2.649143] *** VALIDATE nfs4 *** [ 2.650562] pstore: using deflate compression [ 2.653852] Platform Keyring initialized [ 2.745827] NET: Registered protocol family 38 [ 2.746925] Key type asymmetric registered [ 2.747938] Asymmetric key parser 'x509' registered [ 2.749271] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 2.752328] io scheduler mq-deadline registered [ 2.754361] io scheduler kyber registered [ 2.756509] io scheduler bfq registered [ 2.758874] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 2.762116] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 2.765048] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 2.767859] ACPI: Power Button [PWRF] [ 2.773465] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 2.780288] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 2.792896] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 2.800259] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 2.813604] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 2.840423] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 2.869342] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 2.874300] Non-volatile memory driver v1.3 [ 2.875636] Linux agpgart interface v0.103 [ 2.908647] virtio_blk virtio1: [vda] 145736 512-byte logical blocks (74.6 MB/71.2 MiB) [ 2.911549] vda: detected capacity change from 0 to 74616832 [ 2.927976] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 2.931056] vdb: detected capacity change from 0 to 1073741824 [ 2.948794] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 2.951962] vdc: detected capacity change from 0 to 2621440000 [ 2.969748] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 2.972757] vdd: detected capacity change from 0 to 2621440000 [ 2.992210] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 2.995150] vde: detected capacity change from 0 to 4294967296 [ 3.012092] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.015218] vdf: detected capacity change from 0 to 4294967296 [ 3.022500] libphy: Fixed MDIO Bus: probed [ 3.029212] usbcore: registered new interface driver usbserial_generic [ 3.030985] usbserial: USB Serial support registered for generic [ 3.032339] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.034922] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.036043] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.038123] mousedev: PS/2 mouse device common for all mice [ 3.040571] rtc_cmos 00:05: RTC can wake from S4 [ 3.042404] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.043197] rtc_cmos 00:05: registered as rtc0 [ 3.047236] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.047328] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.050797] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.052046] intel_pstate: CPU model not supported [ 3.057606] hid: raw HID events driver (C) Jiri Kosina [ 3.060089] usbcore: registered new interface driver usbhid [ 3.062367] usbhid: USB HID core driver [ 3.064130] drop_monitor: Initializing network drop monitor service [ 3.066831] Initializing XFRM netlink socket [ 3.068946] NET: Registered protocol family 10 [ 3.071690] Segment Routing with IPv6 [ 3.072662] NET: Registered protocol family 17 [ 3.074287] mpls_gso: MPLS GSO support [ 3.079153] RAS: Correctable Errors collector initialized. [ 3.080858] AVX version of gcm_enc/dec engaged. [ 3.081929] AES CTR mode by8 optimization enabled [ 3.153477] sched_clock: Marking stable (3153453868, 0)->(4060842958, -907389090) [ 3.157367] registered taskstats version 1 [ 3.159681] Loading compiled-in X.509 certificates [ 3.162572] zswap: loaded using pool lzo/zbud [ 3.186734] Key type big_key registered [ 3.198620] Key type encrypted registered [ 3.200374] ima: No TPM chip found, activating TPM-bypass! [ 3.202671] ima: Allocated hash algorithm: sha1 [ 3.204328] ima: No architecture policies found [ 3.206206] evm: Initialising EVM extended attributes: [ 3.208110] evm: security.selinux [ 3.209428] evm: security.ima [ 3.210387] evm: security.capability [ 3.211159] evm: HMAC attrs: 0x1 [ 3.213101] rtc_cmos 00:05: setting system clock to 2026-07-13 13:54:19 UTC (1783950859) [ 3.218735] debug: unmapping init [mem 0xffffffffab203000-0xffffffffab3fffff] [ 3.221892] debug: unmapping init [mem 0xffffffffa9f82000-0xffffffffaa258fff] [ 3.231078] Write protecting the kernel read-only data: 28672k [ 3.233820] debug: unmapping init [mem 0xffffffffa8603000-0xffffffffa87fffff] [ 3.235496] debug: unmapping init [mem 0xffffffffa8f14000-0xffffffffa8ffffff] [ 3.260427] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 3.266432] systemd[1]: Detected virtualization kvm. [ 3.268618] systemd[1]: Detected architecture x86-64. [ 3.270781] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.296960] systemd[1]: No hostname configured. [ 3.298743] systemd[1]: Set hostname to . [ 3.301264] random: systemd: uninitialized urandom read (16 bytes read) [ 3.304011] systemd[1]: Initializing machine ID from random generator. [ 3.353863] random: ln: uninitialized urandom read (6 bytes read) [ 3.453326] random: systemd: uninitialized urandom read (16 bytes read) [ 3.456102] systemd[1]: Reached target Slices. [ OK ] Reached target Slices. [ 3.461411] systemd[1]: Listening on Journal Socket. [ OK ] Listening on Journal Socket. [ 3.466708] systemd[1]: Listening on udev Kernel Socket. [ OK ] Listening on udev Kernel Socket. [ OK ] Listening on udev Control Socket. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Listening on Journal Socket (/dev/log). [ OK ] Reached target Local File Systems. [ OK ] Reached target Initrd Root Device. [ OK ] Started Memstrack Anylazing Service. Starting Journal Service... [ OK ] Reached target Timers. Starting Create Volatile Files and Directories... [ OK ] Reached target Swap. Starting Setup Virtual Console... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. Starting Apply Kernel Variables... [ OK ] Reached target Sockets. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Setup Virtual Console. [ OK ] Started Apply Kernel Variables. Starting dracut cmdline hook... Starting Create Static Device Nodes in /dev... [ OK ] Started Journal Service. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 4.081732] device-mapper: uevent: version 1.0.3 [ 4.083835] 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. Starting dracut initqueue hook... [ OK ] Reached target System Initialization.[ 4.822353] random: fast init done [ 4.830970] virtio_net virtio0 ens2: renamed from eth0 [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ 5.010108] scsi host0: ata_piix [ 5.050356] scsi host1: ata_piix [ 5.052252] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 5.054538] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 8.650107] dracut-initqueue[584]: RTNETLINK answers: File exists [ 9.716901] random: crng init done [ 9.718302] random: 7 urandom warning(s) missed due to ratelimiting Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Mounting /sysroot... [ 10.113944] 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... Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped target Timers. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Sockets. [ OK ] Stopped target System Initialization. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. Stopping udev Kernel Device Manager... [ OK ] Stopped target Swap. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. [ OK ] Stopped target Slices. [ OK ] Stopped target Paths. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped udev Kernel Device Manager. [ 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... [ 11.267082] printk: systemd: 25 output lines suppressed due to ratelimiting [ 11.495271] SELinux: Disabled at runtime. [ 11.550273] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 11.559828] systemd[1]: Detected virtualization kvm. [ 11.562168] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 12.081810] systemd[1]: initrd-switch-root.service: Succeeded. [ 12.086295] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 12.094758] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 12.099729] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 12.102460] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 12.109497] systemd[1]: Starting Journal Service... Starting Journal Service... [ 12.114357] systemd[1]: Listening on initctl Compatibility Named Pipe. [ OK ] Listening on initctl Compatibility Named Pipe. Mounting Kernel Debug File System... [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Created slice system-getty.slice. [ OK ] Created slice User and Session Slice. Activating swap /dev/disk/by-label/SWAP... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Listening on udev Control Socket. [ OK ] Created slice system-serial\x2dgetty.slice. [ 12.190596] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS Starting Remount Root and Kernel File Systems... Mounting Huge Pages File System... [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Reached target Paths. Starting Create list of required st…ce nodes for the current kernel... Mounting POSIX Message Queue File System... [ OK ] Reached target rpc_pipefs.target. [ OK ] Reached target RPC Port Mapper. [ OK ] Reached target Slices. [ OK ] Listening on udev Kernel Socket. Starting udev Coldplug all Devices... [ OK ] Reached target Local Encrypted Volumes. [ OK ] Listening on Process Core Dump Socket. [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd File Systems. [ OK ] Stopped target Initrd Root File System. Starting Apply Kernel Variables... [ OK ] Started Journal Service. [ OK ] Mounted Kernel Debug File System. [ OK ] Activated swap /dev/disk/by-label/SWAP. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Mounted Huge Pages File System. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Started Apply Kernel Variables. Starting Create Static Device Nodes in /dev... Starting Configure read-only root support... [ 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. [ OK ] Reached target Local File Systems (Pre). Mounting /home/green/git/lustre-release... Mounting /mnt... Starting udev Kernel Device Manager... [ OK ] Mounted /mnt. [ 12.539240] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Started udev Coldplug all Devices. [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 12.940738] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 12.941995] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 13.164239] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 13.176580] EDAC sbridge: Ver: 1.1.2 [ 14.851625] Key type dns_resolver registered [ 15.157455] NFS: Registering the id_resolver key type [ 15.158622] Key type id_resolver registered [ 15.159549] Key type id_legacy registered [ OK ] Started Configure read-only root support. [ OK ] Reached target Local File Systems. Starting Mark the need to relabel after reboot... Starting Rebuild Dynamic Linker Cache... Starting Create Volatile Files and Directories... Starting Load/Save Random Seed... [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Load/Save Random Seed. [ OK ] Started Create Volatile Files and Directories. Starting RPC Bind... Starting Update UTMP about System Boot/Shutdown... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Started dnf makecache --timer. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting Login Service... Starting Restore /run/initramfs on shutdown... [ OK ] Started irqbalance daemon. [ OK ] Reached target sshd-keygen.target. [ OK ] Started D-Bus System Message Bus. Starting Network Manager... [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Reached target Timers. [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Login Service. [ OK ] Started Network Manager. [ OK ] Reached target Network. Starting OpenSSH server daemon... Starting GSSAPI Proxy Daemon... Starting Dynamic System Tuning Daemon... Starting Network Manager Wait Online... [ 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... Starting Hostname Service... [ OK ] Started OpenSSH server daemon. [ OK ] Started Permit User Sessions. [ OK ] Started Getty on tty1. [ OK ] Started Command Scheduler. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Serial Getty on ttyS1. [ OK ] Reached target Login Prompts. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting 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 oleg235-server login: [ 40.509568] libcfs: loading out-of-tree module taints kernel. [ 40.530928] Key type ._llcrypt registered [ 40.532663] Key type .llcrypt registered [ 40.589745] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_hostid [ 52.869656] hrtimer: interrupt took 4645512 ns [ 55.939746] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing load_modules_local [ 57.881540] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 57.898306] alg: No test for adler32 (adler32-zlib) [ 59.287094] Lustre: Lustre: Build Version: 2.17.54_162_gb5ded84 [ 60.498423] LNet: Added LNI 192.168.202.135@tcp [8/256/0/180] [ 62.415608] Key type lgssc registered [ 64.885743] Lustre: Echo OBD driver; http://www.lustre.org/ [ 86.160559] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 126.301116] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing load_modules_local [ 138.036727] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 138.088243] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 139.298793] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 139.344082] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 139.495034] Lustre: lustre-MDT0000: new disk, initializing [ 139.611406] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 139.643057] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 143.982993] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 156.363141] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 156.466354] Lustre: 6511: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 [ 156.499678] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 156.502688] Lustre: Skipped 1 previous similar message [ 156.531636] Lustre: lustre-MDT0001: Not available for connect from 0@lo (not set up) [ 156.584321] Lustre: lustre-MDT0001: new disk, initializing [ 156.662400] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 156.697066] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 156.709473] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 161.457761] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 165.902547] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 174.959194] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 175.167720] Lustre: lustre-OST0000: new disk, initializing [ 175.173192] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 175.180263] Lustre: 8446:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 175.281976] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 180.812576] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 180.824425] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 180.899639] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 181.043272] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 194.372656] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 194.500856] Lustre: lustre-OST0001: new disk, initializing [ 194.505607] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 194.511892] Lustre: 9519:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 194.576984] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 201.097827] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 204.321228] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 204.335201] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 204.379741] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 214.204815] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 221.344834] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 227.467794] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing check_logdir /tmp/testlogs/ [ 232.048826] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing yml_node [ 235.667287] Lustre: DEBUG MARKER: Client: 2.17.54.162 [ 238.010329] Lustre: DEBUG MARKER: MDS: 2.17.54.162 [ 240.151912] Lustre: DEBUG MARKER: OSS: 2.17.54.162 [ 241.357808] Lustre: DEBUG MARKER: -----============= acceptance-small: replay-dual ============----- Mon Jul 13 09:58:16 EDT 2026 [ 256.743820] Lustre: DEBUG MARKER: excepting tests: 14b 21b [ 258.324226] Lustre: DEBUG MARKER: skipping tests SLOW=no: 21b [ 260.033763] Lustre: DEBUG MARKER: === replay-dual: start setup 09:58:34 (1783951114) === [ 266.346908] Lustre: DEBUG MARKER: oleg235-client.virtnet: executing check_config_client /mnt/lustre [ 282.903327] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 287.036471] Lustre: 13377:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 291.497256] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug -1 all [ 296.761769] Lustre: DEBUG MARKER: === replay-dual: finish setup 09:59:11 (1783951151) === [ 298.662500] Lustre: DEBUG MARKER: == replay-dual test 0a: expired recovery with lost client ========================================================== 09:59:13 (1783951153) [ 306.091528] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 310.346390] Lustre: Failing over lustre-MDT0000 [ 310.647794] Lustre: server umount lustre-MDT0000 complete [ 311.781228] 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 [ 311.794452] Lustre: Skipped 3 previous similar messages [ 316.901259] LustreError: 6518:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 316.917301] LustreError: 6518:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 10 previous similar messages [ 322.016797] LustreError: 9379:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 322.032493] LustreError: 9379:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 5 previous similar messages [ 327.143030] LustreError: 6522:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 327.167148] LustreError: 6522:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 5 previous similar messages [ 328.162812] Lustre: 3644:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1783951168/real 1783951168] req@ffff9ef17f6e4700 x1870608115805568/t0(0) o400->MGC192.168.202.135@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1783951184 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 328.185063] LustreError: MGC192.168.202.135@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 332.394275] LustreError: 9026:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.202.35@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 332.411220] LustreError: 9026:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 8 previous similar messages [ 332.437765] LDISKFS-fs (dm-0): 10 truncates cleaned up [ 332.442800] LDISKFS-fs (dm-0): recovery complete [ 332.459575] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 338.417106] LustreError: 6523:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 338.436629] LustreError: 6523:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 9 previous similar messages [ 338.547633] Lustre: lustre-MDT0000: Not available for connect from 192.168.202.35@tcp (not set up) [ 338.555302] Lustre: Skipped 1 previous similar message [ 338.706967] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 340.362362] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 343.234616] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug -1 all [ 344.066242] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 446.500172] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 446.508315] Lustre: 14919:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 4e6f3936-4d27-4c50-8445-3699553787f3@192.168.202.35@tcp [ 446.519553] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 446.547356] Lustre: lustre-MDT0000-osp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 446.568251] Lustre: Skipped 2 previous similar messages [ 446.578580] Lustre: 14919:0:(ldlm_lib.c:2950:target_recovery_thread()) too long recovery - read logs [ 446.600273] LustreError: dumping log to /tmp/lustre-log.1783951302.14919 [ 446.669737] Lustre: lustre-MDT0000: Recovery over after 1:46, of 3 clients 2 recovered and 1 was evicted. [ 446.718825] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:28 to 0x2c0000401:65) [ 446.719724] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:28 to 0x280000401:65) [ 467.298615] Lustre: DEBUG MARKER: == replay-dual test 0b: lost client during waiting for next transno ========================================================== 10:02:02 (1783951322) [ 475.460809] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 478.028550] Lustre: Failing over lustre-MDT0000 [ 478.501852] Lustre: server umount lustre-MDT0000 complete [ 480.414624] LustreError: 6518:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.202.35@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 482.272974] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 482.295030] 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 [ 482.323272] Lustre: Skipped 2 previous similar messages [ 497.636142] LustreError: 9379:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 497.660208] LustreError: 9379:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 18 previous similar messages [ 498.655106] Lustre: 3641:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1783951338/real 1783951338] req@ffff9ef15faec000 x1870608115885952/t0(0) o400->MGC192.168.202.135@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1783951354 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 498.670327] LustreError: MGC192.168.202.135@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 501.959083] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 501.961054] LDISKFS-fs (dm-0): recovery complete [ 501.967610] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 508.403395] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 509.635366] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 512.708330] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug -1 all [ 513.546246] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 525.790118] Lustre: lustre-MDT0000: Denying connection for new client 496473be-80ec-43c8-9b36-5ded62500631 (at 192.168.202.35@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:53 [ 531.058955] Lustre: lustre-MDT0000: Denying connection for new client 496473be-80ec-43c8-9b36-5ded62500631 (at 192.168.202.35@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:48 [ 536.184947] Lustre: lustre-MDT0000: Denying connection for new client 496473be-80ec-43c8-9b36-5ded62500631 (at 192.168.202.35@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:43 [ 541.307839] Lustre: lustre-MDT0000: Denying connection for new client 496473be-80ec-43c8-9b36-5ded62500631 (at 192.168.202.35@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:38 [ 544.264991] Lustre: lustre-MDT0001: haven't heard from client 4e6f3936-4d27-4c50-8445-3699553787f3 (at 192.168.202.35@tcp) in 101 seconds. I think it's dead, and I am evicting it. exp ffff9ef17f622000, cur 1783951400 deadline 1783951399 last 1783951299 [ 546.418873] Lustre: lustre-MDT0000: Denying connection for new client 496473be-80ec-43c8-9b36-5ded62500631 (at 192.168.202.35@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:33 [ 556.664292] Lustre: lustre-MDT0000: Denying connection for new client 496473be-80ec-43c8-9b36-5ded62500631 (at 192.168.202.35@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:22 [ 556.673052] Lustre: Skipped 1 previous similar message [ 577.130791] Lustre: lustre-MDT0000: Denying connection for new client 496473be-80ec-43c8-9b36-5ded62500631 (at 192.168.202.35@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:02 [ 577.140174] Lustre: Skipped 3 previous similar messages [ 579.500377] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 579.513045] Lustre: 16676:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client c2a825d0-9537-499a-8731-8d86674e9bc4@ [ 579.536733] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 612.977997] Lustre: lustre-MDT0000: Denying connection for new client 496473be-80ec-43c8-9b36-5ded62500631 (at 192.168.202.35@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 1 evicted) to recover in 1:07 [ 612.979162] Lustre: lustre-MDT0001: haven't heard from client 38d1b8b2-c182-4afa-9254-e4396f664874 (at 192.168.202.35@tcp) in 102 seconds. I think it's dead, and I am evicting it. exp ffff9ef17f610000, cur 1783951469 deadline 1783951467 last 1783951367 [ 613.004611] Lustre: Skipped 6 previous similar messages [ 679.539941] Lustre: lustre-MDT0000: Denying connection for new client 496473be-80ec-43c8-9b36-5ded62500631 (at 192.168.202.35@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 1 evicted) to recover in 0:00 [ 679.566794] Lustre: Skipped 12 previous similar messages [ 680.500594] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 680.505410] Lustre: 16676:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 38d1b8b2-c182-4afa-9254-e4396f664874@192.168.202.35@tcp [ 680.521591] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 680.533172] Lustre: 16676:0:(ldlm_lib.c:2084:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 680.558428] Lustre: 16676:0:(ldlm_lib.c:2950:target_recovery_thread()) too long recovery - read logs [ 680.565535] Lustre: lustre-MDT0000-osp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 680.567926] LustreError: dumping log to /tmp/lustre-log.1783951536.16676 [ 680.594351] Lustre: Skipped 2 previous similar messages [ 680.761145] Lustre: lustre-MDT0000: Recovery over after 2:51, of 3 clients 1 recovered and 2 were evicted. [ 680.862088] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:28 to 0x280000401:97) [ 680.864049] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:28 to 0x2c0000401:97) [ 692.831602] Lustre: DEBUG MARKER: == replay-dual test 1: |X| simple create ================= 10:05:47 (1783951547) [ 702.025193] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 704.040762] Lustre: Failing over lustre-MDT0000 [ 704.437423] Lustre: server umount lustre-MDT0000 complete [ 706.176092] LustreError: 6517:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.202.35@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 706.188437] LustreError: 6517:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 15 previous similar messages [ 706.531995] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 706.533864] 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 [ 706.560246] Lustre: Skipped 1 previous similar message [ 724.449265] Lustre: 3641:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1783951564/real 1783951564] req@ffff9ef17f6b3100 x1870608115987712/t0(0) o400->MGC192.168.202.135@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1783951580 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 724.497271] LustreError: MGC192.168.202.135@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 729.769219] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 729.770613] LDISKFS-fs (dm-0): recovery complete [ 729.778373] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 734.690897] LustreError: 3640:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9ef16dde2680 x1870608115996160/t0(0) o250->MGC192.168.202.135@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 [ 735.148031] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 735.237352] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 736.068180] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 740.345629] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 740.486083] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug -1 all [ 740.537732] Lustre: lustre-MDT0000: Recovery over after 0:04, of 3 clients 3 recovered and 0 were evicted. [ 740.596277] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:129) [ 740.596100] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:129) [ 751.323188] Lustre: DEBUG MARKER: oleg235-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 753.265706] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 762.268874] Lustre: DEBUG MARKER: == replay-dual test 2: |X| mkdir adir ==================== 10:06:57 (1783951617) [ 770.355241] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 772.784155] Lustre: Failing over lustre-MDT0000 [ 773.215647] Lustre: server umount lustre-MDT0000 complete [ 776.171582] 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 [ 776.190239] LustreError: 6516:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 776.207088] Lustre: Skipped 6 previous similar messages [ 776.225029] LustreError: 6516:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 46 previous similar messages [ 792.543352] Lustre: 3643:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1783951632/real 1783951632] req@ffff9ef0421f3b80 x1870608116027136/t0(0) o400->MGC192.168.202.135@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1783951648 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 792.564553] LustreError: MGC192.168.202.135@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 795.985686] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 795.987200] LDISKFS-fs (dm-0): recovery complete [ 795.998517] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 801.764321] LustreError: 3640:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9ef15f511c00 x1870608116035712/t0(0) o250->MGC192.168.202.135@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 [ 802.159350] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 802.221672] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 803.439466] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 807.177606] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug -1 all [ 807.404524] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 807.411975] Lustre: Skipped 3 previous similar messages [ 807.578640] Lustre: lustre-MDT0000: Recovery over after 0:04, of 3 clients 3 recovered and 0 were evicted. [ 807.645762] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:161) [ 807.649757] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:161) [ 816.838737] Lustre: DEBUG MARKER: oleg235-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 818.283741] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 825.944353] Lustre: DEBUG MARKER: == replay-dual test 3: |X| mkdir adir, mkdir adir/bdir === 10:08:01 (1783951681) [ 833.569453] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 835.630286] Lustre: Failing over lustre-MDT0000 [ 835.954277] Lustre: server umount lustre-MDT0000 complete [ 838.115323] 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 [ 838.132425] Lustre: Skipped 1 previous similar message [ 854.431237] Lustre: 3642:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1783951694/real 1783951694] req@ffff9ef0421f0700 x1870608116067072/t0(0) o400->MGC192.168.202.135@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1783951710 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 854.502904] LustreError: MGC192.168.202.135@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 859.625022] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 859.630486] LDISKFS-fs (dm-0): recovery complete [ 859.645973] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 864.893450] Lustre: lustre-MDT0000: Not available for connect from 192.168.202.35@tcp (not set up) [ 864.907120] Lustre: Skipped 1 previous similar message [ 865.190786] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 866.096268] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 869.914546] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug -1 all [ 870.393774] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 870.409745] Lustre: Skipped 3 previous similar messages [ 870.534856] Lustre: lustre-MDT0000: Recovery over after 0:04, of 3 clients 3 recovered and 0 were evicted. [ 870.590387] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:193) [ 870.591459] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:193) [ 879.744046] Lustre: DEBUG MARKER: oleg235-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 880.800880] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 888.845791] Lustre: DEBUG MARKER: == replay-dual test 4: |X| mkdir adir (-EEXIST), mkdir adir/bdir ========================================================== 10:09:03 (1783951743) [ 896.747175] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 898.554988] Lustre: Failing over lustre-MDT0000 [ 898.888484] Lustre: server umount lustre-MDT0000 complete [ 901.089591] 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 [ 901.112615] Lustre: Skipped 2 previous similar messages [ 906.217621] LustreError: 6522:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 906.229059] LustreError: 6522:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 81 previous similar messages [ 917.472237] Lustre: 3644:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1783951757/real 1783951757] req@ffff9ef15faee300 x1870608116106368/t0(0) o400->MGC192.168.202.135@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1783951773 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 917.515877] LustreError: MGC192.168.202.135@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 924.099716] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 924.102680] LDISKFS-fs (dm-0): recovery complete [ 924.115090] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 927.728367] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x60c74037e8304ab3 [ 927.745076] Lustre: MGC192.168.202.135@tcp: Connection restored to 0@lo (at 0@lo) [ 927.754304] Lustre: Skipped 3 previous similar messages [ 928.156519] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 928.170454] Lustre: Skipped 1 previous similar message [ 928.254841] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 929.393021] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 931.642653] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug -1 all [ 933.517987] Lustre: lustre-MDT0000: Recovery over after 0:04, of 3 clients 3 recovered and 0 were evicted. [ 933.563600] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:225) [ 933.564829] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:225) [ 942.373445] Lustre: DEBUG MARKER: oleg235-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 944.091080] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 953.272725] Lustre: DEBUG MARKER: == replay-dual test 5: open, unlink |X| close ============ 10:10:08 (1783951808) [ 962.310562] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 964.304618] Lustre: Failing over lustre-MDT0000 [ 964.579680] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 964.587381] 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 [ 964.606905] Lustre: Skipped 1 previous similar message [ 964.644370] Lustre: server umount lustre-MDT0000 complete [ 986.079625] Lustre: 3641:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1783951825/real 1783951825] req@ffff9ef17f711c00 x1870608116145280/t0(0) o400->MGC192.168.202.135@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1783951841 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 986.122323] LustreError: MGC192.168.202.135@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 989.822506] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 989.828854] LDISKFS-fs (dm-0): recovery complete [ 989.839480] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 997.354634] LustreError: 3640:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9ef178c8d880 x1870608116154880/t0(0) o250->MGC192.168.202.135@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 [ 997.709722] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 998.560263] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 1003.006443] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1003.026956] Lustre: Skipped 4 previous similar messages [ 1003.209433] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug -1 all [ 1003.237890] Lustre: lustre-MDT0000: Recovery over after 0:05, of 3 clients 3 recovered and 0 were evicted. [ 1003.278240] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:257) [ 1003.286997] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:257) [ 1013.360822] Lustre: DEBUG MARKER: oleg235-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1015.090863] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1024.409536] Lustre: DEBUG MARKER: == replay-dual test 6: open1, open2, unlink |X| close1 [fail mds1] close2 ========================================================== 10:11:19 (1783951879) [ 1032.177199] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1034.194821] Lustre: Failing over lustre-MDT0000 [ 1034.211307] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1034.219513] 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 [ 1034.235951] Lustre: Skipped 3 previous similar messages [ 1034.247544] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1034.389730] Lustre: server umount lustre-MDT0000 complete [ 1055.202784] Lustre: 3642:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1783951895/real 1783951895] req@ffff9ef178c7b100 x1870608116184576/t0(0) o400->MGC192.168.202.135@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1783951911 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1055.255193] LustreError: MGC192.168.202.135@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1059.307557] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1059.309935] LDISKFS-fs (dm-0): recovery complete [ 1059.316915] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1065.483238] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x60c74037e83057da [ 1066.005386] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1066.008346] Lustre: Skipped 1 previous similar message [ 1066.163309] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1066.604366] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 1071.180560] Lustre: lustre-MDT0000: Recovery over after 0:05, of 3 clients 3 recovered and 0 were evicted. [ 1071.210808] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:289) [ 1071.212185] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:289) [ 1071.660385] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug -1 all [ 1082.789431] Lustre: DEBUG MARKER: oleg235-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1084.430961] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1093.835313] Lustre: DEBUG MARKER: == replay-dual test 8: replay of resent request ========== 10:12:28 (1783951948) [ 1101.608660] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1102.894911] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 1102.901823] LustreError: 15290:0:(ldlm_lib.c:3345:target_send_reply_msg()) @@@ dropping reply req@ffff9ef166e0f100 x1870608098152064/t38654705670(0) o36->496473be-80ec-43c8-9b36-5ded62500631@192.168.202.35@tcp:220/0 lens 512/448 e 0 to 0 dl 1783951970 ref 1 fl Interpret:/200/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 1119.406580] Lustre: lustre-MDT0000: Client 496473be-80ec-43c8-9b36-5ded62500631 (at 192.168.202.35@tcp) reconnecting [ 1119.430396] Lustre: 6518:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9ef171664380 x1870608098152064/t38654705670(0) o36->496473be-80ec-43c8-9b36-5ded62500631@192.168.202.35@tcp:236/0 lens 512/2880 e 0 to 0 dl 1783951986 ref 1 fl Interpret:/202/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 1123.262656] Lustre: Failing over lustre-MDT0000 [ 1123.542397] Lustre: server umount lustre-MDT0000 complete [ 1127.398193] 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 [ 1127.403597] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1127.442864] Lustre: Skipped 5 previous similar messages [ 1142.761714] Lustre: 3644:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1783951983/real 1783951983] req@ffff9ef15fb6c000 x1870608116231424/t0(0) o400->MGC192.168.202.135@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1783951999 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1142.806664] LustreError: MGC192.168.202.135@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1147.574206] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1147.581152] LDISKFS-fs (dm-0): recovery complete [ 1147.595209] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1153.005151] LustreError: 3640:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9ef14662dc00 x1870608116239872/t0(0) o250->MGC192.168.202.135@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 [ 1153.588702] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1154.705199] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 1158.648881] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1158.656845] Lustre: Skipped 8 previous similar messages [ 1158.851508] Lustre: lustre-MDT0000: Recovery over after 0:04, of 3 clients 3 recovered and 0 were evicted. [ 1158.925682] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:321) [ 1158.926835] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:321) [ 1159.247728] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug -1 all [ 1169.646352] Lustre: DEBUG MARKER: oleg235-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1171.594779] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1181.303942] Lustre: DEBUG MARKER: == replay-dual test 9: resending a replayed create ======= 10:13:56 (1783952036) [ 1189.630181] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1192.800720] Lustre: Failing over lustre-MDT0000 [ 1193.077968] Lustre: server umount lustre-MDT0000 complete [ 1194.473399] LustreError: 6523:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1194.484138] LustreError: 6523:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 157 previous similar messages [ 1216.714709] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1216.718676] LDISKFS-fs (dm-0): recovery complete [ 1216.727642] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1220.084638] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x60c74037e8306325 [ 1220.495716] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1225.633855] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug -1 all [ 1225.760727] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 1225.769990] LustreError: 32171:0:(ldlm_lib.c:3345:target_send_reply_msg()) @@@ dropping reply req@ffff9ef171076680 x1870608098170880/t42949672962(42949672962) o36->496473be-80ec-43c8-9b36-5ded62500631@192.168.202.35@tcp:338/0 lens 528/448 e 0 to 0 dl 1783952088 ref 1 fl Complete:/204/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 1237.125612] Lustre: lustre-MDT0000: Client 496473be-80ec-43c8-9b36-5ded62500631 (at 192.168.202.35@tcp) reconnected, waiting for 3 clients in recovery for 1:29 [ 1237.258104] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:353) [ 1237.258323] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:353) [ 1245.805808] Lustre: DEBUG MARKER: oleg235-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1247.640636] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1258.830677] Lustre: DEBUG MARKER: == replay-dual test 10: resending a replayed unlink ====== 10:15:13 (1783952113) [ 1267.739360] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1270.780658] Lustre: Failing over lustre-MDT0000 [ 1271.253698] Lustre: server umount lustre-MDT0000 complete [ 1271.779710] 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 [ 1271.805906] Lustre: Skipped 7 previous similar messages [ 1288.161015] Lustre: 3641:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1783952128/real 1783952128] req@ffff9ef16efeb800 x1870608116309120/t0(0) o400->MGC192.168.202.135@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1783952144 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1288.201335] Lustre: 3641:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 1288.221220] LustreError: MGC192.168.202.135@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1288.232171] LustreError: Skipped 1 previous similar message [ 1295.304415] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1295.306374] LDISKFS-fs (dm-0): recovery complete [ 1295.312061] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1298.404884] LustreError: 3640:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9ef178c7c700 x1870608116317696/t0(0) o250->MGC192.168.202.135@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 [ 1298.566532] Lustre: lustre-MDT0000: Not available for connect from 192.168.202.35@tcp (not set up) [ 1298.581468] Lustre: Skipped 1 previous similar message [ 1298.908787] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1300.346445] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 1300.353388] Lustre: Skipped 1 previous similar message [ 1303.419279] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug -1 all [ 1304.100236] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 1304.110188] LustreError: 34229:0:(ldlm_lib.c:3345:target_send_reply_msg()) @@@ dropping reply req@ffff9ef15fb6e680 x1870608098191104/t47244640260(47244640260) o36->496473be-80ec-43c8-9b36-5ded62500631@192.168.202.35@tcp:417/0 lens 528/448 e 0 to 0 dl 1783952167 ref 1 fl Complete:/204/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 1316.001332] Lustre: lustre-MDT0000: Client 496473be-80ec-43c8-9b36-5ded62500631 (at 192.168.202.35@tcp) reconnected, waiting for 3 clients in recovery for 1:28 [ 1316.165410] Lustre: lustre-MDT0000: Recovery over after 0:16, of 3 clients 3 recovered and 0 were evicted. [ 1316.180337] Lustre: Skipped 1 previous similar message [ 1316.233110] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:385) [ 1316.240850] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:385) [ 1323.671810] Lustre: DEBUG MARKER: oleg235-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1325.800983] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1335.413245] Lustre: DEBUG MARKER: == replay-dual test 11: both clients timeout during replay ========================================================== 10:16:30 (1783952190) [ 1343.035074] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1346.710356] Lustre: Failing over lustre-MDT0000 [ 1347.051335] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1347.281943] Lustre: server umount lustre-MDT0000 complete [ 1371.857641] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1371.864056] LDISKFS-fs (dm-0): recovery complete [ 1371.889750] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1376.224278] LustreError: 3640:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9ef17f775500 x1870608116358528/t0(0) o250->MGC192.168.202.135@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 [ 1376.691986] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1376.702391] Lustre: Skipped 3 previous similar messages [ 1381.574957] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug -1 all [ 1381.911398] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 1381.921827] LustreError: 36286:0:(ldlm_lib.c:3345:target_send_reply_msg()) @@@ dropping reply req@ffff9ef16dde1880 x1870608098210560/t51539607554(51539607554) o36->496473be-80ec-43c8-9b36-5ded62500631@192.168.202.35@tcp:495/0 lens 528/448 e 0 to 0 dl 1783952245 ref 1 fl Complete:/204/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 1389.309509] Lustre: DEBUG MARKER: oleg235-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1393.802750] Lustre: lustre-MDT0000: Client 496473be-80ec-43c8-9b36-5ded62500631 (at 192.168.202.35@tcp) reconnected, waiting for 3 clients in recovery for 1:28 [ 1393.973203] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:417) [ 1393.973840] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:417) [ 1396.384673] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 5 sec [ 1404.269133] Lustre: DEBUG MARKER: == replay-dual test 12: open resend timeout ============== 10:17:39 (1783952259) [ 1412.832611] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1415.688460] Lustre: Failing over lustre-MDT0000 [ 1415.971909] Lustre: server umount lustre-MDT0000 complete [ 1438.662285] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1438.664543] LDISKFS-fs (dm-0): recovery complete [ 1438.671283] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1443.295930] LustreError: 3640:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9ef15f4a0380 x1870608116392448/t0(0) o250->MGC192.168.202.135@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 [ 1443.743881] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1443.754722] Lustre: Skipped 1 previous similar message [ 1448.971434] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 1448.981143] Lustre: Skipped 16 previous similar messages [ 1449.021346] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug -1 all [ 1449.060445] Lustre: *** cfs_fail_loc=302, val=2147483648*** [ 1465.466571] Lustre: lustre-MDT0000: Client 496473be-80ec-43c8-9b36-5ded62500631 (at 192.168.202.35@tcp) reconnected, waiting for 3 clients in recovery for 1:24 [ 1465.588574] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:449) [ 1465.589199] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:449) [ 1472.627875] Lustre: DEBUG MARKER: == replay-dual test 13: close resend timeout ============= 10:18:47 (1783952327) [ 1479.604318] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1482.558383] Lustre: Failing over lustre-MDT0000 [ 1482.972832] Lustre: server umount lustre-MDT0000 complete [ 1505.491049] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1505.493465] LDISKFS-fs (dm-0): recovery complete [ 1505.501342] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1511.397677] LustreError: 3640:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9ef0410f2d80 x1870608116427776/t0(0) o250->MGC192.168.202.135@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 [ 1511.531312] Lustre: lustre-MDT0000: Not available for connect from 192.168.202.35@tcp (not set up) [ 1517.218828] Lustre: *** cfs_fail_loc=115, val=2147483648*** [ 1517.780668] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug -1 all [ 1533.592615] Lustre: lustre-MDT0000: Client 496473be-80ec-43c8-9b36-5ded62500631 (at 192.168.202.35@tcp) reconnected, waiting for 3 clients in recovery for 1:23 [ 1533.757185] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:481) [ 1533.763034] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:481) [ 1543.764862] Lustre: DEBUG MARKER: SKIP: replay-dual test_14b skipping ALWAYS excluded test 14b [ 1546.317962] Lustre: DEBUG MARKER: == replay-dual test 15a: timeout waiting for lost client during replay, 1 client completes ========================================================== 10:20:00 (1783952400) [ 1555.181437] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1558.713882] Lustre: Failing over lustre-MDT0000 [ 1559.053727] Lustre: server umount lustre-MDT0000 complete [ 1559.520543] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1559.531846] 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 [ 1559.556578] Lustre: Skipped 13 previous similar messages [ 1580.000442] Lustre: 3643:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1783952419/real 1783952419] req@ffff9ef178e91880 x1870608116460032/t0(0) o400->MGC192.168.202.135@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1783952435 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1580.043433] Lustre: 3643:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 1580.048636] LustreError: MGC192.168.202.135@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1580.068751] LustreError: Skipped 3 previous similar messages [ 1584.853798] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1584.856328] LDISKFS-fs (dm-0): recovery complete [ 1584.870260] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1590.381816] Lustre: lustre-MDT0000: Not available for connect from 192.168.202.35@tcp (not set up) [ 1590.385396] Lustre: Skipped 1 previous similar message [ 1591.676383] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 1591.683595] Lustre: Skipped 3 previous similar messages [ 1596.009042] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug -1 all [ 1661.500195] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 1661.509745] Lustre: 41955:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client dddd4970-3837-480b-a72e-8fd8af9f83c4@ [ 1661.526783] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 1662.174530] Lustre: lustre-MDT0000: Recovery over after 1:11, of 3 clients 2 recovered and 1 was evicted. [ 1662.189124] Lustre: Skipped 3 previous similar messages [ 1662.237512] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:495 to 0x2c0000401:513) [ 1662.239093] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:494 to 0x280000401:513) [ 1671.000898] Lustre: DEBUG MARKER: oleg235-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1672.936623] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1683.386369] Lustre: DEBUG MARKER: == replay-dual test 15c: remove multiple OST orphans ===== 10:22:18 (1783952538) [ 1691.541635] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1791.486212] Lustre: Failing over lustre-MDT0000 [ 1791.994445] Lustre: server umount lustre-MDT0000 complete [ 1794.165579] LustreError: 6516:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.202.35@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1794.188971] LustreError: 6516:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 221 previous similar messages [ 1795.555051] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1815.693493] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1815.695696] LDISKFS-fs (dm-0): recovery complete [ 1815.701662] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1821.168208] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x60c74037e8324bb2 [ 1821.599353] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1821.616789] Lustre: Skipped 2 previous similar messages [ 1827.667887] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug -1 all [ 1893.510099] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 1893.525740] Lustre: 43967:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client e0a6182e-d4f5-4ee6-b208-2953141448a6@ [ 1893.530597] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 1893.636048] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:495 to 0x2c0000401:1537) [ 1893.636757] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:494 to 0x280000401:1537) [ 1901.447545] Lustre: DEBUG MARKER: oleg235-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1903.713626] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1913.400178] Lustre: DEBUG MARKER: == replay-dual test 16: fail MDS during recovery (3571) == 10:26:08 (1783952768) [ 1921.792529] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1924.996503] Lustre: Failing over lustre-MDT0000 [ 1925.422310] Lustre: server umount lustre-MDT0000 complete [ 1950.369930] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1950.379093] LDISKFS-fs (dm-0): recovery complete [ 1950.399107] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1955.450977] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1955.459919] Lustre: Skipped 4 previous similar messages [ 1962.081939] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug -1 all [ 1988.695975] Lustre: Failing over lustre-MDT0000 [ 1988.713748] LustreError: 46422:0:(ldlm_lib.c:3003:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 1988.737059] Lustre: 45948:0:(ldlm_lib.c:2403:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 1988.751904] Lustre: 45948:0:(ldlm_lib.c:1913:abort_req_replay_queue()) @@@ aborted: req@ffff9ef15f5f1c00 x1870608100667776/t0(73014444033) o36->496473be-80ec-43c8-9b36-5ded62500631@192.168.202.35@tcp:355/0 lens 528/0 e 3 to 0 dl 1783952860 ref 1 fl Complete:/204/ffffffff rc 0/-1 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 1988.776416] Lustre: lustre-MDT0000-osd: cancel update llog [0x200000400:0x1:0x0] [ 1988.800535] Lustre: lustre-MDT0001-osp-MDT0000: cancel update llog [0x240000401:0x1:0x0] [ 1988.813814] LustreError: 45948:0:(client.c:1381:ptlrpc_import_delay_req()) @@@ IMP_CLOSED req@ffff9ef047b3b800 x1870608116665600/t0(0) o700->lustre-MDT0001-osp-MDT0000@0@lo:30/10 lens 264/248 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 [ 1988.817091] Lustre: lustre-MDT0000: Not available for connect from 192.168.202.35@tcp (stopping) [ 1988.845412] LustreError: 45948:0:(fid_request.c:217:seq_client_alloc_seq()) cli-cli-lustre-MDT0001-osp-MDT0000: Cannot allocate new meta-sequence: rc = -5 [ 1988.845429] LustreError: 45948:0:(fid_request.c:321:seq_client_alloc_fid()) cli-cli-lustre-MDT0001-osp-MDT0000: Can't allocate new sequence: rc = -5 [ 1989.135984] Lustre: server umount lustre-MDT0000 complete [ 2009.164826] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2016.771421] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x60c74037e8328e78 [ 2016.812905] Lustre: MGC192.168.202.135@tcp: Connection restored to 0@lo (at 0@lo) [ 2016.817775] Lustre: Skipped 19 previous similar messages [ 2021.976906] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug -1 all [ 2088.500323] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 2088.505286] Lustre: 46880:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 46a5948f-09b5-4f72-8e38-0eb25277988d@ [ 2088.519458] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 2089.096180] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1550 to 0x280000401:1569) [ 2089.096500] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1551 to 0x2c0000401:1569) [ 2095.818554] Lustre: DEBUG MARKER: oleg235-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2097.212572] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2108.246280] Lustre: DEBUG MARKER: == replay-dual test 17: fail OST during recovery (3571) == 10:29:22 (1783952962) [ 2118.869719] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 2121.636286] Lustre: Failing over lustre-OST0000 [ 2121.698493] LustreError: lustre-OST0000-osc-MDT0001: operation ost_statfs to node 0@lo failed: rc = -107 [ 2121.719397] Lustre: lustre-OST0000-osc-MDT0001: Connection to lustre-OST0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 2121.733656] Lustre: Skipped 14 previous similar messages [ 2121.922902] Lustre: server umount lustre-OST0000 complete [ 2146.729529] LDISKFS-fs (dm-2): 3 truncates cleaned up [ 2146.733065] LDISKFS-fs (dm-2): recovery complete [ 2146.744424] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2147.440796] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 4 clients reconnect [ 2147.452286] Lustre: Skipped 3 previous similar messages [ 2154.346976] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug -1 all [ 2179.006071] Lustre: Failing over lustre-OST0000 [ 2179.011863] LustreError: 49400:0:(ldlm_lib.c:3003:target_stop_recovery_thread()) lustre-OST0000: Aborting recovery [ 2179.017485] Lustre: 48837:0:(ldlm_lib.c:2403:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 2179.023875] Lustre: 48837:0:(ldlm_lib.c:2403:target_recovery_overseer()) Skipped 2 previous similar messages [ 2179.028869] LustreError: 48837:0:(ofd_obd.c:1324:ofd_iocontrol()) lustre-OST0000: iocontrol from 'tgt_recover_0' cmd=c00866c1 _IOWR('f', 193, 8) unrecognized: rc = -25 [ 2179.036282] Lustre: lustre-OST0000: Recovery over after 0:32, of 4 clients 0 recovered and 4 were evicted. [ 2179.047306] Lustre: Skipped 3 previous similar messages [ 2179.124917] Lustre: server umount lustre-OST0000 complete [ 2198.333290] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2200.736402] Lustre: 3640:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1783953004/real 1783953004] req@ffff9ef16ddd0000 x1870608116744832/t0(0) o400->lustre-OST0000-osc-MDT0001@0@lo:28/4 lens 224/224 e 3 to 1 dl 1783953057 ref 1 fl Rpc:XQr/2c0/ffffffff rc 0/-1 job:'ldlm_lock_repla.0' uid:0 gid:0 projid:4294967295 [ 2200.769390] Lustre: 3640:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 4 previous similar messages [ 2204.536409] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug -1 all [ 2270.500215] Lustre: lustre-OST0000: recovery is timed out, evict stale exports [ 2270.507633] Lustre: 49840:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-OST0000: disconnect stale client 567a4687-aed3-4c9e-988e-26312bc76959@ [ 2270.522729] Lustre: lustre-OST0000: disconnecting 1 stale clients [ 2275.315855] Lustre: DEBUG MARKER: oleg235-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 2276.589982] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 2286.402466] Lustre: DEBUG MARKER: == replay-dual test 18: ldlm_handle_enqueue succeeds on evicted export (3822) ========================================================== 10:32:21 (1783953141) [ 2290.683335] LustreError: 6517:0:(ldlm_lockd.c:1361:ldlm_handle_enqueue()) cfs_fail_timeout id 30b sleeping for 40000ms [ 2330.751857] LustreError: 6517:0:(ldlm_lockd.c:1361:ldlm_handle_enqueue()) cfs_fail_timeout id 30b awake [ 2347.151499] Lustre: DEBUG MARKER: == replay-dual test 19: resend of open request =========== 10:33:21 (1783953201) [ 2356.059147] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2357.351621] Lustre: *** cfs_fail_loc=157, val=2147483648*** [ 2357.358396] LustreError: 6518:0:(ldlm_lib.c:3345:target_send_reply_msg()) @@@ dropping reply req@ffff9ef0476c9c00 x1870608100794752/t0(0) o101->496473be-80ec-43c8-9b36-5ded62500631@192.168.202.35@tcp:36/0 lens 576/688 e 0 to 0 dl 1783953296 ref 1 fl Interpret:/600/0 rc 0/0 job:'createmany.0' uid:0 gid:0 projid:0 [ 2445.424516] Lustre: lustre-MDT0000: Client 496473be-80ec-43c8-9b36-5ded62500631 (at 192.168.202.35@tcp) reconnecting [ 2449.383403] Lustre: Failing over lustre-MDT0000 [ 2449.667948] Lustre: server umount lustre-MDT0000 complete [ 2450.569900] LustreError: 15290:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.202.35@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 2450.607269] LustreError: 15290:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 112 previous similar messages [ 2467.300850] LustreError: MGC192.168.202.135@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2467.323575] LustreError: Skipped 3 previous similar messages [ 2473.232471] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2473.238409] LDISKFS-fs (dm-0): recovery complete [ 2473.248758] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2477.539256] LustreError: 3640:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9ef0491d6680 x1870608116895360/t0(0) o250->MGC192.168.202.135@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 [ 2478.014218] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 2478.021491] Lustre: Skipped 4 previous similar messages [ 2483.240120] Lustre: 52488:0:(ldlm_lib.c:2084:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 2483.484918] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1584 to 0x280000401:1601) [ 2483.497352] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1584 to 0x2c0000401:1601) [ 2483.939376] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug -1 all [ 2495.339568] Lustre: DEBUG MARKER: oleg235-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2497.186225] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2506.196646] Lustre: DEBUG MARKER: == replay-dual test 20: recovery time is not increasing == 10:36:01 (1783953361) [ 2514.258984] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2516.489893] Lustre: Failing over lustre-MDT0000 [ 2516.871335] Lustre: server umount lustre-MDT0000 complete [ 2539.761510] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2539.765400] LDISKFS-fs (dm-0): recovery complete [ 2539.775761] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2545.065561] LustreError: 3640:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9ef1714ac380 x1870608116932224/t0(0) o250->MGC192.168.202.135@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 [ 2550.614385] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug -1 all [ 2687.500159] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 2687.505821] Lustre: 54426:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client cb68b8b0-5c10-45df-9e38-919a1f42cb9a@ [ 2687.525445] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 2687.573724] Lustre: 54426:0:(ldlm_lib.c:2084:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 2687.587691] Lustre: 54426:0:(ldlm_lib.c:2084:extend_recovery_timer()) Skipped 6 previous similar messages [ 2687.651562] Lustre: lustre-MDT0000-osp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 2687.658131] Lustre: Skipped 13 previous similar messages [ 2687.692744] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1584 to 0x2c0000401:1633) [ 2687.703983] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1603 to 0x280000401:1633) [ 2693.973485] Lustre: DEBUG MARKER: oleg235-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2695.846050] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2706.114516] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2708.311486] Lustre: Failing over lustre-MDT0000 [ 2708.451528] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 2708.460980] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2708.642984] Lustre: server umount lustre-MDT0000 complete [ 2729.697639] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2729.702145] LDISKFS-fs (dm-0): recovery complete [ 2729.711606] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2735.074768] LustreError: 3640:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9ef048b21f80 x1870608117011840/t0(0) o250->MGC192.168.202.135@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 [ 2735.210810] Lustre: lustre-MDT0000: Not available for connect from 192.168.202.35@tcp (not set up) [ 2735.407054] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 2735.412761] Lustre: Skipped 5 previous similar messages [ 2739.581558] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug -1 all [ 2879.500357] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 2879.513781] Lustre: 56212:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 26f5a01f-1a93-4e6c-97f5-28ecaa6c05ae@ [ 2879.539523] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 2879.582386] Lustre: 56212:0:(ldlm_lib.c:2084:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 2879.593910] Lustre: 56212:0:(ldlm_lib.c:2084:extend_recovery_timer()) Skipped 4 previous similar messages [ 2879.680703] Lustre: lustre-MDT0000: Recovery over after 2:22, of 3 clients 2 recovered and 1 was evicted. [ 2879.688543] Lustre: Skipped 3 previous similar messages [ 2879.722138] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1584 to 0x2c0000401:1665) [ 2879.725278] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1635 to 0x280000401:1665) [ 2884.987375] Lustre: DEBUG MARKER: oleg235-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2886.239713] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2893.912939] Lustre: DEBUG MARKER: == replay-dual test 21a: commit on sharing =============== 10:42:29 (1783953749) [ 2901.383883] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2903.160521] Lustre: Failing over lustre-MDT0000 [ 2903.385475] Lustre: server umount lustre-MDT0000 complete [ 2904.569114] 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 [ 2904.581947] Lustre: Skipped 15 previous similar messages [ 2919.903195] Lustre: 3642:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1783953760/real 1783953760] req@ffff9ef178fcca80 x1870608117085952/t0(0) o400->MGC192.168.202.135@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1783953776 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2919.938381] Lustre: 3642:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 4 previous similar messages [ 2925.197150] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2925.202077] LDISKFS-fs (dm-0): recovery complete [ 2925.215850] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2930.145215] LustreError: 3640:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9ef0476c9500 x1870608117093504/t0(0) o250->MGC192.168.202.135@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 [ 2930.288701] Lustre: lustre-MDT0000: Not available for connect from 192.168.202.35@tcp (not set up) [ 2931.784296] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 2931.794487] Lustre: Skipped 4 previous similar messages [ 2934.156050] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug -1 all [ 3072.501250] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 3072.510077] Lustre: 58239:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client f45de3b6-f254-4135-b01a-2c3c1b4b5797@ [ 3072.528436] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 3072.599266] Lustre: 58239:0:(ldlm_lib.c:2084:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3072.609939] Lustre: 58239:0:(ldlm_lib.c:2084:extend_recovery_timer()) Skipped 4 previous similar messages [ 3072.666291] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1635 to 0x280000401:1697) [ 3072.666291] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1667 to 0x2c0000401:1697) [ 3080.641883] Lustre: DEBUG MARKER: SKIP: replay-dual test_21b skipping SLOW test 21b [ 3082.022670] Lustre: DEBUG MARKER: == replay-dual test 22a: c1 lfs mkdir -i 1 dir1, M1 drop reply [ 3083.046889] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 3083.051137] LustreError: 9026:0:(ldlm_lib.c:3345:target_send_reply_msg()) @@@ dropping reply req@ffff9ef0491a2680 x1870608100915328/t4294967333(0) o36->496473be-80ec-43c8-9b36-5ded62500631@192.168.202.35@tcp:6/0 lens 560/448 e 0 to 0 dl 1783954021 ref 1 fl Interpret:/200/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 3085.442371] Lustre: Failing over lustre-MDT0001 [ 3085.891164] Lustre: server umount lustre-MDT0001 complete [ 3088.529116] LustreError: 6517:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0001: not available for connect from 192.168.202.35@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3088.548605] LustreError: 6517:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 134 previous similar messages [ 3089.376559] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 3103.631817] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3103.874569] Lustre: lustre-MDT0001: Not available for connect from 192.168.202.35@tcp (not set up) [ 3104.314653] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 3104.331491] Lustre: Skipped 3 previous similar messages [ 3108.888084] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug -1 all [ 3109.484212] Lustre: 15290:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9ef16ddedc00 x1870608100915328/t4294967333(0) o36->496473be-80ec-43c8-9b36-5ded62500631@192.168.202.35@tcp:32/0 lens 560/2880 e 0 to 0 dl 1783954047 ref 1 fl Interpret:/202/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 3118.798632] Lustre: DEBUG MARKER: oleg235-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 3120.307705] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3129.514479] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3132.099075] Lustre: Failing over lustre-MDT0000 [ 3132.371362] Lustre: server umount lustre-MDT0000 complete [ 3151.335876] LustreError: MGC192.168.202.135@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3151.362557] LustreError: Skipped 3 previous similar messages [ 3154.282688] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3154.287718] LDISKFS-fs (dm-0): recovery complete [ 3154.297152] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3161.569724] LustreError: 3640:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9ef0410f1180 x1870608117200768/t0(0) o250->MGC192.168.202.135@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 [ 3166.932419] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug -1 all [ 3167.344026] Lustre: 61304:0:(ldlm_lib.c:2084:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3167.455907] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1635 to 0x280000401:1729) [ 3167.461942] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1667 to 0x2c0000401:1729) [ 3176.135616] Lustre: DEBUG MARKER: oleg235-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3177.715440] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3185.983786] Lustre: DEBUG MARKER: == replay-dual test 22b: c1 lfs mkdir -i 1 d1, M1 drop reply [ 3187.039729] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 3187.042658] LustreError: 6516:0:(ldlm_lib.c:3345:target_send_reply_msg()) @@@ dropping reply req@ffff9ef0491d7100 x1870608100955648/t8589934617(0) o36->496473be-80ec-43c8-9b36-5ded62500631@192.168.202.35@tcp:110/0 lens 560/448 e 0 to 0 dl 1783954125 ref 1 fl Interpret:/200/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 3189.642094] Lustre: Failing over lustre-MDT0000 [ 3189.970200] Lustre: server umount lustre-MDT0000 complete [ 3191.794657] LustreError: 6501:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1783954048 with bad export cookie 6973613156869522777 [ 3193.608177] LustreError: 6502:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1783954049 with bad export cookie 6973613156869522672 [ 3193.612154] Lustre: Failing over lustre-MDT0001 [ 3193.628757] LustreError: 62446:0:(client.c:1381:ptlrpc_import_delay_req()) @@@ IMP_CLOSED req@ffff9ef04927ad80 x1870608117233536/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 [ 3193.647721] LustreError: 62446:0:(osp_object.c:618:osp_attr_get()) lustre-MDT0000-osp-MDT0001: osp_attr_get update error [0x200000401:0x1:0x0]: rc = -5 [ 3193.972628] Lustre: server umount lustre-MDT0001 complete [ 3213.623650] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3213.631387] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3213.988241] LustreError: 63154:0:(llog.c:1655:llog_backup()) MGC192.168.202.135@tcp: failed to open log lustre-sptlrpc: rc = -108 [ 3213.994687] Lustre: 63154:0:(mgc_request_server.c:770:mgc_llog_local_copy()) MGC192.168.202.135@tcp: failed to copy new config lustre-sptlrpc: rc = -108 [ 3223.523471] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug -1 all [ 3223.946444] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug -1 all [ 3224.647091] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1635 to 0x280000401:1761) [ 3224.647176] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1667 to 0x2c0000401:1761) [ 3224.833606] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:36 to 0x2c0000400:65) [ 3224.835638] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:36 to 0x280000400:65) [ 3224.838356] Lustre: 63183:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9ef048bce300 x1870608100955648/t8589934617(0) o36->496473be-80ec-43c8-9b36-5ded62500631@192.168.202.35@tcp:148/0 lens 560/2880 e 0 to 0 dl 1783954163 ref 1 fl Interpret:/202/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 3233.333231] Lustre: DEBUG MARKER: oleg235-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 [ 3234.789772] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3236.016198] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3244.392500] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3246.719616] Lustre: Failing over lustre-MDT0000 [ 3247.051490] Lustre: server umount lustre-MDT0000 complete [ 3269.222716] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3269.225849] LDISKFS-fs (dm-0): recovery complete [ 3269.233126] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3274.741917] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x60c74037e832d520 [ 3278.853708] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug -1 all [ 3280.409565] Lustre: 65378:0:(ldlm_lib.c:2084:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3280.422332] Lustre: 65378:0:(ldlm_lib.c:2084:extend_recovery_timer()) Skipped 4 previous similar messages [ 3280.528827] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1667 to 0x2c0000401:1793) [ 3280.534938] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1635 to 0x280000401:1793) [ 3288.056951] Lustre: DEBUG MARKER: oleg235-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3289.455592] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3298.378538] Lustre: DEBUG MARKER: == replay-dual test 22c: c1 lfs mkdir -i 1 d1, M1 drop update [ 3299.405311] Lustre: *** cfs_fail_loc=1701, val=2147483648*** [ 3299.410871] LustreError: 8441:0:(ldlm_lib.c:3345:target_send_reply_msg()) @@@ dropping reply req@ffff9ef0491a1180 x1870608117303168/t107374182411(0) o1000->lustre-MDT0001-mdtlov_UUID@0@lo:151/0 lens 2520/4320 e 0 to 0 dl 1783954166 ref 1 fl Interpret:/200/0 rc 0/0 job:'osp_up0-1.0' uid:0 gid:0 projid:4294967295 [ 3302.478238] Lustre: Failing over lustre-MDT0000 [ 3302.520686] Lustre: lustre-MDT0000: Not available for connect from 192.168.202.35@tcp (stopping) [ 3302.531077] Lustre: Skipped 1 previous similar message [ 3302.811794] Lustre: server umount lustre-MDT0000 complete [ 3320.961554] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3325.829103] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug -1 all [ 3326.970640] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 3326.978440] Lustre: Skipped 26 previous similar messages [ 3327.164176] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1635 to 0x280000401:1825) [ 3327.168424] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1667 to 0x2c0000401:1825) [ 3337.613369] Lustre: DEBUG MARKER: oleg235-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3339.464709] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3350.623088] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3353.899107] Lustre: Failing over lustre-MDT0000 [ 3354.194936] Lustre: server umount lustre-MDT0000 complete [ 3379.425055] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3379.430223] LDISKFS-fs (dm-0): recovery complete [ 3379.447678] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3383.604769] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3383.611790] Lustre: Skipped 7 previous similar messages [ 3388.665477] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug -1 all [ 3388.991250] Lustre: 68569:0:(ldlm_lib.c:2084:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3389.011142] Lustre: 68569:0:(ldlm_lib.c:2084:extend_recovery_timer()) Skipped 4 previous similar messages [ 3389.161455] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1635 to 0x280000401:1857) [ 3389.161542] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1667 to 0x2c0000401:1857) [ 3399.090870] Lustre: DEBUG MARKER: oleg235-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3400.850907] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3409.022403] Lustre: DEBUG MARKER: == replay-dual test 22d: c1 lfs mkdir -i 1 d1, M1 drop update [ 3414.031034] Lustre: *** cfs_fail_loc=1701, val=2147483648*** [ 3414.034541] LustreError: 8440:0:(ldlm_lib.c:3345:target_send_reply_msg()) @@@ dropping reply req@ffff9ef171634e00 x1870608117375360/t115964117002(0) o1000->lustre-MDT0001-mdtlov_UUID@0@lo:266/0 lens 2520/4320 e 0 to 0 dl 1783954281 ref 1 fl Interpret:/200/0 rc 0/0 job:'osp_up0-1.0' uid:0 gid:0 projid:4294967295 [ 3417.293637] Lustre: Failing over lustre-MDT0000 [ 3417.534266] Lustre: server umount lustre-MDT0000 complete [ 3421.351531] LustreError: 6501:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1783954277 with bad export cookie 6973613156869530344 [ 3421.361643] LustreError: 6501:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 6 previous similar messages [ 3421.363341] Lustre: Failing over lustre-MDT0001 [ 3421.394485] LustreError: 69810:0:(ldlm_resource.c:1207:ldlm_resource_complain()) lustre-MDT0000-osp-MDT0001: namespace resource [0x2000013a1:0x78:0x0].0xf7117594 (ffff9ef1498ad100) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 3427.415906] Lustre: server umount lustre-MDT0001 complete [ 3447.310274] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3447.333939] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3447.601717] LustreError: 70520:0:(llog.c:1655:llog_backup()) MGC192.168.202.135@tcp: failed to open log lustre-sptlrpc: rc = -108 [ 3447.617823] Lustre: 70520:0:(mgc_request_server.c:770:mgc_llog_local_copy()) MGC192.168.202.135@tcp: failed to copy new config lustre-sptlrpc: rc = -108 [ 3473.480293] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1667 to 0x2c0000401:1889) [ 3473.510634] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1635 to 0x280000401:1889) [ 3473.694296] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:70 to 0x280000400:97) [ 3473.703249] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:70 to 0x2c0000400:97) [ 3473.749299] Lustre: 70527:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9ef0491d3100 x1870608101041408/t12884901939(0) o36->496473be-80ec-43c8-9b36-5ded62500631@192.168.202.35@tcp:395/0 lens 560/2880 e 0 to 0 dl 1783954410 ref 1 fl Interpret:/202/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 3474.143412] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug -1 all [ 3474.573750] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug -1 all [ 3487.438751] Lustre: DEBUG MARKER: oleg235-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 [ 3488.821218] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3490.360561] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3500.310718] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3502.878424] Lustre: Failing over lustre-MDT0000 [ 3503.310083] Lustre: server umount lustre-MDT0000 complete [ 3520.466606] Lustre: 3644:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1783954360/real 1783954360] req@ffff9ef17f712a00 x1870608117419008/t0(0) o400->MGC192.168.202.135@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1783954376 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3520.500947] Lustre: 3644:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 16 previous similar messages [ 3527.468777] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3527.471440] LDISKFS-fs (dm-0): recovery complete [ 3527.478875] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3535.299476] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug -1 all [ 3535.468242] Lustre: 72743:0:(ldlm_lib.c:2084:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3535.484433] Lustre: 72743:0:(ldlm_lib.c:2084:extend_recovery_timer()) Skipped 4 previous similar messages [ 3535.554836] Lustre: lustre-MDT0000: Recovery over after 0:05, of 3 clients 3 recovered and 0 were evicted. [ 3535.572080] Lustre: Skipped 10 previous similar messages [ 3535.617658] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1635 to 0x280000401:1921) [ 3535.618932] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1667 to 0x2c0000401:1921) [ 3546.320685] Lustre: DEBUG MARKER: oleg235-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3548.418171] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3557.958772] Lustre: DEBUG MARKER: == replay-dual test 23a: c1 rmdir d1, M1 drop reply and fail, client2 mkdir d1 ========================================================== 10:53:32 (1783954412) [ 3559.612519] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 3559.625079] LustreError: 70527:0:(ldlm_lib.c:3345:target_send_reply_msg()) @@@ dropping reply req@ffff9ef171634380 x1870608101090048/t17179869210(0) o36->496473be-80ec-43c8-9b36-5ded62500631@192.168.202.35@tcp:480/0 lens 496/456 e 0 to 0 dl 1783954495 ref 1 fl Interpret:/200/0 rc 0/0 job:'rmdir.0' uid:0 gid:0 projid:4294967295 [ 3563.789336] Lustre: Failing over lustre-MDT0001 [ 3566.049025] Lustre: lustre-MDT0001-lwp-OST0001: Connection to lustre-MDT0001 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 3566.056319] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 3566.074889] Lustre: Skipped 38 previous similar messages [ 3566.081784] Lustre: Skipped 9 previous similar messages [ 3570.557951] Lustre: server umount lustre-MDT0001 complete [ 3590.171419] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3592.267709] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 3592.285608] Lustre: Skipped 10 previous similar messages [ 3596.437065] Lustre: 70529:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9ef15fb6dc00 x1870608101090048/t17179869210(0) o36->496473be-80ec-43c8-9b36-5ded62500631@192.168.202.35@tcp:517/0 lens 496/2888 e 0 to 0 dl 1783954532 ref 1 fl Interpret:/202/0 rc 0/0 job:'rmdir.0' uid:0 gid:0 projid:4294967295 [ 3596.461153] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:100 to 0x2c0000400:129) [ 3596.463726] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:100 to 0x280000400:129) [ 3596.767852] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug -1 all [ 3607.240922] Lustre: DEBUG MARKER: oleg235-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 3608.888926] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3618.853933] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3621.113219] Lustre: Failing over lustre-MDT0000 [ 3621.349121] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3621.359924] LustreError: Skipped 3 previous similar messages [ 3621.490248] Lustre: server umount lustre-MDT0000 complete [ 3644.643311] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3644.645233] LDISKFS-fs (dm-0): recovery complete [ 3644.654505] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3653.602283] LustreError: 3640:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9ef171634a80 x1870608117504000/t0(0) o250->MGC192.168.202.135@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 [ 3658.807366] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug -1 all [ 3659.281234] Lustre: 75913:0:(ldlm_lib.c:2084:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3659.299223] Lustre: 75913:0:(ldlm_lib.c:2084:extend_recovery_timer()) Skipped 4 previous similar messages [ 3659.564290] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1923 to 0x2c0000401:1953) [ 3659.569673] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1923 to 0x280000401:1953) [ 3668.522217] Lustre: DEBUG MARKER: oleg235-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3670.030539] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3679.103876] Lustre: DEBUG MARKER: == replay-dual test 23b: c1 rmdir d1, M1 drop reply and fail M0/M1, c2 mkdir d1 ========================================================== 10:55:34 (1783954534) [ 3680.545615] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 3680.552716] LustreError: 70549:0:(ldlm_lib.c:3345:target_send_reply_msg()) @@@ dropping reply req@ffff9ef047d7ce00 x1870608101129216/t21474836483(0) o36->496473be-80ec-43c8-9b36-5ded62500631@192.168.202.35@tcp:601/0 lens 496/456 e 0 to 0 dl 1783954616 ref 1 fl Interpret:/200/0 rc 0/0 job:'rmdir.0' uid:0 gid:0 projid:4294967295 [ 3684.522192] Lustre: Failing over lustre-MDT0000 [ 3684.600669] LustreError: 6501:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1783954540 with bad export cookie 6973613156869537729 [ 3684.993957] Lustre: server umount lustre-MDT0000 complete [ 3689.108633] LustreError: 10393:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1783954545 with bad export cookie 6973613156869537631 [ 3689.128361] Lustre: Failing over lustre-MDT0001 [ 3689.128722] LustreError: 10393:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 3689.960740] Lustre: server umount lustre-MDT0001 complete [ 3710.179830] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3710.450457] LustreError: 77809:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3710.477408] LustreError: 77809:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 318 previous similar messages [ 3710.516883] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3710.632863] LustreError: 77786:0:(llog.c:1655:llog_backup()) MGC192.168.202.135@tcp: failed to open log lustre-sptlrpc: rc = -108 [ 3710.646181] Lustre: 77786:0:(mgc_request_server.c:770:mgc_llog_local_copy()) MGC192.168.202.135@tcp: failed to copy new config lustre-sptlrpc: rc = -108 [ 3714.531567] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x60c74037e832ff5f to 0x60c74037e83306c1 [ 3715.174633] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 3715.179618] Lustre: Skipped 11 previous similar messages [ 3720.768740] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug -1 all [ 3721.489464] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:100 to 0x2c0000400:161) [ 3721.492085] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:100 to 0x280000400:161) [ 3721.622419] Lustre: 77809:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9ef144b24a80 x1870608101129216/t21474836483(0) o36->496473be-80ec-43c8-9b36-5ded62500631@192.168.202.35@tcp:642/0 lens 496/2888 e 0 to 0 dl 1783954657 ref 1 fl Interpret:/202/0 rc 0/0 job:'rmdir.0' uid:0 gid:0 projid:4294967295 [ 3721.740871] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug -1 all [ 3726.639811] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1923 to 0x280000401:1985) [ 3726.645628] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1923 to 0x2c0000401:1985) [ 3732.628516] Lustre: DEBUG MARKER: oleg235-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 [ 3734.302036] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3735.976622] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3746.014510] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3748.225808] Lustre: Failing over lustre-MDT0000 [ 3748.453772] Lustre: server umount lustre-MDT0000 complete [ 3768.799382] LustreError: MGC192.168.202.135@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3768.812073] LustreError: Skipped 8 previous similar messages [ 3771.846564] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3771.849391] LDISKFS-fs (dm-0): recovery complete [ 3771.856086] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3783.954255] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug -1 all [ 3784.826151] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1987 to 0x280000401:2017) [ 3784.827060] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1987 to 0x2c0000401:2017) [ 3793.983931] Lustre: DEBUG MARKER: oleg235-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3795.742427] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3804.413488] Lustre: DEBUG MARKER: == replay-dual test 23c: c1 rmdir d1, M0 drop update reply and fail M0, c2 mkdir d1 ========================================================== 10:57:39 (1783954659) [ 3806.157718] Lustre: *** cfs_fail_loc=1701, val=2147483648*** [ 3806.162107] LustreError: 8441:0:(ldlm_lib.c:3345:target_send_reply_msg()) @@@ dropping reply req@ffff9ef148e18e00 x1870608117609728/t137438953491(0) o1000->lustre-MDT0001-mdtlov_UUID@0@lo:658/0 lens 1984/4320 e 0 to 0 dl 1783954673 ref 1 fl Interpret:/200/0 rc 0/0 job:'osp_up0-1.0' uid:0 gid:0 projid:4294967295 [ 3809.794331] Lustre: Failing over lustre-MDT0000 [ 3810.196380] Lustre: server umount lustre-MDT0000 complete [ 3831.641046] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3839.579954] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug -1 all [ 3841.598945] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1987 to 0x280000401:2049) [ 3841.599021] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1987 to 0x2c0000401:2049) [ 3849.897348] Lustre: DEBUG MARKER: oleg235-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3852.090589] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3862.126391] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3864.279985] Lustre: Failing over lustre-MDT0000 [ 3864.814679] Lustre: server umount lustre-MDT0000 complete [ 3888.465520] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3888.468067] LDISKFS-fs (dm-0): recovery complete [ 3888.474149] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3899.056841] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug -1 all [ 3899.423536] Lustre: 83216:0:(ldlm_lib.c:2084:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3899.441532] Lustre: 83216:0:(ldlm_lib.c:2084:extend_recovery_timer()) Skipped 17 previous similar messages [ 3899.597917] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2051 to 0x280000401:2081) [ 3899.612840] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2051 to 0x2c0000401:2081) [ 3909.104874] Lustre: DEBUG MARKER: oleg235-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3910.729756] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3919.296537] Lustre: DEBUG MARKER: == replay-dual test 23d: c1 rmdir d1, M0 drop update reply and fail M0/M1, c2 mkdir d1 ========================================================== 10:59:34 (1783954774) [ 3924.256342] Lustre: *** cfs_fail_loc=1701, val=2147483648*** [ 3924.258064] LustreError: 64239:0:(ldlm_lib.c:3345:target_send_reply_msg()) @@@ dropping reply req@ffff9ef15faee680 x1870608117683072/t146028888081(0) o1000->lustre-MDT0001-mdtlov_UUID@0@lo:21/0 lens 1984/4320 e 0 to 0 dl 1783954791 ref 1 fl Interpret:/200/0 rc 0/0 job:'osp_up0-1.0' uid:0 gid:0 projid:4294967295 [ 3928.156490] Lustre: Failing over lustre-MDT0000 [ 3928.775732] Lustre: server umount lustre-MDT0000 complete [ 3933.182145] Lustre: Failing over lustre-MDT0001 [ 3933.183710] LustreError: 6502:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1783954789 with bad export cookie 6973613156869544890 [ 3933.206825] LustreError: 6502:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 5 previous similar messages [ 3933.209155] LustreError: 84454:0:(ldlm_resource.c:1207:ldlm_resource_complain()) lustre-MDT0000-osp-MDT0001: namespace resource [0x2000013a1:0x80:0x0].0x0 (ffff9ef166e4b900) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 3933.289572] Lustre: lustre-MDT0001: Not available for connect from 192.168.202.35@tcp (stopping) [ 3933.300100] Lustre: Skipped 6 previous similar messages [ 3939.247986] Lustre: server umount lustre-MDT0001 complete [ 3959.363896] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3959.366587] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3959.678491] LustreError: 85164:0:(llog.c:1655:llog_backup()) MGC192.168.202.135@tcp: failed to open log lustre-sptlrpc: rc = -108 [ 3959.684411] Lustre: 85164:0:(mgc_request_server.c:770:mgc_llog_local_copy()) MGC192.168.202.135@tcp: failed to copy new config lustre-sptlrpc: rc = -108 [ 3978.213692] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x60c74037e833234d [ 3978.225095] Lustre: MGC192.168.202.135@tcp: Connection restored to 0@lo (at 0@lo) [ 3978.250284] Lustre: Skipped 43 previous similar messages [ 3984.254283] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug -1 all [ 3984.489728] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2051 to 0x280000401:2113) [ 3984.494964] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2051 to 0x2c0000401:2113) [ 3984.694313] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:100 to 0x2c0000400:193) [ 3984.701369] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:100 to 0x280000400:193) [ 3984.768624] Lustre: 85174:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9ef166e0c000 x1870608101207168/t25769803783(0) o36->496473be-80ec-43c8-9b36-5ded62500631@192.168.202.35@tcp:150/0 lens 496/2888 e 0 to 0 dl 1783954920 ref 1 fl Interpret:/202/0 rc 0/0 job:'rmdir.0' uid:0 gid:0 projid:4294967295 [ 3984.896593] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug -1 all [ 3995.456309] Lustre: DEBUG MARKER: oleg235-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 [ 3997.393668] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3999.041568] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4010.392057] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4012.868148] Lustre: Failing over lustre-MDT0000 [ 4013.157808] Lustre: server umount lustre-MDT0000 complete [ 4037.044081] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 4037.046654] LDISKFS-fs (dm-0): recovery complete [ 4037.055256] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4043.231148] LustreError: 87364:0:(import.c:339:ptlrpc_invalidate_import()) MGS: timeout waiting for callback (1 != 0) [ 4043.238950] LustreError: 87364:0:(import.c:363:ptlrpc_invalidate_import()) @@@ still on sending list req@ffff9ef17f713100 x1870608117732480/t0(0) o250->MGC192.168.202.135@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 1783954898 ref 1 fl Rpc:NQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4043.254036] LustreError: 87364:0:(import.c:373:ptlrpc_invalidate_import()) MGS: Unregistering RPCs found (0). Network is sluggish? Waiting for them to error out. [ 4043.637378] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4043.646335] Lustre: Skipped 12 previous similar messages [ 4048.700828] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug -1 all [ 4049.225665] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2115 to 0x280000401:2145) [ 4049.225736] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2115 to 0x2c0000401:2145) [ 4057.487472] Lustre: DEBUG MARKER: oleg235-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4059.043803] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4067.808412] Lustre: DEBUG MARKER: == replay-dual test 24: reconstruct on non-existing object ========================================================== 11:02:02 (1783954922) [ 4069.464375] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 4069.467454] LustreError: 85174:0:(ldlm_lib.c:3345:target_send_reply_msg()) @@@ dropping reply req@ffff9ef148e18700 x1870608101249280/t154618822673(0) o36->496473be-80ec-43c8-9b36-5ded62500631@192.168.202.35@tcp:235/0 lens 488/456 e 0 to 0 dl 1783955005 ref 1 fl Interpret:/200/0 rc 0/0 job:'truncate.0' uid:0 gid:0 projid:4294967295 [ 4154.606166] Lustre: lustre-MDT0000: Client 496473be-80ec-43c8-9b36-5ded62500631 (at 192.168.202.35@tcp) reconnecting [ 4154.646478] Lustre: 85174:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9ef16bd7bb80 x1870608101249280/t154618822673(0) o36->496473be-80ec-43c8-9b36-5ded62500631@192.168.202.35@tcp:320/0 lens 488/3152 e 0 to 0 dl 1783955090 ref 1 fl Interpret:/202/0 rc 0/0 job:'truncate.0' uid:0 gid:0 projid:4294967295 [ 4163.240235] Lustre: DEBUG MARKER: == replay-dual test 25: replay|resend ==================== 11:03:37 (1783955017) [ 4165.925114] Lustre: *** cfs_fail_loc=304, val=0*** [ 4168.335107] Lustre: Failing over lustre-OST0000 [ 4168.621984] Lustre: server umount lustre-OST0000 complete [ 4169.196940] Lustre: lustre-OST0000-osc-MDT0001: Connection to lustre-OST0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 4169.221638] Lustre: Skipped 32 previous similar messages [ 4188.691355] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4191.020589] Lustre: lustre-OST0000: Recovery over after 0:01, of 4 clients 4 recovered and 0 were evicted. [ 4191.040916] Lustre: Skipped 10 previous similar messages [ 4196.704736] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug -1 all [ 4206.510314] Lustre: DEBUG MARKER: oleg235-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 4208.075730] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4218.014470] Lustre: DEBUG MARKER: == replay-dual test 26: dbench and tar with mds failover ========================================================== 11:04:33 (1783955073) [ 4229.585759] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4233.342437] Lustre: DEBUG MARKER: test_26 fail mds1 1 times [ 4235.909302] Lustre: Failing over lustre-MDT0000 [ 4236.508868] Lustre: server umount lustre-MDT0000 complete [ 4238.820725] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4238.830274] LustreError: Skipped 4 previous similar messages [ 4256.740424] Lustre: 3643:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1783955096/real 1783955096] req@ffff9ef04927aa00 x1870608117882880/t0(0) o400->MGC192.168.202.135@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1783955112 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4256.763703] Lustre: 3643:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 16 previous similar messages [ 4258.207063] LDISKFS-fs (dm-0): 4 truncates cleaned up [ 4258.214271] LDISKFS-fs (dm-0): recovery complete [ 4258.228437] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4268.661545] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 4268.667590] Lustre: Skipped 10 previous similar messages [ 4273.286567] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug -1 all [ 4273.693944] Lustre: 91326:0:(ldlm_lib.c:2084:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 4273.710420] Lustre: 91326:0:(ldlm_lib.c:2084:extend_recovery_timer()) Skipped 17 previous similar messages [ 4276.001347] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2176 to 0x280000401:2209) [ 4276.005294] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2175 to 0x2c0000401:2209) [ 4284.079633] Lustre: DEBUG MARKER: oleg235-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4286.192299] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4300.379463] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 4303.902851] Lustre: DEBUG MARKER: test_26 fail mds2 2 times [ 4306.287379] Lustre: Failing over lustre-MDT0001 [ 4306.881331] Lustre: server umount lustre-MDT0001 complete [ 4314.593817] LustreError: 85175:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4314.621038] LustreError: 85175:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 286 previous similar messages [ 4330.854292] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 4330.856333] LDISKFS-fs (dm-1): recovery complete [ 4330.876904] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4331.529668] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 4331.541903] Lustre: Skipped 9 previous similar messages [ 4337.667703] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug -1 all [ 4339.686118] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:270 to 0x2c0000400:289) [ 4339.690020] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:270 to 0x280000400:289) [ 4351.461364] Lustre: DEBUG MARKER: oleg235-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 4353.841023] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4369.092917] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4372.653900] Lustre: DEBUG MARKER: test_26 fail mds1 3 times [ 4374.420217] Lustre: Failing over lustre-MDT0000 [ 4374.765362] Lustre: server umount lustre-MDT0000 complete [ 4392.939580] LustreError: MGC192.168.202.135@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4392.968450] LustreError: Skipped 5 previous similar messages [ 4398.144145] LDISKFS-fs (dm-0): 3 truncates cleaned up [ 4398.148174] LDISKFS-fs (dm-0): recovery complete [ 4398.166757] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4403.169859] LustreError: 3640:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9ef047d7ea00 x1870608118267392/t0(0) o250->MGC192.168.202.135@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 [ 4403.201040] LustreError: 3640:0:(client.c:1391:ptlrpc_import_delay_req()) Skipped 1 previous similar message [ 4409.418702] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug -1 all [ 4410.452560] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2294 to 0x280000401:2337) [ 4410.463276] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2293 to 0x2c0000401:2337) [ 4420.957629] Lustre: DEBUG MARKER: oleg235-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4423.368907] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4472.788245] Lustre: DEBUG MARKER: == replay-dual test 28: lock replay should be ordered: waiting after granted ========================================================== 11:08:47 (1783955327) [ 4488.012884] Lustre: Failing over lustre-OST0000 [ 4488.028903] Lustre: *** cfs_fail_loc=32a, val=0*** [ 4488.034627] LustreError: 96266:0:(ldlm_resource.c:1207:ldlm_resource_complain()) filter-lustre-OST0000_UUID: namespace resource [0x280000401:0x944:0x0].0x0 (ffff9ef04ee05900) refcount nonzero (3) after lock cleanup; forcing cleanup. [ 4488.059211] LustreError: 6504:0:(client.c:1381:ptlrpc_import_delay_req()) @@@ IMP_CLOSED req@ffff9ef14662f480 x1870608118764288/t0(0) o105->lustre-OST0000@192.168.202.35@tcp:15/16 lens 392/224 e 0 to 0 dl 0 ref 1 fl Rpc:QU/0/ffffffff rc 0/-1 job:'' uid:4294967295 gid:4294967295 projid:4294967295 [ 4488.186970] Lustre: server umount lustre-OST0000 complete [ 4506.198526] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4508.030387] Lustre: *** cfs_fail_loc=32a, val=0*** [ 4512.484924] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug -1 all [ 4522.028664] Lustre: DEBUG MARKER: oleg235-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 4523.574462] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4537.755127] Lustre: DEBUG MARKER: == replay-dual test 29: replay vs update with the same xid ========================================================== 11:09:51 (1783955391) [ 4540.046712] Lustre: DEBUG MARKER: SKIP: replay-dual test_29 needs >= 2 clients [ 4541.721904] Lustre: DEBUG MARKER: == replay-dual test 30: layout lock replay is not blocked on IO ========================================================== 11:09:56 (1783955396) [ 4545.851168] Lustre: Failing over lustre-MDT0000 [ 4546.865074] Lustre: server umount lustre-MDT0000 complete [ 4566.753435] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4574.222836] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x60c74037e835ca85 [ 4580.192484] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug -1 all [ 4580.336122] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 4580.352462] Lustre: Skipped 26 previous similar messages [ 4580.626033] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2373 to 0x280000401:2401) [ 4580.627086] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2371 to 0x2c0000401:2433) [ 4590.622595] Lustre: DEBUG MARKER: oleg235-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4592.367916] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4602.886709] Lustre: DEBUG MARKER: == replay-dual test 31: deadlock on file_remove_privs and occupied mod rpc slots ========================================================== 11:10:57 (1783955457) [ 4607.326159] Lustre: Failing over lustre-OST0000 [ 4607.506207] Lustre: server umount lustre-OST0000 complete [ 4626.146915] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4634.231550] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug -1 all [ 4644.614953] Lustre: DEBUG MARKER: oleg235-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 4646.459483] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL [ 4657.241463] Lustre: DEBUG MARKER: == replay-dual test 32: gap in update llog shouldn't break recovery ========================================================== 11:11:51 (1783955511) [ 4658.539965] Lustre: *** cfs_fail_loc=131d, val=10*** [ 4659.107970] Lustre: *** cfs_fail_loc=131d, val=4294967292*** [ 4659.110750] Lustre: Skipped 13 previous similar messages [ 4660.159921] Lustre: *** cfs_fail_loc=131d, val=4294967278*** [ 4660.164428] Lustre: Skipped 13 previous similar messages [ 4662.517121] Lustre: Failing over lustre-MDT0001 [ 4662.864096] Lustre: server umount lustre-MDT0001 complete [ 4667.431857] Lustre: Failing over lustre-MDT0000 [ 4668.567779] Lustre: lustre-MDT0000: Not available for connect from 192.168.202.35@tcp (stopping) [ 4668.583462] Lustre: Skipped 12 previous similar messages [ 4670.017934] Lustre: server umount lustre-MDT0000 complete [ 4677.424278] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4677.782388] Lustre: *** cfs_fail_loc=131d, val=4294967266*** [ 4677.786858] Lustre: Skipped 11 previous similar messages [ 4677.912098] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4677.916068] Lustre: Skipped 7 previous similar messages [ 4683.480200] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug -1 all [ 4690.959826] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4691.153478] Lustre: *** cfs_fail_loc=131d, val=4294967262*** [ 4691.163079] Lustre: Skipped 3 previous similar messages [ 4696.675946] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:330 to 0x2c0000400:353) [ 4696.680266] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:331 to 0x280000400:353) [ 4696.780156] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2441 to 0x280000401:2529) [ 4696.780684] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2371 to 0x2c0000401:2465) [ 4697.227385] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug -1 all [ 4709.177793] Lustre: DEBUG MARKER: == replay-dual test 33: Check for OBD_INCOMPAT_MULTI_RPCS in last_rcvd after abort_recovery ========================================================== 11:12:44 (1783955564) [ 4715.328454] Lustre: Failing over lustre-MDT0001 [ 4715.670062] Lustre: server umount lustre-MDT0001 complete [ 4738.963326] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4744.796099] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug -1 all [ 4754.124890] Lustre: DEBUG MARKER: oleg235-client.virtnet: executing wait_import_state_mount REPLAY_WAIT mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 4755.770309] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in REPLAY_WAIT state after 0 sec [ 4756.663593] Lustre: lustre-MDT0001: Aborting client recovery [ 4756.665626] LustreError: 104063:0:(ldlm_lib.c:3003:target_stop_recovery_thread()) lustre-MDT0001: Aborting recovery [ 4756.671253] Lustre: 103428:0:(ldlm_lib.c:2403:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 4756.674239] Lustre: 103428:0:(ldlm_lib.c:2403:target_recovery_overseer()) Skipped 2 previous similar messages [ 4756.676958] Lustre: 103428:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0001: disconnect stale client c8d8e4d4-bfa6-4232-b1c5-25d4018965f0@ [ 4756.680375] Lustre: lustre-MDT0001: disconnecting 1 stale clients [ 4756.689804] Lustre: lustre-MDT0001-osd: cancel update llog [0x240000400:0x1:0x0] [ 4756.695706] Lustre: lustre-MDT0000-osp-MDT0001: cancel update llog [0x200000401:0x1:0x0] [ 4756.751667] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:331 to 0x280000400:385) [ 4756.754325] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:330 to 0x2c0000400:385) [ 4762.444442] Lustre: DEBUG MARKER: oleg235-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 4764.261506] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4768.332561] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0001.recovery_status 1475 [ 4775.697075] Lustre: Failing over lustre-MDT0001 [ 4776.153074] Lustre: server umount lustre-MDT0001 complete [ 4777.449498] 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 [ 4777.474253] Lustre: Skipped 28 previous similar messages [ 4786.047551] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4791.865969] Lustre: lustre-MDT0001: Recovery over after 0:05, of 2 clients 2 recovered and 0 were evicted. [ 4791.877660] Lustre: Skipped 9 previous similar messages [ 4791.944210] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:331 to 0x280000400:417) [ 4791.948801] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:330 to 0x2c0000400:417) [ 4792.148897] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug -1 all [ 4801.917786] Lustre: DEBUG MARKER: oleg235-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 4803.516457] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4807.468826] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0001.recovery_status 1475 [ 4816.642603] Lustre: DEBUG MARKER: == replay-dual test complete, duration 4574 sec ========== 11:14:31 (1783955671) [ 4818.422463] Lustre: DEBUG MARKER: === replay-dual: start cleanup 11:14:33 (1783955673) === [ 4829.645438] Lustre: DEBUG MARKER: === replay-dual: finish cleanup 11:14:44 (1783955684) === [ 4832.091052] Lustre: Failing over lustre-MDT0000 [ 4832.313578] Lustre: server umount lustre-MDT0000 complete [ 4860.004269] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4864.491731] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x60c74037e83609af [ 4869.579299] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5005.500225] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 5005.508181] Lustre: 107213:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client c8d8e4d4-bfa6-4232-b1c5-25d4018965f0@ [ 5005.519250] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 5005.579627] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2441 to 0x280000401:2561) [ 5005.580025] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2371 to 0x2c0000401:2497) [ 5014.052189] Lustre: DEBUG MARKER: oleg235-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5016.050687] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5029.332698] Lustre: server umount lustre-MDT0000 complete [ 5033.956932] LustreError: 107604:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 5033.974013] LustreError: 107604:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 206 previous similar messages [ 5038.882519] LustreError: 95520:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1783955895 with bad export cookie 6973613156869736879 [ 5038.885978] LustreError: MGC192.168.202.135@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5038.895247] LustreError: 95520:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 5038.917763] LustreError: Skipped 3 previous similar messages [ 5039.266581] Lustre: server umount lustre-MDT0001 complete [ 5048.967918] Lustre: server umount lustre-OST0000 complete [ 5059.677219] Lustre: server umount lustre-OST0001 complete [ 5078.568044] Lustre: DEBUG MARKER: oleg235-server.virtnet: executing unload_modules_local [ 5081.859740] Key type lgssc unregistered [ 5082.188534] LNet: 110151:0:(lib-ptl.c:967:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 5082.192447] LNetError: 110151:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 5082.210219] LNet: Removed LNI 192.168.202.135@tcp [ 5083.128468] Key type .llcrypt unregistered [ 5083.133733] Key type ._llcrypt unregistered