[ 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 770104157 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.001021] APIC: Switch to symmetric I/O mode setup [ 0.002445] x2apic enabled [ 0.003015] Switched APIC routing to physical x2apic. [ 0.005013] kvm-guest: setup PV IPIs [ 0.007000] ..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.007032] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.008020] pid_max: default: 32768 minimum: 301 [ 0.010160] LSM: Security Framework initializing [ 0.011097] Yama: becoming mindful. [ 0.013104] SELinux: Initializing. [ 0.014099] *** VALIDATE selinux *** [ 0.026853] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.034579] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.035186] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.037188] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.039153] *** VALIDATE tmpfs *** [ 0.042465] *** VALIDATE proc *** [ 0.043404] *** VALIDATE cgroup *** [ 0.044018] *** VALIDATE cgroup2 *** [ 0.045344] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.046188] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.047000] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.047000] Spectre V2 : User space: Vulnerable [ 0.047000] Speculative Store Bypass: Vulnerable [ 0.047000] debug: unmapping init [mem 0xffffffffaaa59000-0xffffffffaaa60fff] [ 0.047000] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.048048] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.049030] ... version: 2 [ 0.050013] ... bit width: 48 [ 0.051027] ... generic registers: 4 [ 0.052111] ... value mask: 0000ffffffffffff [ 0.053024] ... max period: 00007fffffffffff [ 0.054026] ... fixed-purpose events: 3 [ 0.055021] ... event mask: 000000070000000f [ 0.056533] rcu: Hierarchical SRCU implementation. [ 0.059539] smp: Bringing up secondary CPUs ... [ 0.060705] x86: Booting SMP configuration: [ 0.061036] .... node #0, CPUs: #1 #2 #3 [ 0.072162] smp: Brought up 1 node, 4 CPUs [ 0.074020] smpboot: Max logical packages: 1 [ 0.075080] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.174199] node 0 deferred pages initialised in 97ms [ 0.185086] devtmpfs: initialized [ 0.186576] x86/mm: Memory block size: 128MB [ 0.189654] gcov: version magic: 0x41383552 [ 0.194520] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.198107] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.202669] pinctrl core: initialized pinctrl subsystem [ 0.205537] [ 0.206009] ************************************************************* [ 0.210018] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.213015] ** ** [ 0.216020] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.219019] ** ** [ 0.223530] ** This means that this kernel is built to expose internal ** [ 0.227036] ** IOMMU data structures, which may compromise security on ** [ 0.231076] ** your system. ** [ 0.237019] ** ** [ 0.242020] ** If you see this message and you are not debugging the ** [ 0.247021] ** kernel, report this immediately to your vendor! ** [ 0.252018] ** ** [ 0.254021] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.258020] ************************************************************* [ 0.264600] NET: Registered protocol family 16 [ 0.267061] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.273085] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.279219] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.285413] cpuidle: using governor menu [ 0.290000] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.296060] PCI: Using configuration type 1 for base access [ 0.300267] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.311883] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.313025] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.317393] cryptd: max_cpu_qlen set to 1000 [ 0.320266] ACPI: Added _OSI(Module Device) [ 0.321018] ACPI: Added _OSI(Processor Device) [ 0.323014] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.325016] ACPI: Added _OSI(Processor Aggregator Device) [ 0.330000] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.338581] ACPI: Interpreter enabled [ 0.340071] ACPI: PM: (supports S0 S3 S4 S5) [ 0.341014] ACPI: Using IOAPIC for interrupt routing [ 0.343127] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.346636] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.359673] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.362040] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.364039] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.368102] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.373992] acpiphp: Slot [2] registered [ 0.375379] acpiphp: Slot [5] registered [ 0.377421] acpiphp: Slot [6] registered [ 0.379223] acpiphp: Slot [7] registered [ 0.381141] acpiphp: Slot [8] registered [ 0.382104] acpiphp: Slot [9] registered [ 0.384178] acpiphp: Slot [10] registered [ 0.385284] acpiphp: Slot [3] registered [ 0.387186] acpiphp: Slot [4] registered [ 0.389112] acpiphp: Slot [11] registered [ 0.390138] acpiphp: Slot [12] registered [ 0.392122] acpiphp: Slot [13] registered [ 0.393156] acpiphp: Slot [14] registered [ 0.395180] acpiphp: Slot [15] registered [ 0.396110] acpiphp: Slot [16] registered [ 0.398099] acpiphp: Slot [17] registered [ 0.399131] acpiphp: Slot [18] registered [ 0.401095] acpiphp: Slot [19] registered [ 0.402131] acpiphp: Slot [20] registered [ 0.404117] acpiphp: Slot [21] registered [ 0.405175] acpiphp: Slot [22] registered [ 0.406092] acpiphp: Slot [23] registered [ 0.408102] acpiphp: Slot [24] registered [ 0.410129] acpiphp: Slot [25] registered [ 0.411096] acpiphp: Slot [26] registered [ 0.413126] acpiphp: Slot [27] registered [ 0.414090] acpiphp: Slot [28] registered [ 0.415102] acpiphp: Slot [29] registered [ 0.416079] acpiphp: Slot [30] registered [ 0.417122] acpiphp: Slot [31] registered [ 0.419062] PCI host bridge to bus 0000:00 [ 0.420023] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.429040] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.439070] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.514060] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.517030] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.574036] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.579219] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.585694] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.593000] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.610020] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.615785] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.618021] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.619018] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.621020] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.623615] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.625809] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.637164] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.642139] pci 0000:00:01.3: quirk_piix4_acpi+0x0/0x1e0 took 15625 usecs [ 0.714795] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.721019] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.744995] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.749016] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.754873] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.768037] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.774021] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.796025] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.800000] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.951045] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.960026] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.988020] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 1.004000] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 1.016035] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 1.027023] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 1.046019] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 1.066135] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 1.092026] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 1.097026] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 1.117000] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 1.186790] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 1.206023] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 1.230020] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 1.256036] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 1.294000] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 1.312415] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 1.332019] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 1.360020] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 1.380652] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 1.384131] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 1.387904] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 1.392426] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 1.396764] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 1.403611] iommu: Default domain type: Passthrough [ 1.404000] SCSI subsystem initialized [ 1.405000] ACPI: bus type USB registered [ 1.408034] usbcore: registered new interface driver usbfs [ 1.411125] usbcore: registered new interface driver hub [ 1.413136] usbcore: registered new device driver usb [ 1.416253] pps_core: LinuxPPS API ver. 1 registered [ 1.417018] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 1.419083] PTP clock support registered [ 1.422142] EDAC MC: Ver: 3.0.0 [ 1.425058] PCI: Using ACPI for IRQ routing [ 1.428277] NetLabel: Initializing [ 1.429019] NetLabel: domain hash size = 128 [ 1.431000] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 1.436801] NetLabel: unlabeled traffic allowed by default [ 1.734199] vgaarb: loaded [ 1.739521] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 1.740020] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 1.757757] clocksource: Switched to clocksource kvm-clock [ 1.881775] VFS: Disk quotas dquot_6.6.0 [ 1.883479] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 1.886381] *** VALIDATE ramfs *** [ 1.887896] *** VALIDATE hugetlbfs *** [ 1.889786] pnp: PnP ACPI init [ 1.892739] pnp: PnP ACPI: found 6 devices [ 1.911972] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 1.915546] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 1.918204] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 1.920855] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 1.923763] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 1.926829] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 1.930445] NET: Registered protocol family 2 [ 1.933683] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 1.940210] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 1.945540] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 1.985665] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 1.992571] TCP: Hash tables configured (established 65536 bind 65536) [ 1.999918] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 2.003022] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 2.005425] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 2.008427] NET: Registered protocol family 1 [ 2.120797] RPC: Registered named UNIX socket transport module. [ 2.122527] RPC: Registered udp transport module. [ 2.130418] RPC: Registered tcp transport module. [ 2.133869] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 2.143103] NET: Registered protocol family 44 [ 2.148928] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 2.152098] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 2.159182] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 2.161257] PCI: CLS 0 bytes, default 64 [ 2.162966] Unpacking initramfs... [ 5.630018] debug: unmapping init [mem 0xffff9a33bcc54000-0xffff9a33bffbffff] [ 5.650648] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 5.655366] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 5.666334] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 7.962535] Initialise system trusted keyrings [ 7.977686] Key type blacklist registered [ 7.993990] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 8.044024] zbud: loaded [ 8.072019] *** VALIDATE nfs *** [ 8.076562] *** VALIDATE nfs4 *** [ 8.090831] pstore: using deflate compression [ 8.237581] Platform Keyring initialized [ 8.984677] NET: Registered protocol family 38 [ 8.985964] Key type asymmetric registered [ 8.987049] Asymmetric key parser 'x509' registered [ 9.003318] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 9.014238] io scheduler mq-deadline registered [ 9.018279] io scheduler kyber registered [ 9.028753] io scheduler bfq registered [ 9.033491] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 9.040882] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 9.051862] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 9.064975] ACPI: Power Button [PWRF] [ 9.095168] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 9.122834] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 9.193143] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 9.223955] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 9.277947] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 9.352594] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 9.407390] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 9.418472] Non-volatile memory driver v1.3 [ 9.421791] Linux agpgart interface v0.103 [ 9.554978] virtio_blk virtio1: [vda] 145840 512-byte logical blocks (74.7 MB/71.2 MiB) [ 9.562749] vda: detected capacity change from 0 to 74670080 [ 9.606473] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 9.611923] vdb: detected capacity change from 0 to 1073741824 [ 9.643770] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 9.646402] vdc: detected capacity change from 0 to 2621440000 [ 9.661896] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 9.664558] vdd: detected capacity change from 0 to 2621440000 [ 9.678218] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 9.680658] vde: detected capacity change from 0 to 4294967296 [ 9.694409] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 9.697652] vdf: detected capacity change from 0 to 4294967296 [ 9.703821] libphy: Fixed MDIO Bus: probed [ 9.748883] usbcore: registered new interface driver usbserial_generic [ 9.750959] usbserial: USB Serial support registered for generic [ 9.753078] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 9.765353] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 9.774665] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 9.803477] mousedev: PS/2 mouse device common for all mice [ 9.818360] rtc_cmos 00:05: RTC can wake from S4 [ 9.856835] rtc_cmos 00:05: registered as rtc0 [ 9.868855] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 9.878847] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 9.898101] intel_pstate: CPU model not supported [ 9.920662] hid: raw HID events driver (C) Jiri Kosina [ 9.922446] usbcore: registered new interface driver usbhid [ 9.932965] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 9.938839] usbhid: USB HID core driver [ 9.939025] drop_monitor: Initializing network drop monitor service [ 9.939145] Initializing XFRM netlink socket [ 9.939506] NET: Registered protocol family 10 [ 9.963058] Segment Routing with IPv6 [ 10.005412] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 10.019106] NET: Registered protocol family 17 [ 10.037886] mpls_gso: MPLS GSO support [ 10.064438] RAS: Correctable Errors collector initialized. [ 10.066378] AVX version of gcm_enc/dec engaged. [ 10.074227] AES CTR mode by8 optimization enabled [ 10.427676] sched_clock: Marking stable (10427643287, 0)->(13991735903, -3564092616) [ 10.443257] registered taskstats version 1 [ 10.450823] Loading compiled-in X.509 certificates [ 10.459539] zswap: loaded using pool lzo/zbud [ 10.600958] Key type big_key registered [ 10.655819] Key type encrypted registered [ 10.665660] ima: No TPM chip found, activating TPM-bypass! [ 10.667702] ima: Allocated hash algorithm: sha1 [ 10.673240] ima: No architecture policies found [ 10.681679] evm: Initialising EVM extended attributes: [ 10.688237] evm: security.selinux [ 10.693911] evm: security.ima [ 10.697742] evm: security.capability [ 10.704930] evm: HMAC attrs: 0x1 [ 10.707595] rtc_cmos 00:05: setting system clock to 2026-08-10 13:49:04 UTC (1786369744) [ 10.721646] debug: unmapping init [mem 0xffffffffaba03000-0xffffffffabbfffff] [ 10.732811] debug: unmapping init [mem 0xffffffffaa782000-0xffffffffaaa58fff] [ 10.740673] Write protecting the kernel read-only data: 28672k [ 10.747285] debug: unmapping init [mem 0xffffffffa8e03000-0xffffffffa8ffffff] [ 10.754816] debug: unmapping init [mem 0xffffffffa9714000-0xffffffffa97fffff] [ 10.836742] 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) [ 10.855221] systemd[1]: Detected virtualization kvm. [ 10.858294] systemd[1]: Detected architecture x86-64. [ 10.868950] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 10.954472] systemd[1]: No hostname configured. [ 10.958489] systemd[1]: Set hostname to . [ 10.965455] random: systemd: uninitialized urandom read (16 bytes read) [ 10.976291] systemd[1]: Initializing machine ID from random generator. [ 11.133310] random: ln: uninitialized urandom read (6 bytes read) [ 11.392562] random: systemd: uninitialized urandom read (16 bytes read) [ 11.405697] systemd[1]: Reached target Timers. [ OK ] Reached target Timers. [ 11.424374] systemd[1]: Reached target Slices. [ OK ] Reached target Slices. [ 11.441499] systemd[1]: Listening on udev Kernel Socket. [ OK ] Listening on udev Kernel Socket. [ OK ] Listening on udev Control Socket. [ OK ] Reached target Swap. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. [ OK ] Reached target Local File Systems. [ OK ] Reached target Initrd Root Device. [ OK ] Listening on Journal Socket (/dev/log). [ OK ] Listening on Journal Socket. Starting Journal Service... [ OK ] Reached target Sockets. [ OK ] Started Memstrack Anylazing Service. Starting Apply Kernel Variables... Starting Create Volatile Files and Directories... Starting Create list of required st…ce nodes for the current kernel... Starting Setup Virtual Console... [ OK ] Started Apply Kernel Variables. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Setup Virtual Console. Starting dracut cmdline hook... Starting Create Static Device Nodes in /dev... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started Journal Service. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 14.211779] device-mapper: uevent: version 1.0.3 [ 14.213863] device-mapper: ioctl: 4.46.0-ioctl (2022-02-22) initialised: dm-devel@redhat.com [ OK ] Started dracut pre-udev hook. Starting udev Kernel Device Manager... [ OK ] Started udev Kernel Device Manager. Starting dracut pre-trigger hook... [ OK ] Started dracut pre-trigger hook. Starting udev Coldplug all Devices... Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting dracut initqueue hook... [ 16.805982] virtio_net virtio0 ens2: renamed from eth0 [ 16.943012] random: fast init done [ 17.467153] scsi host0: ata_piix [ 17.589290] scsi host1: ata_piix [ 17.603382] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 17.624828] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 23.217423] random: crng init done [ 23.219833] random: 7 urandom warning(s) missed due to ratelimiting [ 25.982593] dracut-initqueue[584]: RTNETLINK answers: File exists Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. Mounting /sysroot... [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. [ 29.584599] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped target Timers. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Slices. [ OK ] Stopped target Sockets. [ OK ] Stopped target Paths. [ OK ] Stopped target System Initialization. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. [ OK ] Stopped target Swap. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. Stopping udev Kernel Device Manager... [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Closed udev Control Socket. [ OK ] Closed udev Kernel Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 34.675082] printk: systemd: 26 output lines suppressed due to ratelimiting [ 36.232703] SELinux: Disabled at runtime. [ 36.495444] 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) [ 36.511817] systemd[1]: Detected virtualization kvm. [ 36.514741] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 38.479852] systemd[1]: initrd-switch-root.service: Succeeded. [ 38.490961] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 38.518422] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 38.546053] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 38.560693] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 38.595151] systemd[1]: Starting Journal Service... Starting Journal Service... [ 38.647438] systemd[1]: Starting Create list of required static device nodes for the current kernel... Starting Create list of required st…ce nodes for the current kernel... [ OK ] Created slice system-getty.slice. [ OK ] Listening on RPCbind Server Activation Socket. Mounting Kernel Debug File System... Activating swap /dev/disk/by-label/SWAP... Mounting Huge Pages File System... [ OK ] Reached target RPC Port Mapper. [ OK ] Reached target rpc_pipefs.target. [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Listening on udev Control Socket. Starting Remount Root and Kernel File Systems... [ 39.001089] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS [ OK ] Created slice system-sshd\x2dkeygen.slice. Mounting POSIX Message Queue File System... [ OK ] Listening on udev Kernel Socket. Starting udev Coldplug all Devices... [ OK ] Listening on Process Core Dump Socket. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. Starting Apply Kernel Variables... [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd File Systems. [ OK ] Stopped target Initrd Root File System. [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Created slice User and Session Slice. [ OK ] Reached target Slices. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Mounted Kernel Debug File System. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Mounted Huge Pages File System. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Started Journal Service. [ OK ] Started Apply Kernel Variables. Starting Configure read-only root support... Starting Flush Journal to Persistent Storage... [ OK ] Reached target Swap. Starting Create Static Device Nodes in /dev... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started udev Coldplug all Devices. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Reached target Local File Systems (Pre). Mounting /mnt... Mounting /home/green/git/lustre-release... Starting udev Kernel Device Manager... [ OK ] Mounted /mnt. [ 41.050605] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 42.346506] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 42.406088] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 43.663718] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 44.099620] EDAC sbridge: Ver: 1.1.2 [* ] A start job is running for Configur…-only root support (8s / no limit) [** ] A start job is running for Configur…-only root support (9s / no limit) [*** ] A start job is running for Configur…-only root support (9s / no limit) [ *** ] A start job is running for Configur…only root support (10s / no limit) [ *** ] A start job is running for Configur…only root support (10s / no limit) [ ***] A start job is running for Configur…only root support (11s / no limit)[ 50.071486] Key type dns_resolver registered [ **] A start job is running for Configur…only root support (12s / no limit)[ 50.773393] NFS: Registering the id_resolver key type [ 50.785478] Key type id_resolver registered [ 50.789611] Key type id_legacy registered [ *] A start job is running for Configur…only root support (12s / no limit) [ **] A start job is running for Configur…only root support (13s / no limit) [ OK ] Started Configure read-only root support. [ OK ] Reached target Local File Systems. Starting Create Volatile Files and Directories... Starting Mark the need to relabel after reboot... Starting Rebuild Dynamic Linker Cache... Starting Load/Save Random Seed... [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Load/Save Random Seed. Starting RPC Bind... Starting Update UTMP about System Boot/Shutdown... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Started D-Bus System Message Bus. Starting Network Manager... Starting Login Service... [ OK ] Started dnf makecache --timer. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Reached target Timers. [ OK ] Reached target sshd-keygen.target. Starting Restore /run/initramfs on shutdown... [ OK ] Started irqbalance daemon. [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Login Service. [ OK ] Started Network Manager. Starting Network Manager Wait Online... [ OK ] Reached target Network. Starting Dynamic System Tuning Daemon... Starting GSSAPI Proxy Daemon... Starting OpenSSH server daemon... Starting Hostname Service... [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... [ OK ] Started OpenSSH server daemon. [ OK ] Started Permit User Sessions. [ OK ] Started Serial Getty on ttyS1. [ OK ] Started Getty on tty1. [ OK ] Started Command Scheduler. [ OK ] Started Serial Getty on ttyS0. [ OK ] Reached target Login Prompts. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting Notify NFS peers of a restart... Starting System Logging Service... Starting Crash recovery kernel arming... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. [ OK ] Stopped Serial Getty on ttyS1. [ OK ] Started Serial Getty on ttyS1. Starting 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. [ OK ] Started Authorization Manager. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg251-server login: [ 71.883480] hrtimer: interrupt took 3469994 ns [ 116.570469] libcfs: loading out-of-tree module taints kernel. [ 116.618149] Key type ._llcrypt registered [ 116.620849] Key type .llcrypt registered [ 116.747898] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_hostid [ 134.706159] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing load_modules_local [ 136.489362] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 136.500987] alg: No test for adler32 (adler32-zlib) [ 138.077088] Lustre: Lustre: Build Version: 2.17.56_50_g6d2b241 [ 138.958808] LNet: Added LNI 192.168.202.151@tcp [8/256/0/180] [ 140.719301] Key type lgssc registered [ 142.235432] Lustre: Echo OBD driver; http://www.lustre.org/ [ 158.030773] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 197.643379] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing load_modules_local [ 210.343230] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 210.367904] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 211.644577] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 211.686701] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 211.788930] Lustre: lustre-MDT0000: new disk, initializing [ 211.861154] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 211.874810] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 215.439348] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 227.049873] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 227.140882] Lustre: 6516:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 227.168137] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 227.173692] Lustre: Skipped 1 previous similar message [ 227.240315] Lustre: lustre-MDT0001: new disk, initializing [ 227.304957] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 227.335576] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 227.341306] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 231.263891] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 235.171706] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 243.066712] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 243.263397] Lustre: lustre-OST0000: new disk, initializing [ 243.266640] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 243.271038] Lustre: 8451:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 243.315691] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 249.180377] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 250.911457] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 250.920185] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 250.950446] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 262.542699] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 262.710949] Lustre: lustre-OST0001: new disk, initializing [ 262.713645] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 262.717938] Lustre: 9525:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 262.775688] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 269.079822] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 269.889735] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 269.905118] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 270.040333] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 281.163409] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 293.961953] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 301.135852] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing check_logdir /tmp/testlogs/ [ 307.469887] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing yml_node [ 312.678295] Lustre: DEBUG MARKER: Client: 2.17.56.50 [ 316.146309] Lustre: DEBUG MARKER: MDS: 2.17.56.50 [ 319.101706] Lustre: DEBUG MARKER: OSS: 2.17.56.50 [ 320.934057] Lustre: DEBUG MARKER: -----============= acceptance-small: replay-dual ============----- Mon Aug 10 09:54:12 EDT 2026 [ 337.417897] Lustre: DEBUG MARKER: excepting tests: 14b 21b [ 338.769328] Lustre: DEBUG MARKER: skipping tests SLOW=no: 21b [ 340.902080] Lustre: DEBUG MARKER: === replay-dual: start setup 09:54:32 (1786370072) === [ 346.637714] Lustre: DEBUG MARKER: oleg251-client.virtnet: executing check_config_client /mnt/lustre [ 365.931183] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 369.415605] Lustre: 13387:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 373.344842] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 379.283316] Lustre: DEBUG MARKER: === replay-dual: finish setup 09:55:10 (1786370110) === [ 381.306540] Lustre: DEBUG MARKER: == replay-dual test 0a: expired recovery with lost client ========================================================== 09:55:12 (1786370112) [ 389.694381] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 393.545327] Lustre: Failing over lustre-MDT0000 [ 393.807685] Lustre: server umount lustre-MDT0000 complete [ 396.257962] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 396.263942] 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 [ 398.309552] 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 [ 398.329513] Lustre: Skipped 2 previous similar messages [ 402.922130] LustreError: 6524:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.202.51@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 402.955170] LustreError: 6524:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 9 previous similar messages [ 403.430960] 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. [ 403.463745] LustreError: 6523:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 3 previous similar messages [ 406.003770] LustreError: 6522:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.202.51@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 406.031530] LustreError: 6522:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 1 previous similar message [ 408.041816] LustreError: 6523:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.202.51@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 413.157542] LustreError: 6523:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.202.51@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 413.183063] LustreError: 6523:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 5 previous similar messages [ 414.687353] Lustre: 3648:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786370132/real 1786370132] req@ffff9a343a107480 x1873144575021568/t0(0) o400->MGC192.168.202.151@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1786370148 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 414.719492] LustreError: MGC192.168.202.151@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 417.390768] LDISKFS-fs (dm-0): 10 truncates cleaned up [ 417.397752] LDISKFS-fs (dm-0): recovery complete [ 417.417771] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 424.440242] LustreError: 6523:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.202.51@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 424.462806] LustreError: 6523:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 19 previous similar messages [ 425.406186] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 426.277791] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 430.295584] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 430.590958] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 532.503701] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 532.508038] Lustre: 14927:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client e895e037-933b-4aa0-80f3-c4c32f209b02@192.168.202.51@tcp [ 532.534564] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 532.561926] Lustre: 14927:0:(ldlm_lib.c:2951:target_recovery_thread()) too long recovery - read logs [ 532.563052] Lustre: lustre-MDT0000-osp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 532.575178] LustreError: dumping log to /tmp/lustre-log.1786370266.14927 [ 532.579455] Lustre: Skipped 2 previous similar messages [ 532.711799] Lustre: lustre-MDT0000: Recovery over after 1:46, of 3 clients 2 recovered and 1 was evicted. [ 532.749997] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:28 to 0x280000401:65) [ 532.763775] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:28 to 0x2c0000401:65) [ 553.927859] Lustre: DEBUG MARKER: == replay-dual test 0b: lost client during waiting for next transno ========================================================== 09:58:05 (1786370285) [ 560.530928] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 562.465365] Lustre: Failing over lustre-MDT0000 [ 562.749716] Lustre: server umount lustre-MDT0000 complete [ 563.683081] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 563.695618] 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 [ 563.719614] LustreError: 6528: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. [ 563.742678] LustreError: 6528:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 4 previous similar messages [ 566.762078] 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 [ 566.774422] Lustre: Skipped 2 previous similar messages [ 583.650530] Lustre: 3647:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786370300/real 1786370300] req@ffff9a343569d880 x1873144575102208/t0(0) o400->MGC192.168.202.151@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1786370316 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 583.694157] LustreError: MGC192.168.202.151@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 584.122325] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 584.127155] LDISKFS-fs (dm-0): recovery complete [ 584.134418] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 593.897834] LustreError: 3646:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9a343fbe5f80 x1873144575111680/t0(0) o250->MGC192.168.202.151@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 [ 594.196642] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 594.702737] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 599.016817] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 599.546551] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 611.818070] Lustre: lustre-MDT0000: Denying connection for new client 0d0ff944-d11f-4d31-816d-8e65d8a5876f (at 192.168.202.51@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:52 [ 616.932206] Lustre: lustre-MDT0000: Denying connection for new client 0d0ff944-d11f-4d31-816d-8e65d8a5876f (at 192.168.202.51@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:47 [ 619.939097] Lustre: lustre-MDT0000: Denying connection for new client 0d0ff944-d11f-4d31-816d-8e65d8a5876f (at 192.168.202.51@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:44 [ 625.150074] Lustre: lustre-MDT0000: Denying connection for new client 0d0ff944-d11f-4d31-816d-8e65d8a5876f (at 192.168.202.51@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:39 [ 630.246891] Lustre: lustre-MDT0001: haven't heard from client e895e037-933b-4aa0-80f3-c4c32f209b02 (at 192.168.202.51@tcp) in 101 seconds. I think it's dead, and I am evicting it. exp ffff9a3303595000, cur 1786370364 deadline 1786370363 last 1786370263 [ 630.259851] Lustre: lustre-MDT0000: Denying connection for new client 0d0ff944-d11f-4d31-816d-8e65d8a5876f (at 192.168.202.51@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:34 [ 640.499037] Lustre: lustre-MDT0000: Denying connection for new client 0d0ff944-d11f-4d31-816d-8e65d8a5876f (at 192.168.202.51@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:24 [ 640.517843] Lustre: Skipped 1 previous similar message [ 660.977635] Lustre: lustre-MDT0000: Denying connection for new client 0d0ff944-d11f-4d31-816d-8e65d8a5876f (at 192.168.202.51@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:03 [ 661.000814] Lustre: Skipped 3 previous similar messages [ 664.500242] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 664.504253] Lustre: 16670:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 6fb8557c-934c-43f3-a5b9-dac2309d1b15@ [ 664.512039] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 696.812538] Lustre: lustre-MDT0000: Denying connection for new client 0d0ff944-d11f-4d31-816d-8e65d8a5876f (at 192.168.202.51@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 1 evicted) to recover in 1:08 [ 696.828599] Lustre: Skipped 6 previous similar messages [ 701.931764] Lustre: lustre-MDT0001: haven't heard from client 9ae7a73f-15ef-4013-a592-1ff3bd2f9ac5 (at 192.168.202.51@tcp) in 102 seconds. I think it's dead, and I am evicting it. exp ffff9a330326a800, cur 1786370435 deadline 1786370433 last 1786370333 [ 763.373234] Lustre: lustre-MDT0000: Denying connection for new client 0d0ff944-d11f-4d31-816d-8e65d8a5876f (at 192.168.202.51@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 1 evicted) to recover in 0:02 [ 763.388444] Lustre: Skipped 12 previous similar messages [ 765.500158] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 765.509855] Lustre: 16670:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 9ae7a73f-15ef-4013-a592-1ff3bd2f9ac5@192.168.202.51@tcp [ 765.533536] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 765.544740] Lustre: 16670:0:(ldlm_lib.c:2085:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 765.566173] Lustre: 16670:0:(ldlm_lib.c:2951:target_recovery_thread()) too long recovery - read logs [ 765.566633] Lustre: lustre-MDT0000-osp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 765.582786] LustreError: dumping log to /tmp/lustre-log.1786370499.16670 [ 765.588178] Lustre: Skipped 2 previous similar messages [ 765.720661] Lustre: lustre-MDT0000: Recovery over after 2:51, of 3 clients 1 recovered and 2 were evicted. [ 765.766654] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:28 to 0x280000401:97) [ 765.770884] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:28 to 0x2c0000401:97) [ 775.063525] Lustre: DEBUG MARKER: == replay-dual test 1: |X| simple create ================= 10:01:46 (1786370506) [ 780.945378] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 782.527172] Lustre: Failing over lustre-MDT0000 [ 782.852644] Lustre: server umount lustre-MDT0000 complete [ 783.843976] 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 [ 783.845430] 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. [ 783.853814] Lustre: Skipped 3 previous similar messages [ 783.879563] LustreError: 6523:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 39 previous similar messages [ 800.229032] Lustre: 3647:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786370517/real 1786370517] req@ffff9a3304470380 x1873144575197824/t0(0) o400->MGC192.168.202.151@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1786370533 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 800.251368] LustreError: MGC192.168.202.151@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 802.956057] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 802.961045] LDISKFS-fs (dm-0): recovery complete [ 802.970033] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 810.464271] LustreError: 3646:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9a33033b8a80 x1873144575206144/t0(0) o250->MGC192.168.202.151@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 [ 810.780446] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 810.834248] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 812.407702] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 814.235206] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 816.134810] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 816.269295] Lustre: lustre-MDT0000: Recovery over after 0:04, of 3 clients 3 recovered and 0 were evicted. [ 816.313343] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:129) [ 816.322181] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:129) [ 821.777990] Lustre: DEBUG MARKER: oleg251-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 823.076154] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 829.801303] Lustre: DEBUG MARKER: == replay-dual test 2: |X| mkdir adir ==================== 10:02:41 (1786370561) [ 835.748983] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 837.111714] Lustre: Failing over lustre-MDT0000 [ 837.302332] Lustre: server umount lustre-MDT0000 complete [ 841.700972] 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 [ 841.708302] Lustre: Skipped 3 previous similar messages [ 848.368044] LustreError: 6522:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.202.51@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 848.387256] LustreError: 6522:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 49 previous similar messages [ 857.926975] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 857.933749] LDISKFS-fs (dm-0): recovery complete [ 857.942661] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 858.055417] LustreError: MGC192.168.202.151@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 858.060522] Lustre: 3647:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786370575/real 1786370575] req@ffff9a330568aa00 x1873144575231232/t0(0) o400->MGC192.168.202.151@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1786370591 ref 1 fl Rpc:EXNQr/200/ffffffff rc -5/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 858.301370] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 858.344716] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 858.598412] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 861.703449] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 863.734963] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 863.740865] Lustre: Skipped 3 previous similar messages [ 863.790617] Lustre: lustre-MDT0000: Recovery over after 0:05, of 3 clients 3 recovered and 0 were evicted. [ 863.824399] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:161) [ 863.825796] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:161) [ 870.238821] Lustre: DEBUG MARKER: oleg251-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 871.680424] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 878.804767] Lustre: DEBUG MARKER: == replay-dual test 3: |X| mkdir adir, mkdir adir/bdir === 10:03:30 (1786370610) [ 884.863344] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 886.810241] Lustre: Failing over lustre-MDT0000 [ 887.116659] Lustre: server umount lustre-MDT0000 complete [ 889.318947] 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 [ 889.322855] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 889.334353] Lustre: Skipped 3 previous similar messages [ 905.688113] Lustre: 3648:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786370623/real 1786370623] req@ffff9a3304657b80 x1873144575267584/t0(0) o400->MGC192.168.202.151@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1786370639 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 905.721417] LustreError: MGC192.168.202.151@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 907.104728] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 907.106644] LDISKFS-fs (dm-0): recovery complete [ 907.116531] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 916.281957] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 917.132117] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 919.514373] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 921.581067] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 921.586927] Lustre: Skipped 3 previous similar messages [ 921.668252] Lustre: lustre-MDT0000: Recovery over after 0:04, of 3 clients 3 recovered and 0 were evicted. [ 921.706429] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:193) [ 921.707026] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:193) [ 926.728513] Lustre: DEBUG MARKER: oleg251-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 927.892487] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 935.397423] Lustre: DEBUG MARKER: == replay-dual test 4: |X| mkdir adir (-EEXIST), mkdir adir/bdir ========================================================== 10:04:26 (1786370666) [ 940.897190] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 942.268563] Lustre: Failing over lustre-MDT0000 [ 942.456247] Lustre: server umount lustre-MDT0000 complete [ 942.560303] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 942.562912] 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 [ 962.188808] LDISKFS-fs (dm-0): 4 truncates cleaned up [ 962.190421] LDISKFS-fs (dm-0): recovery complete [ 962.199696] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 962.279551] LustreError: MGC192.168.202.151@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 962.483281] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 962.485838] Lustre: Skipped 1 previous similar message [ 962.527706] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 964.068874] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 966.474487] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 967.699168] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 967.708944] Lustre: Skipped 3 previous similar messages [ 967.775548] Lustre: lustre-MDT0000: Recovery over after 0:03, of 3 clients 3 recovered and 0 were evicted. [ 967.798723] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:225) [ 967.798873] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:225) [ 974.641716] Lustre: DEBUG MARKER: oleg251-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 975.953339] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 982.741495] Lustre: DEBUG MARKER: == replay-dual test 5: open, unlink |X| close ============ 10:05:14 (1786370714) [ 988.760643] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 990.547228] Lustre: Failing over lustre-MDT0000 [ 990.827065] Lustre: server umount lustre-MDT0000 complete [ 993.250404] LustreError: 6527: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. [ 993.263562] LustreError: 6527:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 80 previous similar messages [ 1009.631184] Lustre: 3650:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786370727/real 1786370727] req@ffff9a34060b1500 x1873144575340672/t0(0) o400->MGC192.168.202.151@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1786370743 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1009.669479] LustreError: MGC192.168.202.151@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1012.273568] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1012.276055] LDISKFS-fs (dm-0): recovery complete [ 1012.285186] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1021.202089] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1021.412453] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 1025.030972] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 1026.669567] Lustre: lustre-MDT0000: Recovery over after 0:05, of 3 clients 3 recovered and 0 were evicted. [ 1026.712949] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:257) [ 1026.715395] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:257) [ 1033.072433] Lustre: DEBUG MARKER: oleg251-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1034.500186] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1043.461655] Lustre: DEBUG MARKER: == replay-dual test 6: open1, open2, unlink |X| close1 [fail mds1] close2 ========================================================== 10:06:14 (1786370774) [ 1051.305640] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1052.793168] Lustre: Failing over lustre-MDT0000 [ 1052.976804] Lustre: server umount lustre-MDT0000 complete [ 1057.252797] 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 [ 1057.279432] Lustre: Skipped 10 previous similar messages [ 1072.848399] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1072.850804] LDISKFS-fs (dm-0): recovery complete [ 1072.856671] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1072.931855] LustreError: MGC192.168.202.151@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1073.193776] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1073.689461] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 1076.872763] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 1078.264316] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1078.273986] Lustre: Skipped 7 previous similar messages [ 1078.389623] Lustre: lustre-MDT0000: Recovery over after 0:05, of 3 clients 3 recovered and 0 were evicted. [ 1078.431376] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:289) [ 1078.436253] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:289) [ 1085.957320] Lustre: DEBUG MARKER: oleg251-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1087.505418] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1094.843642] Lustre: DEBUG MARKER: == replay-dual test 8: replay of resent request ========== 10:07:06 (1786370826) [ 1100.782891] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1101.653116] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 1101.656294] LustreError: 6522:0:(ldlm_lib.c:3346:target_send_reply_msg()) @@@ dropping reply req@ffff9a3303751880 x1873144555250688/t38654705670(0) o36->0d0ff944-d11f-4d31-816d-8e65d8a5876f@192.168.202.51@tcp:76/0 lens 512/448 e 0 to 0 dl 1786370846 ref 1 fl Interpret:/200/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 1118.185539] Lustre: lustre-MDT0000: Client 0d0ff944-d11f-4d31-816d-8e65d8a5876f (at 192.168.202.51@tcp) reconnecting [ 1118.203961] Lustre: 6523:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9a342f881500 x1873144555250688/t38654705670(0) o36->0d0ff944-d11f-4d31-816d-8e65d8a5876f@192.168.202.51@tcp:92/0 lens 512/2880 e 0 to 0 dl 1786370862 ref 1 fl Interpret:/202/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 1120.938840] Lustre: Failing over lustre-MDT0000 [ 1121.173464] Lustre: server umount lustre-MDT0000 complete [ 1140.526972] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1140.530034] LDISKFS-fs (dm-0): recovery complete [ 1140.540346] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1140.648412] LustreError: MGC192.168.202.151@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1140.906435] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1140.912381] Lustre: Skipped 2 previous similar messages [ 1140.981602] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1144.309876] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 1144.804945] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 1146.414022] Lustre: lustre-MDT0000: Recovery over after 0:02, of 3 clients 3 recovered and 0 were evicted. [ 1146.443070] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:321) [ 1146.445722] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:321) [ 1151.684690] Lustre: DEBUG MARKER: oleg251-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1152.801881] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1159.057892] Lustre: DEBUG MARKER: == replay-dual test 9: resending a replayed create ======= 10:08:10 (1786370890) [ 1164.872372] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1166.893114] Lustre: Failing over lustre-MDT0000 [ 1167.082937] Lustre: server umount lustre-MDT0000 complete [ 1171.956473] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1187.187062] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1187.189955] LDISKFS-fs (dm-0): recovery complete [ 1187.206357] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1187.279132] Lustre: 3650:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786370905/real 1786370905] req@ffff9a3303f69f80 x1873144575452800/t0(0) o400->MGC192.168.202.151@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1786370921 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1197.823871] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1202.166859] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 1203.248120] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 1203.252254] LustreError: 32158:0:(ldlm_lib.c:3346:target_send_reply_msg()) @@@ dropping reply req@ffff9a3303f6b480 x1873144555266560/t42949672962(42949672962) o36->0d0ff944-d11f-4d31-816d-8e65d8a5876f@192.168.202.51@tcp:173/0 lens 528/448 e 0 to 0 dl 1786370943 ref 1 fl Complete:/204/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 1214.461586] Lustre: lustre-MDT0000: Client 0d0ff944-d11f-4d31-816d-8e65d8a5876f (at 192.168.202.51@tcp) reconnected, waiting for 3 clients in recovery for 1:29 [ 1214.584299] Lustre: lustre-MDT0000-osp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1214.590081] Lustre: Skipped 10 previous similar messages [ 1214.652472] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:353) [ 1214.656234] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:353) [ 1219.411396] Lustre: DEBUG MARKER: oleg251-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1220.622462] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1228.546230] Lustre: DEBUG MARKER: == replay-dual test 10: resending a replayed unlink ====== 10:09:20 (1786370960) [ 1234.039421] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1236.310904] Lustre: Failing over lustre-MDT0000 [ 1236.538312] Lustre: server umount lustre-MDT0000 complete [ 1239.015506] 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 [ 1239.027218] Lustre: Skipped 11 previous similar messages [ 1249.264848] LustreError: 6528: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. [ 1249.284932] LustreError: 6528:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 145 previous similar messages [ 1254.367224] Lustre: 3649:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786370972/real 1786370972] req@ffff9a3408db0700 x1873144575489792/t0(0) o400->MGC192.168.202.151@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1786370988 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1256.607559] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1256.609566] LDISKFS-fs (dm-0): recovery complete [ 1256.619665] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1264.609135] LustreError: 3646:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9a342fcc4000 x1873144575496704/t0(0) o250->MGC192.168.202.151@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 [ 1264.932740] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1267.488373] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 1270.319566] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 1270.322467] LustreError: 34217:0:(ldlm_lib.c:3346:target_send_reply_msg()) @@@ dropping reply req@ffff9a343569f480 x1873144555286144/t47244640260(47244640260) o36->0d0ff944-d11f-4d31-816d-8e65d8a5876f@192.168.202.51@tcp:241/0 lens 528/448 e 0 to 0 dl 1786371011 ref 1 fl Complete:/204/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 1283.102038] Lustre: lustre-MDT0000: Client 0d0ff944-d11f-4d31-816d-8e65d8a5876f (at 192.168.202.51@tcp) reconnected, waiting for 3 clients in recovery for 1:27 [ 1283.153875] Lustre: lustre-MDT0000: Recovery over after 0:17, of 3 clients 3 recovered and 0 were evicted. [ 1283.169267] Lustre: Skipped 1 previous similar message [ 1283.207649] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:385) [ 1283.207894] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:385) [ 1287.667617] Lustre: DEBUG MARKER: oleg251-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1288.688274] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1295.860259] Lustre: DEBUG MARKER: == replay-dual test 11: both clients timeout during replay ========================================================== 10:10:27 (1786371027) [ 1301.520661] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1303.420067] Lustre: Failing over lustre-MDT0000 [ 1303.688500] Lustre: server umount lustre-MDT0000 complete [ 1304.032398] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1321.424145] Lustre: 3649:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786371039/real 1786371039] req@ffff9a3303751c00 x1873144575526272/t0(0) o400->MGC192.168.202.151@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1786371055 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1321.446431] LustreError: MGC192.168.202.151@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1321.453936] LustreError: Skipped 2 previous similar messages [ 1323.939792] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1323.945966] LDISKFS-fs (dm-0): recovery complete [ 1323.957580] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1331.693186] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x9ddb3b30e4e9b702 [ 1333.228036] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 1333.242447] Lustre: Skipped 2 previous similar messages [ 1335.409806] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 1337.367790] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 1337.375321] LustreError: 36274:0:(ldlm_lib.c:3346:target_send_reply_msg()) @@@ dropping reply req@ffff9a343fcdfb80 x1873144555303168/t51539607554(51539607554) o36->0d0ff944-d11f-4d31-816d-8e65d8a5876f@192.168.202.51@tcp:308/0 lens 528/448 e 0 to 0 dl 1786371078 ref 1 fl Complete:/204/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 1341.072910] Lustre: DEBUG MARKER: oleg251-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1349.620690] Lustre: lustre-MDT0000: Client 0d0ff944-d11f-4d31-816d-8e65d8a5876f (at 192.168.202.51@tcp) reconnected, waiting for 3 clients in recovery for 1:27 [ 1349.759121] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:417) [ 1349.759866] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:417) [ 1350.818518] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 8 sec [ 1356.357602] Lustre: DEBUG MARKER: == replay-dual test 12: open resend timeout ============== 10:11:28 (1786371088) [ 1361.643871] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1363.547938] Lustre: Failing over lustre-MDT0000 [ 1363.737600] Lustre: server umount lustre-MDT0000 complete [ 1364.961132] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1382.716512] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1382.718881] LDISKFS-fs (dm-0): recovery complete [ 1382.724460] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1385.876483] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 1388.190555] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:449) [ 1388.190567] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:449) [ 1394.010657] Lustre: DEBUG MARKER: == replay-dual test 13: close resend timeout ============= 10:12:05 (1786371125) [ 1399.648672] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1401.590248] Lustre: Failing over lustre-MDT0000 [ 1401.859380] Lustre: server umount lustre-MDT0000 complete [ 1403.883219] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1420.944352] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1420.946376] LDISKFS-fs (dm-0): recovery complete [ 1420.953616] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1421.279155] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1421.284830] Lustre: Skipped 4 previous similar messages [ 1421.316593] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1421.332110] Lustre: Skipped 2 previous similar messages [ 1425.318867] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 1426.535359] Lustre: *** cfs_fail_loc=115, val=2147483648*** [ 1442.867040] Lustre: lustre-MDT0000: Client 0d0ff944-d11f-4d31-816d-8e65d8a5876f (at 192.168.202.51@tcp) reconnected, waiting for 3 clients in recovery for 1:24 [ 1442.961691] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:481) [ 1442.962368] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:481) [ 1447.792685] Lustre: DEBUG MARKER: SKIP: replay-dual test_14b skipping ALWAYS excluded test 14b [ 1448.780795] Lustre: DEBUG MARKER: == replay-dual test 15a: timeout waiting for lost client during replay, 1 client completes ========================================================== 10:13:00 (1786371180) [ 1453.987642] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1456.107844] Lustre: Failing over lustre-MDT0000 [ 1456.359212] Lustre: server umount lustre-MDT0000 complete [ 1472.484883] Lustre: 3650:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786371190/real 1786371190] req@ffff9a343fdfc380 x1873144575620480/t0(0) o400->MGC192.168.202.151@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1786371206 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1474.471121] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1474.473477] LDISKFS-fs (dm-0): recovery complete [ 1474.481624] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1485.673473] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 1488.361054] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1488.369598] Lustre: Skipped 17 previous similar messages [ 1554.501041] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 1554.505973] Lustre: 41913:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client f95d6f5f-4410-44b2-bc10-f92f14519444@ [ 1554.512689] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 1554.935637] Lustre: lustre-MDT0000: Recovery over after 1:10, of 3 clients 2 recovered and 1 was evicted. [ 1554.940244] Lustre: Skipped 3 previous similar messages [ 1554.981218] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:494 to 0x2c0000401:513) [ 1554.981660] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:495 to 0x280000401:513) [ 1558.782951] Lustre: DEBUG MARKER: oleg251-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1559.882222] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1566.494717] Lustre: DEBUG MARKER: == replay-dual test 15c: remove multiple OST orphans ===== 10:14:58 (1786371298) [ 1571.346813] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1636.436920] Lustre: Failing over lustre-MDT0000 [ 1636.801386] Lustre: server umount lustre-MDT0000 complete [ 1636.841114] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1636.845330] 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 [ 1636.863116] Lustre: Skipped 19 previous similar messages [ 1654.194653] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1654.196156] LDISKFS-fs (dm-0): recovery complete [ 1654.202314] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1654.267227] LustreError: MGC192.168.202.151@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1654.272755] LustreError: Skipped 3 previous similar messages [ 1654.753453] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 1654.759228] Lustre: Skipped 3 previous similar messages [ 1656.714030] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 1724.500515] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 1724.505622] Lustre: 43919:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client fb6c6719-e50a-4b67-948d-bb55a6da9859@ [ 1724.515746] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 1724.618175] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:494 to 0x2c0000401:1537) [ 1724.620871] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:495 to 0x280000401:1537) [ 1728.292650] Lustre: DEBUG MARKER: oleg251-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1729.318330] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1734.584884] Lustre: DEBUG MARKER: == replay-dual test 16: fail MDS during recovery (3571) == 10:17:46 (1786371466) [ 1738.821497] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1740.365022] Lustre: Failing over lustre-MDT0000 [ 1740.558610] Lustre: server umount lustre-MDT0000 complete [ 1757.593135] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1757.595604] LDISKFS-fs (dm-0): recovery complete [ 1757.599492] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1757.886808] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1757.893516] Lustre: Skipped 2 previous similar messages [ 1760.329601] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 1782.682742] Lustre: Failing over lustre-MDT0000 [ 1782.690934] LustreError: 46358:0:(ldlm_lib.c:3004:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 1782.696675] Lustre: 45884:0:(ldlm_lib.c:2404:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 1782.700181] Lustre: 45884:0:(ldlm_lib.c:1914:abort_req_replay_queue()) @@@ aborted: req@ffff9a342f11c700 x1873144557740160/t0(73014444033) o36->0d0ff944-d11f-4d31-816d-8e65d8a5876f@192.168.202.51@tcp:3/0 lens 528/0 e 2 to 0 dl 1786371528 ref 1 fl Complete:/204/ffffffff rc 0/-1 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 1782.711487] Lustre: lustre-MDT0000-osd: cancel update llog [0x200000400:0x1:0x0] [ 1782.721152] Lustre: lustre-MDT0000: Not available for connect from 192.168.202.51@tcp (stopping) [ 1782.724564] Lustre: lustre-MDT0001-osp-MDT0000: cancel update llog [0x240000401:0x1:0x0] [ 1782.727934] LustreError: 45884:0:(client.c:1381:ptlrpc_import_delay_req()) @@@ IMP_CLOSED req@ffff9a34109fea00 x1873144575793536/t0(0) o1000->lustre-MDT0001-osp-MDT0000@0@lo:24/4 lens 336/33016 e 0 to 0 dl 0 ref 2 fl Rpc:QU/200/ffffffff rc 0/-1 job:'tgt_recover_0.0' uid:0 gid:0 projid:4294967295 [ 1782.737585] LustreError: 45884:0:(llog_osd.c:1178:llog_osd_next_block()) lustre-MDT0001-osp-MDT0000: can't read llog block from log [0x240000401:0x1:0x0] offset 32768: rc = -5 [ 1782.742494] LustreError: 45884:0:(llog.c:875:llog_process_thread()) lustre-MDT0001-osp-MDT0000 retry remote llog process [ 1782.746713] LustreError: 45884:0:(fid_request.c:217:seq_client_alloc_seq()) cli-cli-lustre-MDT0001-osp-MDT0000: Cannot allocate new meta-sequence: rc = -5 [ 1782.751128] LustreError: 45884:0:(fid_request.c:321:seq_client_alloc_fid()) cli-cli-lustre-MDT0001-osp-MDT0000: Can't allocate new sequence: rc = -5 [ 1782.878823] Lustre: server umount lustre-MDT0000 complete [ 1783.782175] LustreError: 6524: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. [ 1783.790696] LustreError: 6524:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 170 previous similar messages [ 1797.470624] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1799.814576] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 1803.743140] Lustre: 3646:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786371497/real 1786371497] req@ffff9a342fcf1c00 x1873144575786496/t0(0) o400->lustre-MDT0000-osp-MDT0001@0@lo:24/4 lens 224/224 e 2 to 1 dl 1786371537 ref 1 fl Rpc:XQr/2c0/ffffffff rc 0/-1 job:'ldlm_lock_repla.0' uid:0 gid:0 projid:4294967295 [ 1868.500537] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 1868.503958] Lustre: 46813:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 80faa523-5754-4710-96de-1ea37b91d5ea@ [ 1868.512106] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 1869.056880] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1551 to 0x280000401:1569) [ 1869.058618] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1550 to 0x2c0000401:1569) [ 1872.434428] Lustre: DEBUG MARKER: oleg251-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1873.264628] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1879.143082] Lustre: DEBUG MARKER: == replay-dual test 17: fail OST during recovery (3571) == 10:20:11 (1786371611) [ 1883.991467] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 1885.123564] Lustre: Failing over lustre-OST0000 [ 1885.199329] Lustre: server umount lustre-OST0000 complete [ 1901.887593] LDISKFS-fs (dm-2): 3 truncates cleaned up [ 1901.889852] LDISKFS-fs (dm-2): recovery complete [ 1901.898322] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 1906.170420] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 1930.337725] Lustre: Failing over lustre-OST0000 [ 1930.346116] LustreError: 49327:0:(ldlm_lib.c:3004:target_stop_recovery_thread()) lustre-OST0000: Aborting recovery [ 1930.354769] Lustre: 48761:0:(ldlm_lib.c:2404:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 1930.362965] Lustre: 48761:0:(ldlm_lib.c:2404:target_recovery_overseer()) Skipped 2 previous similar messages [ 1930.367622] LustreError: 48761:0:(ofd_obd.c:1324:ofd_iocontrol()) lustre-OST0000: iocontrol from 'tgt_recover_0' cmd=c00866c1 _IOWR('f', 193, 8) unrecognized: rc = -25 [ 1930.610568] Lustre: server umount lustre-OST0000 complete [ 1951.753640] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 1951.960991] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 1951.970723] Lustre: Skipped 5 previous similar messages [ 1961.133465] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 2023.501518] Lustre: lustre-OST0000: recovery is timed out, evict stale exports [ 2023.504807] Lustre: 49765:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-OST0000: disconnect stale client 4b7bcd56-ac08-427f-9303-4eaab62e6c1c@ [ 2023.514837] Lustre: lustre-OST0000: disconnecting 1 stale clients [ 2023.542492] Lustre: lustre-OST0000-osc-MDT0001: Connection restored to 0@lo (at 0@lo) [ 2023.548029] Lustre: Skipped 14 previous similar messages [ 2029.461642] Lustre: DEBUG MARKER: oleg251-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 2030.642621] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 2038.331074] Lustre: DEBUG MARKER: == replay-dual test 18: ldlm_handle_enqueue succeeds on evicted export (3822) ========================================================== 10:22:49 (1786371769) [ 2042.183453] LustreError: 7802:0:(ldlm_lockd.c:1361:ldlm_handle_enqueue()) cfs_fail_timeout id 30b sleeping for 40000ms [ 2082.191138] LustreError: 7802:0:(ldlm_lockd.c:1361:ldlm_handle_enqueue()) cfs_fail_timeout id 30b awake [ 2094.369992] Lustre: DEBUG MARKER: == replay-dual test 19: resend of open request =========== 10:23:45 (1786371825) [ 2100.452667] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2101.577233] Lustre: *** cfs_fail_loc=157, val=2147483648*** [ 2101.583637] LustreError: 32526:0:(ldlm_lib.c:3346:target_send_reply_msg()) @@@ dropping reply req@ffff9a3410948e00 x1873144557858688/t0(0) o101->0d0ff944-d11f-4d31-816d-8e65d8a5876f@192.168.202.51@tcp:392/0 lens 576/688 e 0 to 0 dl 1786371917 ref 1 fl Interpret:/600/0 rc 0/0 job:'createmany.0' uid:0 gid:0 projid:0 [ 2188.301063] Lustre: lustre-MDT0000: Client 0d0ff944-d11f-4d31-816d-8e65d8a5876f (at 192.168.202.51@tcp) reconnecting [ 2190.951078] Lustre: Failing over lustre-MDT0000 [ 2191.242644] Lustre: server umount lustre-MDT0000 complete [ 2192.355474] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 2192.361734] 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 [ 2192.369915] Lustre: Skipped 9 previous similar messages [ 2209.252321] LustreError: MGC192.168.202.151@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2209.267363] LustreError: Skipped 2 previous similar messages [ 2210.131235] LDISKFS-fs (dm-0): 4 truncates cleaned up [ 2210.134512] LDISKFS-fs (dm-0): recovery complete [ 2210.147904] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2220.003684] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 2220.009625] Lustre: Skipped 4 previous similar messages [ 2223.109577] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 2225.174878] Lustre: 52410:0:(ldlm_lib.c:2085:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 2225.254094] Lustre: lustre-MDT0000: Recovery over after 0:05, of 3 clients 3 recovered and 0 were evicted. [ 2225.268015] Lustre: Skipped 5 previous similar messages [ 2225.311896] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1584 to 0x2c0000401:1601) [ 2225.312260] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1584 to 0x280000401:1601) [ 2231.028758] Lustre: DEBUG MARKER: oleg251-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2232.167835] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2238.999097] Lustre: DEBUG MARKER: == replay-dual test 20: recovery time is not increasing == 10:26:10 (1786371970) [ 2244.805358] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2246.367211] Lustre: Failing over lustre-MDT0000 [ 2246.642916] Lustre: server umount lustre-MDT0000 complete [ 2266.635820] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2266.638121] LDISKFS-fs (dm-0): recovery complete [ 2266.644567] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2270.303263] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 2408.500263] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 2408.507454] Lustre: 54344:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 594a5b6f-b8d4-4175-aab9-0c38b89061f0@ [ 2408.520287] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 2408.597591] Lustre: 54344:0:(ldlm_lib.c:2085:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 2408.615032] Lustre: 54344:0:(ldlm_lib.c:2085:extend_recovery_timer()) Skipped 6 previous similar messages [ 2408.734206] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1603 to 0x280000401:1633) [ 2408.741530] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1584 to 0x2c0000401:1633) [ 2413.301757] Lustre: DEBUG MARKER: oleg251-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2414.719902] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2423.091393] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2424.685954] Lustre: Failing over lustre-MDT0000 [ 2424.980460] Lustre: server umount lustre-MDT0000 complete [ 2425.839300] LustreError: 6528: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. [ 2425.865994] LustreError: 6528:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 86 previous similar messages [ 2442.209342] Lustre: 3650:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786372159/real 1786372159] req@ffff9a3410be5500 x1873144576110464/t0(0) o400->MGC192.168.202.151@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1786372175 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2442.230339] Lustre: 3650:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 2444.913887] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2444.916507] LDISKFS-fs (dm-0): recovery complete [ 2444.924982] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2452.449787] LustreError: 3646:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9a342fc57b80 x1873144576119168/t0(0) o250->MGC192.168.202.151@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 [ 2452.469506] LustreError: 3646:0:(client.c:1391:ptlrpc_import_delay_req()) Skipped 1 previous similar message [ 2452.833354] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 2452.836965] Lustre: Skipped 5 previous similar messages [ 2456.234062] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 2594.500205] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 2594.502742] Lustre: 56133:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 35c6ee9d-a8e4-4e7f-bebb-31b82a00b9b6@ [ 2594.510173] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 2594.538398] Lustre: 56133:0:(ldlm_lib.c:2085:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 2594.546531] Lustre: 56133:0:(ldlm_lib.c:2085:extend_recovery_timer()) Skipped 4 previous similar messages [ 2594.652042] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1603 to 0x280000401:1665) [ 2594.653311] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1635 to 0x2c0000401:1665) [ 2598.441948] Lustre: DEBUG MARKER: oleg251-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2599.419247] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2604.996182] Lustre: DEBUG MARKER: == replay-dual test 21a: commit on sharing =============== 10:32:17 (1786372337) [ 2609.885800] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2611.079052] Lustre: Failing over lustre-MDT0000 [ 2611.279245] Lustre: server umount lustre-MDT0000 complete [ 2627.335803] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2627.338811] LDISKFS-fs (dm-0): recovery complete [ 2627.344937] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2627.587618] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 2627.590570] Lustre: Skipped 3 previous similar messages [ 2629.572378] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 2632.681634] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 2632.684010] Lustre: Skipped 13 previous similar messages [ 2769.501069] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 2769.506694] Lustre: 58157:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 1f9837ec-7caa-4983-984a-108312ab27bc@ [ 2769.512831] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 2769.563017] Lustre: 58157:0:(ldlm_lib.c:2085:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 2769.569954] Lustre: 58157:0:(ldlm_lib.c:2085:extend_recovery_timer()) Skipped 4 previous similar messages [ 2769.609669] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1603 to 0x280000401:1697) [ 2769.610529] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1667 to 0x2c0000401:1697) [ 2775.159184] Lustre: DEBUG MARKER: SKIP: replay-dual test_21b skipping SLOW test 21b [ 2776.192411] Lustre: DEBUG MARKER: == replay-dual test 22a: c1 lfs mkdir -i 1 dir1, M1 drop reply [ 2776.903360] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 2776.906544] LustreError: 6522:0:(ldlm_lib.c:3346:target_send_reply_msg()) @@@ dropping reply req@ffff9a3442161880 x1873144557971072/t4294967341(0) o36->0d0ff944-d11f-4d31-816d-8e65d8a5876f@192.168.202.51@tcp:311/0 lens 560/448 e 0 to 0 dl 1786372591 ref 1 fl Interpret:/200/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 2778.861971] Lustre: Failing over lustre-MDT0001 [ 2778.996623] Lustre: server umount lustre-MDT0001 complete [ 2781.155880] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 2793.854486] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2796.525577] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 2799.151450] Lustre: 32526:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9a343a0ab800 x1873144557971072/t4294967341(0) o36->0d0ff944-d11f-4d31-816d-8e65d8a5876f@192.168.202.51@tcp:333/0 lens 560/2880 e 0 to 0 dl 1786372613 ref 1 fl Interpret:/202/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 2802.258542] Lustre: DEBUG MARKER: oleg251-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 2803.116140] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2808.912298] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2810.011863] Lustre: Failing over lustre-MDT0000 [ 2810.279954] Lustre: server umount lustre-MDT0000 complete [ 2814.439280] Lustre: lustre-MDT0000-lwp-OST0001: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 2814.452248] Lustre: Skipped 20 previous similar messages [ 2826.719950] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2826.722029] LDISKFS-fs (dm-0): recovery complete [ 2826.733588] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2826.808103] LustreError: MGC192.168.202.151@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2826.812845] LustreError: Skipped 3 previous similar messages [ 2829.104662] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 2831.330769] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 2831.333913] Lustre: Skipped 4 previous similar messages [ 2832.391543] Lustre: 61219:0:(ldlm_lib.c:2085:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 2832.427873] Lustre: lustre-MDT0000: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [ 2832.433311] Lustre: Skipped 4 previous similar messages [ 2832.460776] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1603 to 0x280000401:1729) [ 2832.466852] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1667 to 0x2c0000401:1729) [ 2835.333953] Lustre: DEBUG MARKER: oleg251-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2836.260443] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2841.477733] Lustre: DEBUG MARKER: == replay-dual test 22b: c1 lfs mkdir -i 1 d1, M1 drop reply [ 2842.128063] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 2842.130603] LustreError: 6523:0:(ldlm_lib.c:3346:target_send_reply_msg()) @@@ dropping reply req@ffff9a342fd54700 x1873144558003712/t8589934617(0) o36->0d0ff944-d11f-4d31-816d-8e65d8a5876f@192.168.202.51@tcp:376/0 lens 560/448 e 0 to 0 dl 1786372656 ref 1 fl Interpret:/200/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 2843.977180] Lustre: Failing over lustre-MDT0000 [ 2844.019266] LustreError: 6508:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1786372577 with bad export cookie 11374750365039463551 [ 2844.033243] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2844.297280] Lustre: server umount lustre-MDT0000 complete [ 2846.360867] LustreError: 6506:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1786372580 with bad export cookie 11374750365039463446 [ 2846.368836] Lustre: Failing over lustre-MDT0001 [ 2846.380045] LustreError: 6506:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 2846.570799] Lustre: server umount lustre-MDT0001 complete [ 2861.345515] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2861.361683] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2861.495957] LustreError: 63063:0:(llog.c:1655:llog_backup()) MGC192.168.202.151@tcp: failed to open log lustre-sptlrpc: rc = -108 [ 2861.499835] Lustre: 63063:0:(mgc_request_server.c:770:mgc_llog_local_copy()) MGC192.168.202.151@tcp: failed to copy new config lustre-sptlrpc: rc = -108 [ 2871.265121] LustreError: 3646:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9a342fcf0e00 x1873144576329984/t0(0) o250->MGC192.168.202.151@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 [ 2873.818426] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 2873.891821] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 2876.996266] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1667 to 0x2c0000401:1761) [ 2876.996266] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1603 to 0x280000401:1761) [ 2877.081402] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:36 to 0x2c0000400:65) [ 2877.082630] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:36 to 0x280000400:65) [ 2877.099169] Lustre: 63073:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9a342f89b800 x1873144558003712/t8589934617(0) o36->0d0ff944-d11f-4d31-816d-8e65d8a5876f@192.168.202.51@tcp:411/0 lens 560/2880 e 0 to 0 dl 1786372691 ref 1 fl Interpret:/202/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 2880.153968] Lustre: DEBUG MARKER: oleg251-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 [ 2880.920472] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2881.746445] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2887.406780] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2888.738927] Lustre: Failing over lustre-MDT0000 [ 2888.988447] Lustre: server umount lustre-MDT0000 complete [ 2905.850185] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2905.851559] LDISKFS-fs (dm-0): recovery complete [ 2905.854978] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2908.440934] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 2911.253090] Lustre: 65280:0:(ldlm_lib.c:2085:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 2911.261210] Lustre: 65280:0:(ldlm_lib.c:2085:extend_recovery_timer()) Skipped 4 previous similar messages [ 2911.334503] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1667 to 0x2c0000401:1793) [ 2911.343795] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1603 to 0x280000401:1793) [ 2914.482451] Lustre: DEBUG MARKER: oleg251-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2915.365829] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2921.266328] Lustre: DEBUG MARKER: == replay-dual test 22c: c1 lfs mkdir -i 1 d1, M1 drop update [ 2921.966492] Lustre: *** cfs_fail_loc=1701, val=2147483648*** [ 2921.968910] LustreError: 66135:0:(ldlm_lib.c:3346:target_send_reply_msg()) @@@ dropping reply req@ffff9a3437e9bb80 x1873144576388992/t107374182411(0) o1000->lustre-MDT0001-mdtlov_UUID@0@lo:386/0 lens 2520/4320 e 0 to 0 dl 1786372666 ref 1 fl Interpret:/200/0 rc 0/0 job:'osp_up0-1.0' uid:0 gid:0 projid:4294967295 [ 2924.296789] Lustre: Failing over lustre-MDT0000 [ 2926.542712] Lustre: server umount lustre-MDT0000 complete [ 2940.892195] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2943.279348] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 2946.584129] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1667 to 0x2c0000401:1825) [ 2946.584161] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1603 to 0x280000401:1825) [ 2949.552770] Lustre: DEBUG MARKER: oleg251-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2950.416773] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2956.051369] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2957.397158] Lustre: Failing over lustre-MDT0000 [ 2957.822602] Lustre: server umount lustre-MDT0000 complete [ 2973.673261] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2973.674955] LDISKFS-fs (dm-0): recovery complete [ 2973.680646] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2975.902769] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 2979.353233] Lustre: 68467:0:(ldlm_lib.c:2085:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 2979.360280] Lustre: 68467:0:(ldlm_lib.c:2085:extend_recovery_timer()) Skipped 4 previous similar messages [ 2979.415531] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1667 to 0x2c0000401:1857) [ 2979.415556] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1603 to 0x280000401:1857) [ 2982.254652] Lustre: DEBUG MARKER: oleg251-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2983.038792] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2988.184613] Lustre: DEBUG MARKER: == replay-dual test 22d: c1 lfs mkdir -i 1 d1, M1 drop update [ 2991.295308] Lustre: *** cfs_fail_loc=1701, val=2147483648*** [ 2991.297392] LustreError: 8445:0:(ldlm_lib.c:3346:target_send_reply_msg()) @@@ dropping reply req@ffff9a342766f100 x1873144576448768/t115964117001(0) o1000->lustre-MDT0001-mdtlov_UUID@0@lo:456/0 lens 2520/4320 e 0 to 0 dl 1786372736 ref 1 fl Interpret:/200/0 rc 0/0 job:'osp_up0-1.0' uid:0 gid:0 projid:4294967295 [ 2993.498582] Lustre: Failing over lustre-MDT0000 [ 2993.690295] Lustre: server umount lustre-MDT0000 complete [ 2995.560169] LustreError: 6506:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1786372729 with bad export cookie 11374750365039471125 [ 2995.562992] Lustre: Failing over lustre-MDT0001 [ 2995.570539] LustreError: 6506:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 7 previous similar messages [ 2995.577427] LustreError: 69702:0:(ldlm_resource.c:1207:ldlm_resource_complain()) lustre-MDT0000-osp-MDT0001: namespace resource [0x2000013a1:0x78:0x0].0xf7117594 (ffff9a34421f6700) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 2995.596850] Lustre: lustre-MDT0001: Not available for connect from 192.168.202.51@tcp (stopping) [ 2999.778180] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 2999.780724] Lustre: Skipped 3 previous similar messages [ 3000.965322] Lustre: server umount lustre-MDT0001 complete [ 3015.415362] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3015.443405] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3015.564748] LustreError: 70410:0:(llog.c:1655:llog_backup()) MGC192.168.202.151@tcp: failed to open log lustre-sptlrpc: rc = -108 [ 3015.569033] Lustre: 70410:0:(mgc_request_server.c:770:mgc_llog_local_copy()) MGC192.168.202.151@tcp: failed to copy new config lustre-sptlrpc: rc = -108 [ 3020.257261] LustreError: 3646:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9a3439f3b480 x1873144576455808/t0(0) o250->MGC192.168.202.151@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 [ 3022.687621] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 3022.817450] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 3025.844454] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1667 to 0x2c0000401:1889) [ 3025.847789] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1603 to 0x280000401:1889) [ 3030.602604] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:70 to 0x280000400:97) [ 3030.603356] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:70 to 0x2c0000400:97) [ 3030.604504] Lustre: 70417:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9a3303753480 x1873144558076288/t12884901939(0) o36->0d0ff944-d11f-4d31-816d-8e65d8a5876f@192.168.202.51@tcp:564/0 lens 560/2880 e 0 to 0 dl 1786372844 ref 1 fl Interpret:/202/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 3033.457839] Lustre: DEBUG MARKER: oleg251-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 [ 3034.239839] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3035.080994] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3040.104513] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3041.064866] Lustre: Failing over lustre-MDT0000 [ 3041.253271] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3041.257286] Lustre: Skipped 6 previous similar messages [ 3041.308725] Lustre: server umount lustre-MDT0000 complete [ 3045.859260] LustreError: 71198:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.202.51@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3045.867395] LustreError: 71198:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 173 previous similar messages [ 3057.436753] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3057.439557] LDISKFS-fs (dm-0): recovery complete [ 3057.456089] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3057.728508] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 3057.735240] Lustre: Skipped 10 previous similar messages [ 3059.808189] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 3062.789719] Lustre: 72623:0:(ldlm_lib.c:2085:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3062.799945] Lustre: 72623:0:(ldlm_lib.c:2085:extend_recovery_timer()) Skipped 4 previous similar messages [ 3062.849853] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1603 to 0x280000401:1921) [ 3062.849853] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1667 to 0x2c0000401:1921) [ 3065.352639] Lustre: DEBUG MARKER: oleg251-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3066.067645] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3070.632568] Lustre: DEBUG MARKER: == replay-dual test 23a: c1 rmdir d1, M1 drop reply and fail, client2 mkdir d1 ========================================================== 10:40:02 (1786372802) [ 3071.129952] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 3071.132028] LustreError: 70421:0:(ldlm_lib.c:3346:target_send_reply_msg()) @@@ dropping reply req@ffff9a33051a7800 x1873144558111488/t17179869210(0) o36->0d0ff944-d11f-4d31-816d-8e65d8a5876f@192.168.202.51@tcp:604/0 lens 496/456 e 0 to 0 dl 1786372884 ref 1 fl Interpret:/200/0 rc 0/0 job:'rmdir.0' uid:0 gid:0 projid:4294967295 [ 3073.246991] Lustre: Failing over lustre-MDT0001 [ 3073.457591] Lustre: server umount lustre-MDT0001 complete [ 3087.243300] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3089.085565] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 3092.986956] Lustre: 70421:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9a343974b480 x1873144558111488/t17179869210(0) o36->0d0ff944-d11f-4d31-816d-8e65d8a5876f@192.168.202.51@tcp:626/0 lens 496/2888 e 0 to 0 dl 1786372906 ref 1 fl Interpret:/202/0 rc 0/0 job:'rmdir.0' uid:0 gid:0 projid:4294967295 [ 3092.997366] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:100 to 0x280000400:129) [ 3092.997453] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:100 to 0x2c0000400:129) [ 3095.139182] Lustre: DEBUG MARKER: oleg251-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 3095.829648] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3100.622872] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3101.468852] Lustre: Failing over lustre-MDT0000 [ 3101.765446] Lustre: server umount lustre-MDT0000 complete [ 3116.936069] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3116.938041] LDISKFS-fs (dm-0): recovery complete [ 3116.943026] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3118.951844] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 3122.768267] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1923 to 0x280000401:1953) [ 3122.768349] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1923 to 0x2c0000401:1953) [ 3125.252487] Lustre: DEBUG MARKER: oleg251-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3125.945216] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3130.094456] Lustre: DEBUG MARKER: == replay-dual test 23b: c1 rmdir d1, M1 drop reply and fail M0/M1, c2 mkdir d1 ========================================================== 10:41:02 (1786372862) [ 3130.716711] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 3130.718612] LustreError: 70417:0:(ldlm_lib.c:3346:target_send_reply_msg()) @@@ dropping reply req@ffff9a343fe0a680 x1873144558139136/t21474836483(0) o36->0d0ff944-d11f-4d31-816d-8e65d8a5876f@192.168.202.51@tcp:664/0 lens 496/456 e 0 to 0 dl 1786372944 ref 1 fl Interpret:/200/0 rc 0/0 job:'rmdir.0' uid:0 gid:0 projid:4294967295 [ 3132.789934] Lustre: Failing over lustre-MDT0000 [ 3132.898985] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3133.043861] Lustre: server umount lustre-MDT0000 complete [ 3134.651240] LustreError: 6508:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1786372868 with bad export cookie 11374750365039478314 [ 3134.653889] Lustre: Failing over lustre-MDT0001 [ 3134.659198] LustreError: 6508:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 3140.175143] Lustre: server umount lustre-MDT0001 complete [ 3154.086465] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3154.125991] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3159.456139] LustreError: 3646:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9a3437c29c00 x1873144576569600/t0(0) o250->MGC192.168.202.151@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 [ 3164.217514] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1923 to 0x280000401:1985) [ 3164.219330] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1923 to 0x2c0000401:1985) [ 3164.792031] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 3164.950208] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 3178.041363] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:100 to 0x280000400:161) [ 3178.041370] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:100 to 0x2c0000400:161) [ 3178.134746] Lustre: 77699:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9a3303440a80 x1873144558139136/t21474836483(0) o36->0d0ff944-d11f-4d31-816d-8e65d8a5876f@192.168.202.51@tcp:711/0 lens 496/2888 e 0 to 0 dl 1786372991 ref 1 fl Interpret:/202/0 rc 0/0 job:'rmdir.0' uid:0 gid:0 projid:4294967295 [ 3182.999574] Lustre: DEBUG MARKER: oleg251-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 [ 3185.031129] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3186.232544] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3194.120598] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3195.515814] Lustre: Failing over lustre-MDT0000 [ 3195.705200] Lustre: server umount lustre-MDT0000 complete [ 3216.875719] Lustre: 3648:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786372934/real 1786372934] req@ffff9a3303f69c00 x1873144576607744/t0(0) o400->MGC192.168.202.151@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1786372950 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3216.961730] Lustre: 3648:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 13 previous similar messages [ 3220.029997] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3220.034188] LDISKFS-fs (dm-0): recovery complete [ 3220.051751] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3227.624492] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x9ddb3b30e4ec55dc [ 3228.100794] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3228.112714] Lustre: Skipped 14 previous similar messages [ 3231.776825] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 3233.279740] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 3233.303811] Lustre: Skipped 52 previous similar messages [ 3233.328518] Lustre: 79919:0:(ldlm_lib.c:2085:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3233.340772] Lustre: 79919:0:(ldlm_lib.c:2085:extend_recovery_timer()) Skipped 13 previous similar messages [ 3233.516333] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1987 to 0x280000401:2017) [ 3233.518308] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1987 to 0x2c0000401:2017) [ 3240.560310] Lustre: DEBUG MARKER: oleg251-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3241.780826] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3250.000114] Lustre: DEBUG MARKER: == replay-dual test 23c: c1 rmdir d1, M0 drop update reply and fail M0, c2 mkdir d1 ========================================================== 10:43:01 (1786372981) [ 3251.280867] Lustre: *** cfs_fail_loc=1701, val=2147483648*** [ 3251.284040] LustreError: 8446:0:(ldlm_lib.c:3346:target_send_reply_msg()) @@@ dropping reply req@ffff9a3437c2a300 x1873144576647296/t137438953491(0) o1000->lustre-MDT0001-mdtlov_UUID@0@lo:716/0 lens 1984/4320 e 0 to 0 dl 1786372996 ref 1 fl Interpret:/200/0 rc 0/0 job:'osp_up0-1.0' uid:0 gid:0 projid:4294967295 [ 3254.395943] Lustre: Failing over lustre-MDT0000 [ 3254.637499] Lustre: server umount lustre-MDT0000 complete [ 3271.051559] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3274.330913] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 3276.844843] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1987 to 0x280000401:2049) [ 3276.848123] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1987 to 0x2c0000401:2049) [ 3280.836295] Lustre: DEBUG MARKER: oleg251-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3282.085078] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3288.778496] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3290.350050] Lustre: Failing over lustre-MDT0000 [ 3290.659356] Lustre: server umount lustre-MDT0000 complete [ 3310.431730] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3310.434125] LDISKFS-fs (dm-0): recovery complete [ 3310.439788] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3317.729495] LustreError: 3646:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9a3303f6ad80 x1873144576686336/t0(0) o250->MGC192.168.202.151@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 [ 3321.180516] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 3323.597274] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2051 to 0x280000401:2081) [ 3323.600880] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2051 to 0x2c0000401:2081) [ 3327.898948] Lustre: DEBUG MARKER: oleg251-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3329.055993] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3334.886661] Lustre: DEBUG MARKER: == replay-dual test 23d: c1 rmdir d1, M0 drop update reply and fail M0/M1, c2 mkdir d1 ========================================================== 10:44:26 (1786373066) [ 3338.970430] Lustre: *** cfs_fail_loc=1701, val=2147483648*** [ 3338.975926] LustreError: 66135:0:(ldlm_lib.c:3346:target_send_reply_msg()) @@@ dropping reply req@ffff9a3430789c00 x1873144576711936/t146028888081(0) o1000->lustre-MDT0001-mdtlov_UUID@0@lo:48/0 lens 1984/4320 e 0 to 0 dl 1786373083 ref 1 fl Interpret:/200/0 rc 0/0 job:'osp_up0-1.0' uid:0 gid:0 projid:4294967295 [ 3341.858377] Lustre: Failing over lustre-MDT0000 [ 3342.064467] Lustre: server umount lustre-MDT0000 complete [ 3344.306963] LustreError: 6506:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1786373078 with bad export cookie 11374750365039485608 [ 3344.310560] Lustre: Failing over lustre-MDT0001 [ 3344.314285] LustreError: 6506:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 3 previous similar messages [ 3344.327335] LustreError: 84344:0:(ldlm_resource.c:1207:ldlm_resource_complain()) lustre-MDT0000-osp-MDT0001: namespace resource [0x2000013a1:0x80:0x0].0x0 (ffff9a3308dffc00) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 3344.351419] Lustre: lustre-MDT0001: Not available for connect from 192.168.202.51@tcp (stopping) [ 3344.354512] Lustre: Skipped 11 previous similar messages [ 3350.267817] Lustre: server umount lustre-MDT0001 complete [ 3366.175097] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3366.332562] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3366.380495] LustreError: 85029:0:(llog.c:1655:llog_backup()) MGC192.168.202.151@tcp: failed to open log lustre-sptlrpc: rc = -108 [ 3366.386353] Lustre: 85029:0:(mgc_request_server.c:770:mgc_llog_local_copy()) MGC192.168.202.151@tcp: failed to copy new config lustre-sptlrpc: rc = -108 [ 3369.440652] LustreError: 3646:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9a343078a300 x1873144576718720/t0(0) o250->MGC192.168.202.151@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 [ 3373.221468] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 3373.649599] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 3375.166975] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2051 to 0x2c0000401:2113) [ 3375.180129] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2051 to 0x280000401:2113) [ 3375.186842] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:100 to 0x2c0000400:193) [ 3375.186896] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:100 to 0x280000400:193) [ 3375.219554] Lustre: 85056:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9a34097aed80 x1873144558212352/t25769803783(0) o36->0d0ff944-d11f-4d31-816d-8e65d8a5876f@192.168.202.51@tcp:153/0 lens 496/2888 e 0 to 0 dl 1786373188 ref 1 fl Interpret:/202/0 rc 0/0 job:'rmdir.0' uid:0 gid:0 projid:4294967295 [ 3381.452522] Lustre: DEBUG MARKER: oleg251-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 [ 3382.626299] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3383.849927] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3390.706367] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3392.245587] Lustre: Failing over lustre-MDT0000 [ 3392.440192] Lustre: server umount lustre-MDT0000 complete [ 3395.567511] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3395.573502] LustreError: Skipped 12 previous similar messages [ 3410.688528] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3410.692174] LDISKFS-fs (dm-0): recovery complete [ 3410.704639] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3410.913436] Lustre: lustre-MDT0000: Not available for connect from 0@lo (not set up) [ 3410.925132] Lustre: Skipped 12 previous similar messages [ 3414.085252] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 3416.096711] Lustre: 87267:0:(ldlm_lib.c:2085:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3416.106801] Lustre: 87267:0:(ldlm_lib.c:2085:extend_recovery_timer()) Skipped 17 previous similar messages [ 3416.198683] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2115 to 0x280000401:2145) [ 3416.203638] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2115 to 0x2c0000401:2145) [ 3420.381200] Lustre: DEBUG MARKER: oleg251-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3421.284693] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3427.143620] Lustre: DEBUG MARKER: == replay-dual test 24: reconstruct on non-existing object ========================================================== 10:45:59 (1786373159) [ 3427.806641] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 3427.809533] LustreError: 85057:0:(ldlm_lib.c:3346:target_send_reply_msg()) @@@ dropping reply req@ffff9a34097adc00 x1873144558244864/t154618822673(0) o36->0d0ff944-d11f-4d31-816d-8e65d8a5876f@192.168.202.51@tcp:206/0 lens 488/456 e 0 to 0 dl 1786373241 ref 1 fl Interpret:/200/0 rc 0/0 job:'truncate.0' uid:0 gid:0 projid:4294967295 [ 3512.305252] Lustre: lustre-MDT0000: Client 0d0ff944-d11f-4d31-816d-8e65d8a5876f (at 192.168.202.51@tcp) reconnecting [ 3512.323582] Lustre: 86134:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9a342fcf0e00 x1873144558244864/t154618822673(0) o36->0d0ff944-d11f-4d31-816d-8e65d8a5876f@192.168.202.51@tcp:291/0 lens 488/3152 e 0 to 0 dl 1786373326 ref 1 fl Interpret:/202/0 rc 0/0 job:'truncate.0' uid:0 gid:0 projid:4294967295 [ 3517.146745] Lustre: DEBUG MARKER: == replay-dual test 25: replay|resend ==================== 10:47:29 (1786373249) [ 3518.553863] Lustre: *** cfs_fail_loc=304, val=0*** [ 3520.346703] Lustre: Failing over lustre-OST0000 [ 3522.471849] Lustre: server umount lustre-OST0000 complete [ 3523.560695] Lustre: lustre-OST0000-osc-MDT0000: Connection to lustre-OST0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 3523.568176] Lustre: Skipped 64 previous similar messages [ 3537.582902] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3537.892722] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 4 clients reconnect [ 3537.901058] Lustre: Skipped 18 previous similar messages [ 3539.234237] Lustre: lustre-OST0000: Recovery over after 0:02, of 4 clients 4 recovered and 0 were evicted. [ 3539.240507] Lustre: Skipped 18 previous similar messages [ 3541.332753] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 3546.989296] Lustre: DEBUG MARKER: oleg251-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 3547.963829] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 3553.286272] Lustre: DEBUG MARKER: == replay-dual test 26: dbench and tar with mds failover ========================================================== 10:48:05 (1786373285) [ 3559.651642] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3562.602485] Lustre: DEBUG MARKER: test_26 fail mds1 1 times [ 3563.667850] Lustre: Failing over lustre-MDT0000 [ 3563.770459] Lustre: lustre-MDT0000: Not available for connect from 192.168.202.51@tcp (stopping) [ 3563.982365] Lustre: server umount lustre-MDT0000 complete [ 3581.129643] LDISKFS-fs (dm-0): 3 truncates cleaned up [ 3581.131825] LDISKFS-fs (dm-0): recovery complete [ 3581.145593] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3581.209265] LustreError: MGC192.168.202.151@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3581.215806] LustreError: Skipped 13 previous similar messages [ 3584.131254] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 3588.043687] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2184 to 0x280000401:2209) [ 3588.049910] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2182 to 0x2c0000401:2209) [ 3591.735822] Lustre: DEBUG MARKER: oleg251-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3593.181936] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3602.063452] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 3605.008868] Lustre: DEBUG MARKER: test_26 fail mds2 2 times [ 3606.072095] Lustre: Failing over lustre-MDT0001 [ 3606.290674] Lustre: server umount lustre-MDT0001 complete [ 3623.081790] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 3623.083485] LDISKFS-fs (dm-1): recovery complete [ 3623.092629] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3625.652424] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 3629.002927] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:272 to 0x2c0000400:289) [ 3629.003873] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:272 to 0x280000400:289) [ 3632.913946] Lustre: DEBUG MARKER: oleg251-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 3634.072091] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3643.075337] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3646.277550] Lustre: DEBUG MARKER: test_26 fail mds1 3 times [ 3647.634099] Lustre: Failing over lustre-MDT0000 [ 3647.662673] Lustre: lustre-MDT0000: Not available for connect from 192.168.202.51@tcp (stopping) [ 3647.673820] Lustre: Skipped 1 previous similar message [ 3647.839577] Lustre: server umount lustre-MDT0000 complete [ 3648.998840] LustreError: 93634: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. [ 3649.014939] LustreError: 93634:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 248 previous similar messages [ 3666.115771] LDISKFS-fs (dm-0): 3 truncates cleaned up [ 3666.121096] LDISKFS-fs (dm-0): recovery complete [ 3666.126460] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3674.817053] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 3674.820105] Lustre: Skipped 13 previous similar messages [ 3677.890206] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 3680.264844] Lustre: 94764:0:(ldlm_lib.c:2085:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3680.270973] Lustre: 94764:0:(ldlm_lib.c:2085:extend_recovery_timer()) Skipped 336 previous similar messages [ 3681.653398] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2290 to 0x2c0000401:2305) [ 3681.653435] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2290 to 0x280000401:2305) [ 3685.911667] Lustre: DEBUG MARKER: oleg251-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3686.951194] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3696.122739] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 3699.190578] Lustre: DEBUG MARKER: test_26 fail mds2 4 times [ 3700.523874] Lustre: Failing over lustre-MDT0001 [ 3705.995840] Lustre: server umount lustre-MDT0001 complete [ 3723.805251] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 3723.806774] LDISKFS-fs (dm-1): recovery complete [ 3723.812148] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3726.981300] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 3730.810147] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:396 to 0x280000400:417) [ 3730.811762] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:396 to 0x2c0000400:417) [ 3735.350541] Lustre: DEBUG MARKER: oleg251-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 3736.538236] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3745.281669] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3748.379378] Lustre: DEBUG MARKER: test_26 fail mds1 5 times [ 3749.611396] Lustre: Failing over lustre-MDT0000 [ 3749.846618] Lustre: server umount lustre-MDT0000 complete [ 3767.927839] LDISKFS-fs (dm-0): 3 truncates cleaned up [ 3767.929906] LDISKFS-fs (dm-0): recovery complete [ 3767.935678] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3770.768703] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 3774.498053] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2416 to 0x280000401:2433) [ 3774.500602] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2416 to 0x2c0000401:2433) [ 3778.439209] Lustre: DEBUG MARKER: oleg251-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3779.560810] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3831.450588] Lustre: DEBUG MARKER: == replay-dual test 28: lock replay should be ordered: waiting after granted ========================================================== 10:52:43 (1786373563) [ 3846.241921] Lustre: Failing over lustre-OST0000 [ 3846.351663] Lustre: server umount lustre-OST0000 complete [ 3863.065772] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3863.438459] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 3863.440411] Lustre: Skipped 11 previous similar messages [ 3865.022957] Lustre: *** cfs_fail_loc=32a, val=0*** [ 3865.078621] Lustre: lustre-OST0000-osc-MDT0001: Connection restored to 0@lo (at 0@lo) [ 3865.092950] Lustre: Skipped 41 previous similar messages [ 3871.306863] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 3882.476376] Lustre: DEBUG MARKER: oleg251-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 3884.549361] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 3896.988117] Lustre: DEBUG MARKER: == replay-dual test 29: replay vs update with the same xid ========================================================== 10:53:48 (1786373628) [ 3898.334736] Lustre: DEBUG MARKER: SKIP: replay-dual test_29 needs >= 2 clients [ 3901.163047] Lustre: DEBUG MARKER: == replay-dual test 30: layout lock replay is not blocked on IO ========================================================== 10:53:51 (1786373631) [ 3905.410454] Lustre: Failing over lustre-MDT0000 [ 3905.552392] Lustre: lustre-MDT0000: Not available for connect from 192.168.202.51@tcp (stopping) [ 3905.557963] Lustre: Skipped 11 previous similar messages [ 3906.229207] Lustre: server umount lustre-MDT0000 complete [ 3925.983144] Lustre: 3650:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786373643/real 1786373643] req@ffff9a3429b4dc00 x1873144578735360/t0(0) o400->MGC192.168.202.151@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1786373659 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3926.051145] Lustre: 3650:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 3929.618039] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3940.714729] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 3941.961236] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2451 to 0x2c0000401:2497) [ 3941.961986] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2453 to 0x280000401:2497) [ 3949.020348] Lustre: DEBUG MARKER: oleg251-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3950.142734] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3956.961686] Lustre: DEBUG MARKER: == replay-dual test 31: deadlock on file_remove_privs and occupied mod rpc slots ========================================================== 10:54:48 (1786373688) [ 3959.262774] Lustre: Failing over lustre-OST0000 [ 3959.349491] Lustre: server umount lustre-OST0000 complete [ 3975.463905] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3980.215857] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 3987.638404] Lustre: DEBUG MARKER: oleg251-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 3988.587440] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in IDLE [ 3995.683400] Lustre: DEBUG MARKER: == replay-dual test 32: gap in update llog shouldn't break recovery ========================================================== 10:55:27 (1786373727) [ 3996.605613] Lustre: *** cfs_fail_loc=131d, val=10*** [ 3997.169845] Lustre: *** cfs_fail_loc=131d, val=0*** [ 3997.172531] Lustre: Skipped 9 previous similar messages [ 3998.241512] Lustre: *** cfs_fail_loc=131d, val=4294967270*** [ 3998.243486] Lustre: Skipped 25 previous similar messages [ 3999.504847] Lustre: Failing over lustre-MDT0001 [ 3999.726177] Lustre: server umount lustre-MDT0001 complete [ 4002.395123] Lustre: Failing over lustre-MDT0000 [ 4002.799629] Lustre: server umount lustre-MDT0000 complete [ 4008.579986] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4008.848897] Lustre: *** cfs_fail_loc=131d, val=4294967266*** [ 4008.851879] Lustre: Skipped 3 previous similar messages [ 4012.393185] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 4018.202254] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4018.277810] Lustre: *** cfs_fail_loc=131d, val=4294967262*** [ 4018.280109] Lustre: Skipped 3 previous similar messages [ 4021.682733] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:496 to 0x2c0000400:513) [ 4021.683915] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:496 to 0x280000400:513) [ 4021.688861] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2537 to 0x280000401:2625) [ 4021.689728] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2451 to 0x2c0000401:2529) [ 4022.056209] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 4030.721987] Lustre: DEBUG MARKER: == replay-dual test 33: Check for OBD_INCOMPAT_MULTI_RPCS in last_rcvd after abort_recovery ========================================================== 10:56:02 (1786373762) [ 4036.089518] Lustre: Failing over lustre-MDT0001 [ 4036.252450] Lustre: server umount lustre-MDT0001 complete [ 4037.094526] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 4037.100288] LustreError: Skipped 8 previous similar messages [ 4053.522871] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4057.144282] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 4062.549120] Lustre: DEBUG MARKER: oleg251-client.virtnet: executing wait_import_state_mount REPLAY_WAIT mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 4063.792397] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in REPLAY_WAIT state after 0 sec [ 4064.459182] Lustre: lustre-MDT0001: Aborting client recovery [ 4064.464345] LustreError: 107615:0:(ldlm_lib.c:3004:target_stop_recovery_thread()) lustre-MDT0001: Aborting recovery [ 4064.475306] Lustre: 106982:0:(ldlm_lib.c:2404:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 4064.480362] Lustre: 106982:0:(ldlm_lib.c:2404:target_recovery_overseer()) Skipped 2 previous similar messages [ 4064.491936] Lustre: 106982:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0001: disconnect stale client b4f6b50d-b060-4560-a834-4c500c4c5fb3@ [ 4064.501734] Lustre: lustre-MDT0001: disconnecting 1 stale clients [ 4064.515544] Lustre: lustre-MDT0001-osd: cancel update llog [0x240000400:0x1:0x0] [ 4064.532780] Lustre: lustre-MDT0000-osp-MDT0001: cancel update llog [0x200000401:0x1:0x0] [ 4064.598622] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:496 to 0x280000400:545) [ 4064.606338] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:496 to 0x2c0000400:545) [ 4068.874782] Lustre: DEBUG MARKER: oleg251-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 4070.196350] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4073.643785] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0001.recovery_status 1475 [ 4080.239030] Lustre: Failing over lustre-MDT0001 [ 4080.424298] Lustre: server umount lustre-MDT0001 complete [ 4087.667829] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4091.898303] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing set_default_debug -1 all [ 4093.497495] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:496 to 0x280000400:577) [ 4093.504572] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:496 to 0x2c0000400:577) [ 4098.334438] Lustre: DEBUG MARKER: oleg251-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 4099.592264] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4102.440371] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0001.recovery_status 1475 [ 4108.511426] Lustre: DEBUG MARKER: == replay-dual test complete, duration 3787 sec ========== 10:57:20 (1786373840) [ 4109.755815] Lustre: DEBUG MARKER: === replay-dual: start cleanup 10:57:21 (1786373841) === [ 4118.507291] Lustre: DEBUG MARKER: === replay-dual: finish cleanup 10:57:29 (1786373849) === [ 4149.729635] 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 [ 4149.752680] Lustre: Skipped 39 previous similar messages [ 4153.170701] Lustre: server umount lustre-MDT0000 complete [ 4158.767969] LustreError: 6506:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1786373892 with bad export cookie 11374750365039833956 [ 4158.787923] LustreError: 6506:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 4159.065634] Lustre: server umount lustre-MDT0001 complete [ 4231.828700] Lustre: server umount lustre-OST0000 complete [ 4301.135801] Lustre: server umount lustre-OST0001 complete [ 4328.476465] Lustre: DEBUG MARKER: oleg251-server.virtnet: executing unload_modules_local [ 4331.631871] Key type lgssc unregistered [ 4331.977635] LNet: 112157:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 4331.980933] LNetError: 112157:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 4331.998777] LNet: Removed LNI 192.168.202.151@tcp [ 4333.344663] Key type .llcrypt unregistered [ 4333.348993] Key type ._llcrypt unregistered