[ 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 978485910 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, 524584K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] ftrace: allocating 41240 entries in 162 pages [ 0.000000] ftrace: allocated 162 pages with 3 groups [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] rcu: RCU event tracing is enabled. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ 0.000000] rcu: RCU callback double-/use-after-free debug enabled. [ 0.000000] Rude variant of Tasks RCU enabled. [ 0.000000] Tracing variant of Tasks RCU enabled. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 0.000000] NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16 [ 0.000000] random: get_random_bytes called from start_kernel+0x622/0x9a8 with crng_init=0 [ 0.001000] Console: colour *CGA 80x25 [ 0.001000] printk: console [ttyS1] enabled [ 0.001000] ACPI: Core revision 20220331 [ 0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.001010] APIC: Switch to symmetric I/O mode setup [ 0.002388] x2apic enabled [ 0.003010] Switched APIC routing to physical x2apic. [ 0.004017] kvm-guest: setup PV IPIs [ 0.008000] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.008011] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.009021] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.010012] pid_max: default: 32768 minimum: 301 [ 0.012128] LSM: Security Framework initializing [ 0.013060] Yama: becoming mindful. [ 0.014044] SELinux: Initializing. [ 0.015144] *** VALIDATE selinux *** [ 0.026000] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.033478] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.034137] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.035116] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.036121] *** VALIDATE tmpfs *** [ 0.037634] *** VALIDATE proc *** [ 0.040273] *** VALIDATE cgroup *** [ 0.041013] *** VALIDATE cgroup2 *** [ 0.043032] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.044292] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.046011] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.047034] Spectre V2 : User space: Vulnerable [ 0.048015] Speculative Store Bypass: Vulnerable [ 0.053347] debug: unmapping init [mem 0xffffffff85c59000-0xffffffff85c60fff] [ 0.056000] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.056927] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.057032] ... version: 2 [ 0.058015] ... bit width: 48 [ 0.059018] ... generic registers: 4 [ 0.060017] ... value mask: 0000ffffffffffff [ 0.061018] ... max period: 00007fffffffffff [ 0.062018] ... fixed-purpose events: 3 [ 0.063016] ... event mask: 000000070000000f [ 0.065060] rcu: Hierarchical SRCU implementation. [ 0.068738] smp: Bringing up secondary CPUs ... [ 0.070932] x86: Booting SMP configuration: [ 0.071035] .... node #0, CPUs: #1 #2 #3 [ 0.088173] smp: Brought up 1 node, 4 CPUs [ 0.090015] smpboot: Max logical packages: 1 [ 0.091070] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.156715] node 0 deferred pages initialised in 62ms [ 0.165083] devtmpfs: initialized [ 0.171274] x86/mm: Memory block size: 128MB [ 0.184113] gcov: version magic: 0x41383552 [ 0.192000] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.206088] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.214125] pinctrl core: initialized pinctrl subsystem [ 0.224115] [ 0.227011] ************************************************************* [ 0.238012] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.247014] ** ** [ 0.256012] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.264013] ** ** [ 0.272021] ** This means that this kernel is built to expose internal ** [ 0.280014] ** IOMMU data structures, which may compromise security on ** [ 0.287017] ** your system. ** [ 0.295019] ** ** [ 0.301013] ** If you see this message and you are not debugging the ** [ 0.309015] ** kernel, report this immediately to your vendor! ** [ 0.316013] ** ** [ 0.322014] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.330007] ************************************************************* [ 0.339000] NET: Registered protocol family 16 [ 0.344494] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.351072] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.360319] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.369227] cpuidle: using governor menu [ 0.375826] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.386420] PCI: Using configuration type 1 for base access [ 0.390042] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.415067] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.421021] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.427037] cryptd: max_cpu_qlen set to 1000 [ 0.432400] ACPI: Added _OSI(Module Device) [ 0.434029] ACPI: Added _OSI(Processor Device) [ 0.437019] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.443015] ACPI: Added _OSI(Processor Aggregator Device) [ 0.459095] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.476122] ACPI: Interpreter enabled [ 0.478587] ACPI: PM: (supports S0 S3 S4 S5) [ 0.482016] ACPI: Using IOAPIC for interrupt routing [ 0.484262] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.491984] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.516000] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.518623] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.524021] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.530068] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.544723] acpiphp: Slot [2] registered [ 0.549282] acpiphp: Slot [5] registered [ 0.552217] acpiphp: Slot [6] registered [ 0.556150] acpiphp: Slot [7] registered [ 0.560733] acpiphp: Slot [8] registered [ 0.565094] acpiphp: Slot [9] registered [ 0.571155] acpiphp: Slot [10] registered [ 0.577092] acpiphp: Slot [3] registered [ 0.583144] acpiphp: Slot [4] registered [ 0.591141] acpiphp: Slot [11] registered [ 0.594130] acpiphp: Slot [12] registered [ 0.600259] acpiphp: Slot [13] registered [ 0.604130] acpiphp: Slot [14] registered [ 0.607115] acpiphp: Slot [15] registered [ 0.610131] acpiphp: Slot [16] registered [ 0.615136] acpiphp: Slot [17] registered [ 0.619902] acpiphp: Slot [18] registered [ 0.622116] acpiphp: Slot [19] registered [ 0.626123] acpiphp: Slot [20] registered [ 0.630133] acpiphp: Slot [21] registered [ 0.634154] acpiphp: Slot [22] registered [ 0.638121] acpiphp: Slot [23] registered [ 0.642130] acpiphp: Slot [24] registered [ 0.647000] acpiphp: Slot [25] registered [ 0.649115] acpiphp: Slot [26] registered [ 0.654088] acpiphp: Slot [27] registered [ 0.655108] acpiphp: Slot [28] registered [ 0.659150] acpiphp: Slot [29] registered [ 0.663136] acpiphp: Slot [30] registered [ 0.666114] acpiphp: Slot [31] registered [ 0.669066] PCI host bridge to bus 0000:00 [ 0.673040] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.680022] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.686021] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.694022] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.701032] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.709957] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.717063] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.723533] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.734038] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.765024] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.782074] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.791020] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.799019] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.805030] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.814161] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.820866] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.828048] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.834094] pci 0000:00:01.3: quirk_piix4_acpi+0x0/0x1e0 took 12695 usecs [ 0.841710] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.850013] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.885015] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.893913] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.901440] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.913018] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.925026] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.956026] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.983069] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 1.005023] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 1.021020] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 1.072016] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 1.100079] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 1.116027] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 1.130016] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 1.168016] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 1.201951] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 1.224028] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 1.236000] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 1.277000] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 1.301072] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 1.327021] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 1.341000] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 1.382017] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 1.399000] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 1.407015] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 1.419014] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 1.455014] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 1.476745] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 1.479384] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 1.482937] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 1.487140] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 1.490404] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 1.496081] iommu: Default domain type: Passthrough [ 1.497108] SCSI subsystem initialized [ 1.498473] ACPI: bus type USB registered [ 1.502136] usbcore: registered new interface driver usbfs [ 1.508084] usbcore: registered new interface driver hub [ 1.512905] usbcore: registered new device driver usb [ 1.516052] pps_core: LinuxPPS API ver. 1 registered [ 1.518012] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 1.523052] PTP clock support registered [ 1.528062] EDAC MC: Ver: 3.0.0 [ 1.529000] PCI: Using ACPI for IRQ routing [ 1.533333] NetLabel: Initializing [ 1.535013] NetLabel: domain hash size = 128 [ 1.538011] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 1.542074] NetLabel: unlabeled traffic allowed by default [ 1.545088] vgaarb: loaded [ 1.548106] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 1.552013] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 1.564206] clocksource: Switched to clocksource kvm-clock [ 2.032474] VFS: Disk quotas dquot_6.6.0 [ 2.037877] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 2.043715] *** VALIDATE ramfs *** [ 2.046598] *** VALIDATE hugetlbfs *** [ 2.052306] pnp: PnP ACPI init [ 2.058479] pnp: PnP ACPI: found 6 devices [ 2.099645] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 2.114620] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 2.120989] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 2.130134] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 2.142181] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 2.154519] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 2.166968] NET: Registered protocol family 2 [ 2.177647] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 2.198270] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 2.217162] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 2.241569] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 2.263539] TCP: Hash tables configured (established 65536 bind 65536) [ 2.278189] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 2.285745] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 2.291824] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 2.297217] NET: Registered protocol family 1 [ 2.302487] RPC: Registered named UNIX socket transport module. [ 2.306581] RPC: Registered udp transport module. [ 2.308806] RPC: Registered tcp transport module. [ 2.311086] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 2.314791] NET: Registered protocol family 44 [ 2.317117] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 2.323127] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 2.327711] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 2.334202] PCI: CLS 0 bytes, default 64 [ 2.339569] Unpacking initramfs... [ 4.032125] hrtimer: interrupt took 2165104 ns [ 7.911370] debug: unmapping init [mem 0xffff99c33cc54000-0xffff99c33ffbffff] [ 7.933341] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 7.940474] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 7.955217] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 9.849368] Initialise system trusted keyrings [ 9.854060] Key type blacklist registered [ 9.858338] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 9.882336] zbud: loaded [ 9.889565] *** VALIDATE nfs *** [ 9.892249] *** VALIDATE nfs4 *** [ 9.895992] pstore: using deflate compression [ 9.904239] Platform Keyring initialized [ 10.587740] NET: Registered protocol family 38 [ 10.591754] Key type asymmetric registered [ 10.595772] Asymmetric key parser 'x509' registered [ 10.601600] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 10.621221] io scheduler mq-deadline registered [ 10.625995] io scheduler kyber registered [ 10.628913] io scheduler bfq registered [ 10.641009] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 10.643798] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 10.662770] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 10.673217] ACPI: Power Button [PWRF] [ 10.703288] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 10.724648] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 10.769327] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 10.803632] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 10.874434] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 10.969171] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 11.039105] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 11.068543] Non-volatile memory driver v1.3 [ 11.073330] Linux agpgart interface v0.103 [ 11.226550] virtio_blk virtio1: [vda] 146712 512-byte logical blocks (75.1 MB/71.6 MiB) [ 11.232308] vda: detected capacity change from 0 to 75116544 [ 11.295766] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 11.300161] vdb: detected capacity change from 0 to 1073741824 [ 11.405548] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 11.418078] vdc: detected capacity change from 0 to 2621440000 [ 11.530206] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 11.554074] vdd: detected capacity change from 0 to 2621440000 [ 11.651159] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 11.667021] vde: detected capacity change from 0 to 4294967296 [ 11.718418] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 11.727352] vdf: detected capacity change from 0 to 4294967296 [ 11.758581] libphy: Fixed MDIO Bus: probed [ 11.810413] usbcore: registered new interface driver usbserial_generic [ 11.812868] usbserial: USB Serial support registered for generic [ 11.831887] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 11.867204] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 11.874019] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 11.887033] mousedev: PS/2 mouse device common for all mice [ 11.906419] rtc_cmos 00:05: RTC can wake from S4 [ 11.922138] rtc_cmos 00:05: registered as rtc0 [ 11.925238] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 11.950960] intel_pstate: CPU model not supported [ 11.953825] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 11.968803] hid: raw HID events driver (C) Jiri Kosina [ 11.980171] usbcore: registered new interface driver usbhid [ 11.995052] usbhid: USB HID core driver [ 12.006158] drop_monitor: Initializing network drop monitor service [ 12.008204] Initializing XFRM netlink socket [ 12.025995] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 12.026944] NET: Registered protocol family 10 [ 12.059224] Segment Routing with IPv6 [ 12.060465] NET: Registered protocol family 17 [ 12.064240] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 12.078378] mpls_gso: MPLS GSO support [ 12.120598] RAS: Correctable Errors collector initialized. [ 12.135542] AVX version of gcm_enc/dec engaged. [ 12.137369] AES CTR mode by8 optimization enabled [ 12.468314] sched_clock: Marking stable (12468288984, 0)->(14833325195, -2365036211) [ 12.492762] registered taskstats version 1 [ 12.514988] Loading compiled-in X.509 certificates [ 12.516808] zswap: loaded using pool lzo/zbud [ 12.704733] Key type big_key registered [ 12.756068] Key type encrypted registered [ 12.767887] ima: No TPM chip found, activating TPM-bypass! [ 12.776969] ima: Allocated hash algorithm: sha1 [ 12.784788] ima: No architecture policies found [ 12.792091] evm: Initialising EVM extended attributes: [ 12.794957] evm: security.selinux [ 12.796077] evm: security.ima [ 12.805767] evm: security.capability [ 12.809758] evm: HMAC attrs: 0x1 [ 12.819637] rtc_cmos 00:05: setting system clock to 2026-09-19 00:23:33 UTC (1789777413) [ 12.862545] debug: unmapping init [mem 0xffffffff86c03000-0xffffffff86dfffff] [ 12.888857] debug: unmapping init [mem 0xffffffff85982000-0xffffffff85c58fff] [ 12.917142] Write protecting the kernel read-only data: 28672k [ 12.951248] debug: unmapping init [mem 0xffffffff84003000-0xffffffff841fffff] [ 12.973061] debug: unmapping init [mem 0xffffffff84914000-0xffffffff849fffff] [ 13.276734] 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) [ 13.325607] systemd[1]: Detected virtualization kvm. [ 13.327033] systemd[1]: Detected architecture x86-64. [ 13.336101] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 13.474961] systemd[1]: No hostname configured. [ 13.483969] systemd[1]: Set hostname to . [ 13.490296] random: systemd: uninitialized urandom read (16 bytes read) [ 13.502376] systemd[1]: Initializing machine ID from random generator. [ 13.779537] random: ln: uninitialized urandom read (6 bytes read) [ 14.291197] random: systemd: uninitialized urandom read (16 bytes read) [ 14.303111] systemd[1]: Reached target Slices. [ OK ] Reached target Slices. [ 14.324732] systemd[1]: Listening on Journal Socket (/dev/log). [ OK ] Listening on Journal Socket (/dev/log). [ 14.339424] systemd[1]: Listening on udev Control Socket. [ OK ] Listening on udev Control Socket. [ OK ] Listening on udev Kernel Socket. [ OK ] Listening on Journal Socket. Starting Journal Service... [ 14.532551] urandom_read: 5 callbacks suppressed [ 14.532560] random: systemd: uninitialized urandom read (16 bytes read) Starting Setup Virtual Console... [ 14.642170] random: systemd: uninitialized urandom read (16 bytes read) [ OK ] Reached target Local File Systems. [ OK ] Reached target Timers. Starting Create Volatile Files and Directories... [ OK ] Reached target Sockets. Starting Apply Kernel Variables... [ OK ] Started Memstrack Anylazing Service. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Reached target Initrd Root Device. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Paths. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Swap. [ OK ] Started Setup Virtual Console. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Apply Kernel Variables. [ OK ] Started Create list of required sta…vice nodes for the current kernel. Starting Create Static Device Nodes in /dev... Starting dracut cmdline hook... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started Journal Service. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 17.351259] device-mapper: uevent: version 1.0.3 [ 17.357653] 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... [ 20.941407] virtio_net virtio0 ens2: renamed from eth0 [ 21.052562] random: fast init done [ 21.859165] scsi host0: ata_piix [ 22.193976] scsi host1: ata_piix [ 22.200291] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 22.218374] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 27.332292] random: crng init done [ 30.429684] dracut-initqueue[588]: RTNETLINK answers: File exists Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Mounting /sysroot... [ 32.262324] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped target Timers. [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target 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. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Sockets. [ OK ] Stopped target Slices. [ OK ] Stopped target Paths. [ OK ] Stopped target System Initialization. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. [ OK ] Stopped target Swap. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. Stopping udev Kernel Device Manager... [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Closed udev Kernel Socket. [ OK ] Closed udev Control Socket. Starting Cleanup udevd DB... [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 35.108940] printk: systemd: 26 output lines suppressed due to ratelimiting [ 36.522893] SELinux: Disabled at runtime. [ 36.823611] 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.894645] systemd[1]: Detected virtualization kvm. [ 36.916334] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 39.051591] systemd[1]: initrd-switch-root.service: Succeeded. [ 39.058656] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 39.073371] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 39.083896] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 39.092281] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 39.110221] systemd[1]: Starting Journal Service... Starting Journal Service... [ 39.124626] systemd[1]: Reached target rpc_pipefs.target. [ OK ] Reached target rpc_pipefs.target. Mounting POSIX Message Queue File System... Starting Create list of required st…ce nodes for the current kernel... [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Listening on Process Core Dump Socket. [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Reached target RPC Port Mapper. [ OK ] Listening on udev Control Socket. [ OK ] Started Dispatch Password Requests to Console Directory Watch. Starting Apply Kernel Variables... [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd File Systems. [ OK ] Stopped target Initrd Root File System. Starting Remount Root and Kernel File Systems... [ OK ] Created slice User and Session Slice. [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Created slice system-getty.slice. [ OK ] Listening on udev Kernel Socket. Starting udev Coldplug all Devices... [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Reached target Paths. [ OK ] Reached target Local Encrypted Volumes. Activating swap /dev/disk/by-label/SWAP... [ OK ] Reached target Slices. [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. Mounting Kernel Debug File System... [ 40.045958] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS Mounting Huge Pages File System... [ OK ] Started Journal Service. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Apply Kernel Variables. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Mounted Kernel Debug File System. [ OK ] Mounted Huge Pages File System. [ OK ] Reached target Swap. Starting Configure read-only root support... Starting Create Static Device Nodes in /dev... Starting Flush Journal to Persistent Storage... [ OK ] Started udev Coldplug all Devices. [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Reached target Local File Systems (Pre). Mounting /home/green/git/lustre-release... Mounting /mnt... Starting udev Kernel Device Manager... [ OK ] Mounted /mnt. [ 41.076796] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 43.282095] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 43.361138] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 45.288521] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 45.522064] 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) [ **] A start job is running for Configur…only root support (11s / no limit) [ *] A start job is running for Configur…only root support (12s / no limit) [ **] 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) [ *** ] A start job is running for Configur…only root support (13s / no limit) [ *** ] A start job is running for Configur…only root support (14s / no limit) [*** ] A start job is running for Configur…only root support (14s / no limit) [** ] A start job is running for Configur…only root support (15s / no limit) [* ] A start job is running for Configur…only root support (16s / no limit) [** ] A start job is running for Configur…only root support (16s / no limit)[ 55.727287] Key type dns_resolver registered [*** ] A start job is running for Configur…only root support (17s / no limit) [ *** ] A start job is running for Configur…only root support (17s / no limit) [ *** ] A start job is running for Configur…only root support (18s / no limit) [ ***] A start job is running for Configur…only root support (18s / no limit)[ 57.712500] NFS: Registering the id_resolver key type [ 57.725298] Key type id_resolver registered [ 57.730217] Key type id_legacy registered [ **] A start job is running for Configur…only root support (19s / no limit) [ *] A start job is running for Configur…only root support (19s / no limit) [ OK ] Started Configure read-only root support. [ OK ] Reached target Local File Systems. Starting Mark the need to relabel after reboot... Starting Rebuild Dynamic Linker Cache... Starting Create Volatile Files and Directories... Starting Load/Save Random Seed... [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Load/Save Random Seed. [ OK ] Started Create Volatile Files and Directories. Starting RPC Bind... Starting Update UTMP about System Boot/Shutdown... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Started dnf makecache --timer. [ OK ] Reached target Timers. [ OK ] Reached target Basic System. [ OK ] Started D-Bus System Message Bus. Starting Restore /run/initramfs on shutdown... [ OK ] Started irqbalance daemon. Starting Network Manager... Starting Login Service... [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Reached target sshd-keygen.target. [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Network Manager. Starting Network Manager Wait Online... [ OK ] Reached target Network. Starting GSSAPI Proxy Daemon... Starting OpenSSH server daemon... Starting Dynamic System Tuning Daemon... [ OK ] Started Login Service. Starting Hostname Service... [ OK ] Started OpenSSH server daemon. [ 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 Permit User Sessions. [ OK ] Started Getty on tty1. [ OK ] Started Serial Getty on ttyS1. [ OK ] Started Serial Getty on ttyS0. [ OK ] Reached target Login Prompts. [ OK ] Started Command Scheduler. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting Crash recovery kernel arming... Starting Notify NFS peers of a restart... Starting System Logging Service... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg615-server login: [ 115.547417] libcfs: loading out-of-tree module taints kernel. [ 115.579839] Key type ._llcrypt registered [ 115.582166] Key type .llcrypt registered [ 115.700368] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_hostid [ 131.875852] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing load_modules_local [ 133.365774] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 133.386950] alg: No test for adler32 (adler32-zlib) [ 134.935518] Lustre: Lustre: Build Version: 2.17.57_111_g8cb7ca1 [ 135.764954] LNet: Added LNI 192.168.206.115@tcp [8/256/0/180] [ 137.567878] Key type lgssc registered [ 139.066562] Lustre: Echo OBD driver; http://www.lustre.org/ [ 155.873034] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 191.210591] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing load_modules_local [ 201.943872] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 201.984069] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 203.257567] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 203.279441] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 203.376092] Lustre: lustre-MDT0000: new disk, initializing [ 203.437269] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 203.453996] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 207.596262] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 218.115177] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 218.223406] Lustre: 6513: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 [ 218.248873] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 218.252699] Lustre: Skipped 1 previous similar message [ 218.329530] Lustre: lustre-MDT0001: new disk, initializing [ 218.408214] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 218.465082] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 218.497058] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 222.211954] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 226.562474] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 234.504694] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 234.698798] Lustre: lustre-OST0000: new disk, initializing [ 234.703827] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 234.709722] Lustre: 8451:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 234.777119] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 240.253302] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 240.273691] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 240.407910] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 241.647693] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 259.784906] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 259.998711] Lustre: lustre-OST0001: new disk, initializing [ 260.004252] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 260.011985] Lustre: 9523:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 260.121619] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 267.729395] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 268.334049] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 268.343254] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 268.433096] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 280.612967] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 286.812688] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 293.422676] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing check_logdir /tmp/testlogs/ [ 298.713477] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing yml_node [ 303.209674] Lustre: DEBUG MARKER: Client: 2.17.57.111 [ 305.506840] Lustre: DEBUG MARKER: MDS: 2.17.57.111 [ 307.992822] Lustre: DEBUG MARKER: OSS: 2.17.57.111 [ 309.653572] Lustre: DEBUG MARKER: -----============= acceptance-small: replay-dual ============----- Fri Sep 18 20:28:27 EDT 2026 [ 325.845558] Lustre: DEBUG MARKER: excepting tests: 14b 21b [ 327.270975] Lustre: DEBUG MARKER: skipping tests SLOW=no: 21b [ 328.754469] Lustre: DEBUG MARKER: === replay-dual: start setup 20:28:46 (1789777726) === [ 334.865271] Lustre: DEBUG MARKER: oleg615-client.virtnet: executing check_config_client /mnt/lustre [ 353.933584] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 357.676258] Lustre: 13382:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 361.412458] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug -1 all [ 366.036943] Lustre: DEBUG MARKER: === replay-dual: finish setup 20:29:24 (1789777764) === [ 367.894105] Lustre: DEBUG MARKER: == replay-dual test 0a: expired recovery with lost client ========================================================== 20:29:25 (1789777765) [ 375.140484] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 378.954641] Lustre: Failing over lustre-MDT0000 [ 379.315421] Lustre: server umount lustre-MDT0000 complete [ 380.900308] 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 [ 380.940892] Lustre: Skipped 3 previous similar messages [ 385.823376] LustreError: 14187:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.206.15@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 385.844894] LustreError: 14187:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 8 previous similar messages [ 390.921152] LustreError: 6519:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.206.15@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 390.939835] LustreError: 6519:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 4 previous similar messages [ 396.050348] LustreError: 6521:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.206.15@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 396.067198] LustreError: 6521:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 6 previous similar messages [ 397.279570] Lustre: 3650:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789777781/real 1789777781] req@ffff99c283be0000 x1876717769706240/t0(0) o400->MGC192.168.206.115@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789777797 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 397.321527] LustreError: MGC192.168.206.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 401.161852] LustreError: 9752:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.206.15@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 401.196166] LustreError: 9752:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 11 previous similar messages [ 401.999154] LDISKFS-fs (dm-0): 10 truncates cleaned up [ 402.004705] LDISKFS-fs (dm-0): recovery complete [ 402.028201] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 407.310212] LustreError: 14187:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.206.15@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 407.342908] LustreError: 14187:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 7 previous similar messages [ 407.876519] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 409.254033] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 412.438832] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug -1 all [ 413.175282] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 515.500196] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 515.502884] Lustre: 14926:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 6d22f995-a58d-4929-bad6-83c8dad0e345@192.168.206.15@tcp [ 515.520765] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 515.540521] Lustre: 14926:0:(ldlm_lib.c:2976:target_recovery_thread()) too long recovery - read logs [ 515.547656] Lustre: lustre-MDT0000-osp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 515.572192] Lustre: Skipped 2 previous similar messages [ 515.573972] LustreError: dumping log to /tmp/lustre-log.1789777916.14926 [ 515.784938] Lustre: lustre-MDT0000: Recovery over after 1:46, of 3 clients 2 recovered and 1 was evicted. [ 515.840524] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:28 to 0x2c0000401:65) [ 515.840650] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:28 to 0x280000401:65) [ 538.010738] Lustre: DEBUG MARKER: == replay-dual test 0b: lost client during waiting for next transno ========================================================== 20:32:16 (1789777936) [ 546.396394] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 548.389840] Lustre: Failing over lustre-MDT0000 [ 548.695551] Lustre: server umount lustre-MDT0000 complete [ 549.178859] LustreError: 6521:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.206.15@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 549.205730] LustreError: 6521:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 4 previous similar messages [ 551.392856] 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 [ 551.427608] Lustre: Skipped 3 previous similar messages [ 565.526530] LustreError: 6519:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.206.15@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 565.550019] LustreError: 6519:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 15 previous similar messages [ 567.776373] Lustre: 3649:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789777952/real 1789777952] req@ffff99c3b73a1f80 x1876717769787392/t0(0) o400->MGC192.168.206.115@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789777968 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 567.809550] LustreError: MGC192.168.206.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 570.612313] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 570.615487] LDISKFS-fs (dm-0): recovery complete [ 570.623441] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 578.029720] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x3397d59de413f560 [ 578.045494] Lustre: MGC192.168.206.115@tcp: Connection restored to 0@lo (at 0@lo) [ 578.313741] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 579.389647] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 582.568478] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug -1 all [ 583.682790] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 595.295675] Lustre: lustre-MDT0000: Denying connection for new client 8f0f7804-f3fd-45d1-b59c-eb1f56a8f568 (at 192.168.206.15@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:54 [ 600.334103] Lustre: lustre-MDT0000: Denying connection for new client 8f0f7804-f3fd-45d1-b59c-eb1f56a8f568 (at 192.168.206.15@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:49 [ 605.450324] Lustre: lustre-MDT0000: Denying connection for new client 8f0f7804-f3fd-45d1-b59c-eb1f56a8f568 (at 192.168.206.15@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:44 [ 610.570494] Lustre: lustre-MDT0000: Denying connection for new client 8f0f7804-f3fd-45d1-b59c-eb1f56a8f568 (at 192.168.206.15@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:38 [ 614.373035] Lustre: lustre-MDT0001: haven't heard from client 6d22f995-a58d-4929-bad6-83c8dad0e345 (at 192.168.206.15@tcp) in 103 seconds. I think it's dead, and I am evicting it. exp ffff99c2832d2800, cur 1789778015 deadline 1789778012 last 1789777912 [ 615.688249] Lustre: lustre-MDT0000: Denying connection for new client 8f0f7804-f3fd-45d1-b59c-eb1f56a8f568 (at 192.168.206.15@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:33 [ 625.937459] Lustre: lustre-MDT0000: Denying connection for new client 8f0f7804-f3fd-45d1-b59c-eb1f56a8f568 (at 192.168.206.15@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:23 [ 625.951197] Lustre: Skipped 1 previous similar message [ 646.418546] Lustre: lustre-MDT0000: Denying connection for new client 8f0f7804-f3fd-45d1-b59c-eb1f56a8f568 (at 192.168.206.15@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:03 [ 646.446289] Lustre: Skipped 3 previous similar messages [ 649.502820] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 649.515936] Lustre: 16667:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 533b2f5e-9152-4498-8435-6483a560a75e@ [ 649.545355] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 682.264052] Lustre: lustre-MDT0000: Denying connection for new client 8f0f7804-f3fd-45d1-b59c-eb1f56a8f568 (at 192.168.206.15@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 1 evicted) to recover in 1:08 [ 682.286447] Lustre: Skipped 6 previous similar messages [ 686.060317] Lustre: lustre-MDT0001: haven't heard from client 59730150-2e27-480b-b554-5075c97de4df (at 192.168.206.15@tcp) in 102 seconds. I think it's dead, and I am evicting it. exp ffff99c3bfa65000, cur 1789778086 deadline 1789778084 last 1789777984 [ 748.812200] Lustre: lustre-MDT0000: Denying connection for new client 8f0f7804-f3fd-45d1-b59c-eb1f56a8f568 (at 192.168.206.15@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 1 evicted) to recover in 0:01 [ 748.827320] Lustre: Skipped 12 previous similar messages [ 750.500140] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 750.507194] Lustre: 16667:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 59730150-2e27-480b-b554-5075c97de4df@192.168.206.15@tcp [ 750.526409] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 750.534889] Lustre: 16667:0:(ldlm_lib.c:2110:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 750.563927] Lustre: 16667:0:(ldlm_lib.c:2976:target_recovery_thread()) too long recovery - read logs [ 750.569677] Lustre: lustre-MDT0000-osp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 750.576720] LustreError: dumping log to /tmp/lustre-log.1789778151.16667 [ 750.598964] Lustre: Skipped 2 previous similar messages [ 750.784211] Lustre: lustre-MDT0000: Recovery over after 2:51, of 3 clients 1 recovered and 2 were evicted. [ 750.828870] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:28 to 0x2c0000401:97) [ 750.830397] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:28 to 0x280000401:97) [ 763.965723] Lustre: DEBUG MARKER: == replay-dual test 1: |X| simple create ================= 20:36:01 (1789778161) [ 772.687873] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 774.607160] Lustre: Failing over lustre-MDT0000 [ 774.983275] Lustre: server umount lustre-MDT0000 complete [ 775.503954] LustreError: 9752:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.206.15@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 775.530390] LustreError: 9752:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 19 previous similar messages [ 776.175293] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 776.202458] 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 [ 778.229687] 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 [ 778.248443] Lustre: Skipped 1 previous similar message [ 793.567730] Lustre: 3650:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789778178/real 1789778178] req@ffff99c284243b80 x1876717769886976/t0(0) o400->MGC192.168.206.115@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789778194 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 793.598613] LustreError: MGC192.168.206.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 797.889617] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 797.894023] LDISKFS-fs (dm-0): recovery complete [ 797.904778] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 804.126725] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 804.208295] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 804.707493] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 809.103494] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug -1 all [ 809.481145] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 809.636220] Lustre: lustre-MDT0000: Recovery over after 0:05, of 3 clients 3 recovered and 0 were evicted. [ 809.705936] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:129) [ 809.708431] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:129) [ 819.215245] Lustre: DEBUG MARKER: oleg615-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 820.712263] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 829.912044] Lustre: DEBUG MARKER: == replay-dual test 2: |X| mkdir adir ==================== 20:37:07 (1789778227) [ 836.964510] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 838.717767] Lustre: Failing over lustre-MDT0000 [ 839.021568] Lustre: server umount lustre-MDT0000 complete [ 839.973898] LustreError: 14187:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.206.15@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 839.990786] LustreError: 14187:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 36 previous similar messages [ 840.169869] 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 [ 840.182259] Lustre: Skipped 3 previous similar messages [ 855.505717] Lustre: 3648:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789778240/real 1789778240] req@ffff99c3bfbd2a00 x1876717769922432/t0(0) o400->MGC192.168.206.115@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789778256 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 855.538252] LustreError: MGC192.168.206.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 861.204309] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 861.207201] LDISKFS-fs (dm-0): recovery complete [ 861.222932] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 865.761141] LustreError: 3646:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff99c3892c0380 x1876717769929600/t0(0) o250->MGC192.168.206.115@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 [ 866.154101] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 866.216708] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 867.388937] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 870.871272] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug -1 all [ 871.426386] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 871.438311] Lustre: Skipped 3 previous similar messages [ 871.518712] Lustre: lustre-MDT0000: Recovery over after 0:04, of 3 clients 3 recovered and 0 were evicted. [ 871.569880] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:161) [ 871.571071] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:161) [ 880.434176] Lustre: DEBUG MARKER: oleg615-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 882.099093] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 891.184692] Lustre: DEBUG MARKER: == replay-dual test 3: |X| mkdir adir, mkdir adir/bdir === 20:38:09 (1789778289) [ 898.560755] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 900.737546] Lustre: Failing over lustre-MDT0000 [ 901.103529] Lustre: server umount lustre-MDT0000 complete [ 902.114858] 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 [ 902.141266] Lustre: Skipped 2 previous similar messages [ 917.952110] Lustre: 3647:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789778302/real 1789778302] req@ffff99c385f74000 x1876717769963392/t0(0) o400->MGC192.168.206.115@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789778318 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 917.990750] LustreError: MGC192.168.206.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 923.516542] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 923.518913] LDISKFS-fs (dm-0): recovery complete [ 923.528275] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 928.736201] LustreError: 22261:0:(import.c:339:ptlrpc_invalidate_import()) MGS: timeout waiting for callback (1 != 0) [ 928.740355] LustreError: 22261:0:(import.c:363:ptlrpc_invalidate_import()) @@@ still on sending list req@ffff99c3adb7d180 x1876717769969280/t0(0) o250->MGC192.168.206.115@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 1789778328 ref 1 fl Rpc:NQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 928.763383] LustreError: 22261:0:(import.c:373:ptlrpc_invalidate_import()) MGS: Unregistering RPCs found (0). Network is sluggish? Waiting for them to error out. [ 929.292599] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x3397d59de41407d5 [ 929.310236] Lustre: MGC192.168.206.115@tcp: Connection restored to 0@lo (at 0@lo) [ 929.318905] Lustre: Skipped 3 previous similar messages [ 929.680844] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 930.363134] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 934.282289] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug -1 all [ 935.069473] Lustre: lustre-MDT0000: Recovery over after 0:05, of 3 clients 3 recovered and 0 were evicted. [ 935.111783] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:193) [ 935.111863] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:193) [ 944.163654] Lustre: DEBUG MARKER: oleg615-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 945.937171] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 953.512739] Lustre: DEBUG MARKER: == replay-dual test 4: |X| mkdir adir (-EEXIST), mkdir adir/bdir ========================================================== 20:39:11 (1789778351) [ 960.252369] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 962.073588] Lustre: Failing over lustre-MDT0000 [ 962.491160] Lustre: server umount lustre-MDT0000 complete [ 965.609507] 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 [ 965.630980] Lustre: Skipped 1 previous similar message [ 970.724360] LustreError: 6524:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 970.751356] LustreError: 6524:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 91 previous similar messages [ 981.990829] Lustre: 3649:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789778366/real 1789778366] req@ffff99c39f586300 x1876717770007424/t0(0) o400->MGC192.168.206.115@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789778382 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 982.014683] LustreError: MGC192.168.206.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 983.950925] LDISKFS-fs (dm-0): 4 truncates cleaned up [ 983.952934] LDISKFS-fs (dm-0): recovery complete [ 983.964591] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 992.226360] LustreError: 3646:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff99c2833b3800 x1876717770015488/t0(0) o250->MGC192.168.206.115@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 [ 992.592533] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 992.600701] Lustre: Skipped 1 previous similar message [ 992.677294] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 992.864701] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 997.042524] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug -1 all [ 997.870921] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 997.881738] Lustre: Skipped 4 previous similar messages [ 998.009442] Lustre: lustre-MDT0000: Recovery over after 0:06, of 3 clients 3 recovered and 0 were evicted. [ 998.055544] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:225) [ 998.060670] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:225) [ 1005.954952] Lustre: DEBUG MARKER: oleg615-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1007.746626] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1016.033382] Lustre: DEBUG MARKER: == replay-dual test 5: open, unlink |X| close ============ 20:40:14 (1789778414) [ 1023.991829] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1026.011500] Lustre: Failing over lustre-MDT0000 [ 1026.378816] Lustre: server umount lustre-MDT0000 complete [ 1028.580246] 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 [ 1028.607970] Lustre: Skipped 3 previous similar messages [ 1044.959298] Lustre: 3647:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789778429/real 1789778429] req@ffff99c3add74380 x1876717770045952/t0(0) o400->MGC192.168.206.115@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789778445 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1045.002841] LustreError: MGC192.168.206.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1049.029584] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1049.031801] LDISKFS-fs (dm-0): recovery complete [ 1049.047837] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1055.210682] LustreError: 3646:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff99c3b5df1f80 x1876717770055680/t0(0) o250->MGC192.168.206.115@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 [ 1055.567258] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1056.367951] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 1060.433593] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug -1 all [ 1061.041326] Lustre: lustre-MDT0000: Recovery over after 0:05, of 3 clients 3 recovered and 0 were evicted. [ 1061.116113] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:257) [ 1061.116569] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:257) [ 1070.568575] Lustre: DEBUG MARKER: oleg615-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1072.185282] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1081.029837] Lustre: DEBUG MARKER: == replay-dual test 6: open1, open2, unlink |X| close1 [fail mds1] close2 ========================================================== 20:41:19 (1789778479) [ 1088.940569] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1090.795417] Lustre: Failing over lustre-MDT0000 [ 1091.134161] Lustre: server umount lustre-MDT0000 complete [ 1107.935791] Lustre: 3647:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789778492/real 1789778492] req@ffff99c3c1217480 x1876717770083968/t0(0) o400->MGC192.168.206.115@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789778508 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1107.960869] LustreError: MGC192.168.206.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1112.920786] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1112.929195] LDISKFS-fs (dm-0): recovery complete [ 1112.950544] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1118.556121] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1120.095244] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 1122.253290] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug -1 all [ 1123.884521] Lustre: lustre-MDT0000: Recovery over after 0:03, of 3 clients 3 recovered and 0 were evicted. [ 1123.922294] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:289) [ 1123.924567] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:289) [ 1130.279200] Lustre: DEBUG MARKER: oleg615-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1132.002928] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1140.171488] Lustre: DEBUG MARKER: == replay-dual test 8: replay of resent request ========== 20:42:18 (1789778538) [ 1148.766996] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1149.951186] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 1149.960035] LustreError: 6521:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff99c3adab1880 x1876717750992896/t38654705670(0) o36->8f0f7804-f3fd-45d1-b59c-eb1f56a8f568@192.168.206.15@tcp:476/0 lens 512/448 e 0 to 0 dl 1789778561 ref 1 fl Interpret:/200/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 1166.128434] Lustre: lustre-MDT0000: Client 8f0f7804-f3fd-45d1-b59c-eb1f56a8f568 (at 192.168.206.15@tcp) reconnecting [ 1166.172765] Lustre: 6519:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff99c3adf09f80 x1876717750992896/t38654705670(0) o36->8f0f7804-f3fd-45d1-b59c-eb1f56a8f568@192.168.206.15@tcp:492/0 lens 512/2880 e 0 to 0 dl 1789778577 ref 1 fl Interpret:/202/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 1169.684400] Lustre: Failing over lustre-MDT0000 [ 1169.889425] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1169.893773] 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 [ 1169.903910] Lustre: Skipped 6 previous similar messages [ 1170.004788] Lustre: server umount lustre-MDT0000 complete [ 1190.600901] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1190.607320] LDISKFS-fs (dm-0): recovery complete [ 1190.639087] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1190.849983] LustreError: MGC192.168.206.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1191.227172] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1191.231321] Lustre: Skipped 2 previous similar messages [ 1191.333380] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1191.699274] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 1196.094546] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug -1 all [ 1196.581348] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1196.595622] Lustre: Skipped 11 previous similar messages [ 1196.672365] Lustre: lustre-MDT0000: Recovery over after 0:05, of 3 clients 3 recovered and 0 were evicted. [ 1196.727585] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:321) [ 1196.729121] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:321) [ 1205.681467] Lustre: DEBUG MARKER: oleg615-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1207.313850] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1215.411374] Lustre: DEBUG MARKER: == replay-dual test 9: resending a replayed create ======= 20:43:33 (1789778613) [ 1223.307637] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1226.072511] Lustre: Failing over lustre-MDT0000 [ 1226.334839] Lustre: server umount lustre-MDT0000 complete [ 1227.246825] LustreError: 22968:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1227.266812] LustreError: 22968:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 140 previous similar messages [ 1242.593725] Lustre: 3647:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789778627/real 1789778627] req@ffff99c39f585f80 x1876717770163840/t0(0) o400->MGC192.168.206.115@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789778643 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1248.125543] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1248.129019] LDISKFS-fs (dm-0): recovery complete [ 1248.144599] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1253.254884] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1257.747042] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug -1 all [ 1258.594098] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 1258.603110] LustreError: 32155:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff99c385f77b80 x1876717751008896/t42949672962(42949672962) o36->8f0f7804-f3fd-45d1-b59c-eb1f56a8f568@192.168.206.15@tcp:581/0 lens 528/448 e 0 to 0 dl 1789778666 ref 1 fl Complete:/204/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 1270.565383] Lustre: lustre-MDT0000: Client 8f0f7804-f3fd-45d1-b59c-eb1f56a8f568 (at 192.168.206.15@tcp) reconnected, waiting for 3 clients in recovery for 1:28 [ 1270.655698] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:353) [ 1270.658779] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:353) [ 1276.271933] Lustre: DEBUG MARKER: oleg615-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1277.545530] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1285.070705] Lustre: DEBUG MARKER: == replay-dual test 10: resending a replayed unlink ====== 20:44:43 (1789778683) [ 1290.783871] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1293.183061] Lustre: Failing over lustre-MDT0000 [ 1293.446844] Lustre: server umount lustre-MDT0000 complete [ 1314.679620] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1314.682153] LDISKFS-fs (dm-0): recovery complete [ 1314.695187] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1320.927147] LustreError: 34177:0:(import.c:339:ptlrpc_invalidate_import()) MGS: timeout waiting for callback (1 != 0) [ 1320.929732] LustreError: 3646:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff99c3adb7df80 x1876717770211328/t0(0) o250->MGC192.168.206.115@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 [ 1320.985566] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x3397d59de4142d8a [ 1321.376457] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1321.749881] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 1321.758612] Lustre: Skipped 1 previous similar message [ 1325.370341] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug -1 all [ 1326.672416] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 1326.680931] LustreError: 34211:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff99c2870d1f80 x1876717751027200/t47244640260(47244640260) o36->8f0f7804-f3fd-45d1-b59c-eb1f56a8f568@192.168.206.15@tcp:648/0 lens 528/448 e 0 to 0 dl 1789778733 ref 1 fl Complete:/204/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 1338.178567] Lustre: lustre-MDT0000: Client 8f0f7804-f3fd-45d1-b59c-eb1f56a8f568 (at 192.168.206.15@tcp) reconnected, waiting for 3 clients in recovery for 1:29 [ 1338.261536] Lustre: lustre-MDT0000: Recovery over after 0:17, of 3 clients 3 recovered and 0 were evicted. [ 1338.278206] Lustre: Skipped 1 previous similar message [ 1338.308201] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:385) [ 1338.309461] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:385) [ 1343.257627] Lustre: DEBUG MARKER: oleg615-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1345.032836] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1353.556600] Lustre: DEBUG MARKER: == replay-dual test 11: both clients timeout during replay ========================================================== 20:45:51 (1789778751) [ 1360.004541] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1362.410371] Lustre: Failing over lustre-MDT0000 [ 1362.420722] 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 [ 1362.427633] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1362.432350] Lustre: Skipped 12 previous similar messages [ 1362.436622] LustreError: 3649:0:(client.c:1394:ptlrpc_import_delay_req()) @@@ IMP_CLOSED req@ffff99c38b593800 x1876717770242432/t0(0) o41->lustre-MDT0001-osp-MDT0000@0@lo:24/4 lens 224/368 e 0 to 0 dl 0 ref 1 fl Rpc:QU/200/ffffffff rc 0/-1 job:'osp-pre-1-0.0' uid:0 gid:0 projid:4294967295 [ 1362.707520] Lustre: server umount lustre-MDT0000 complete [ 1383.908361] Lustre: 3650:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789778768/real 1789778768] req@ffff99c3adab0380 x1876717770243840/t0(0) o400->MGC192.168.206.115@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789778784 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1383.939746] Lustre: 3650:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 1383.948821] LustreError: MGC192.168.206.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1383.966213] LustreError: Skipped 2 previous similar messages [ 1384.821469] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1384.826741] LDISKFS-fs (dm-0): recovery complete [ 1384.834575] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1394.168755] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x3397d59de41433fe [ 1398.355644] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug -1 all [ 1399.855713] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 1399.861628] LustreError: 36271:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff99c385f75c00 x1876717751044480/t51539607554(51539607554) o36->8f0f7804-f3fd-45d1-b59c-eb1f56a8f568@192.168.206.15@tcp:722/0 lens 528/448 e 0 to 0 dl 1789778807 ref 1 fl Complete:/204/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 1405.065882] Lustre: DEBUG MARKER: oleg615-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1410.672364] Lustre: lustre-MDT0000: Client 8f0f7804-f3fd-45d1-b59c-eb1f56a8f568 (at 192.168.206.15@tcp) reconnected, waiting for 3 clients in recovery for 1:29 [ 1410.788192] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:417) [ 1410.792929] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:417) [ 1412.875513] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 6 sec [ 1419.730200] Lustre: DEBUG MARKER: == replay-dual test 12: open resend timeout ============== 20:46:57 (1789778817) [ 1426.179299] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1428.601280] Lustre: Failing over lustre-MDT0000 [ 1428.840957] Lustre: server umount lustre-MDT0000 complete [ 1450.506812] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1450.510788] LDISKFS-fs (dm-0): recovery complete [ 1450.523472] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1457.127126] LustreError: 3646:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff99c39fb55500 x1876717770287616/t0(0) o250->MGC192.168.206.115@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 [ 1457.441909] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1457.449791] Lustre: Skipped 3 previous similar messages [ 1457.516381] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1457.525619] Lustre: Skipped 1 previous similar message [ 1461.536120] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug -1 all [ 1462.782770] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 1462.787598] Lustre: Skipped 17 previous similar messages [ 1462.915406] Lustre: *** cfs_fail_loc=302, val=2147483648*** [ 1479.479750] Lustre: lustre-MDT0000: Client 8f0f7804-f3fd-45d1-b59c-eb1f56a8f568 (at 192.168.206.15@tcp) reconnected, waiting for 3 clients in recovery for 1:24 [ 1479.607278] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:449) [ 1479.613243] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:449) [ 1486.020686] Lustre: DEBUG MARKER: == replay-dual test 13: close resend timeout ============= 20:48:04 (1789778884) [ 1492.767952] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1495.230983] Lustre: Failing over lustre-MDT0000 [ 1495.562945] Lustre: server umount lustre-MDT0000 complete [ 1516.044283] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1516.046415] LDISKFS-fs (dm-0): recovery complete [ 1516.055730] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1525.224600] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x3397d59de41440c3 [ 1529.225713] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug -1 all [ 1530.954132] Lustre: *** cfs_fail_loc=115, val=2147483648*** [ 1546.530589] Lustre: lustre-MDT0000: Client 8f0f7804-f3fd-45d1-b59c-eb1f56a8f568 (at 192.168.206.15@tcp) reconnected, waiting for 3 clients in recovery for 1:24 [ 1546.643205] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:481) [ 1546.645319] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:481) [ 1552.438770] Lustre: DEBUG MARKER: SKIP: replay-dual test_14b skipping ALWAYS excluded test 14b [ 1553.817112] Lustre: DEBUG MARKER: == replay-dual test 15a: timeout waiting for lost client during replay, 1 client completes ========================================================== 20:49:12 (1789778952) [ 1559.950664] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1562.302654] Lustre: Failing over lustre-MDT0000 [ 1562.405878] Lustre: lustre-MDT0000: Not available for connect from 192.168.206.15@tcp (stopping) [ 1562.413380] Lustre: Skipped 2 previous similar messages [ 1562.484780] Lustre: server umount lustre-MDT0000 complete [ 1581.801592] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1581.806220] LDISKFS-fs (dm-0): recovery complete [ 1581.815351] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1582.056484] Lustre: lustre-MDT0000: Not available for connect from 0@lo (not set up) [ 1582.068444] Lustre: Skipped 3 previous similar messages [ 1582.857395] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 1582.869455] Lustre: Skipped 3 previous similar messages [ 1586.163371] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug -1 all [ 1652.503033] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 1652.509325] Lustre: 41941:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 34d552fe-e60a-4387-9f70-925b8cb48a3c@ [ 1652.523331] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 1653.256495] Lustre: lustre-MDT0000: Recovery over after 1:11, of 3 clients 2 recovered and 1 was evicted. [ 1653.266772] Lustre: Skipped 3 previous similar messages [ 1653.338613] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:495 to 0x2c0000401:513) [ 1653.340251] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:494 to 0x280000401:513) [ 1659.468764] Lustre: DEBUG MARKER: oleg615-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1661.046971] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1671.190978] Lustre: DEBUG MARKER: == replay-dual test 15c: remove multiple OST orphans ===== 20:51:09 (1789779069) [ 1679.052775] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1771.694935] Lustre: Failing over lustre-MDT0000 [ 1772.208390] Lustre: server umount lustre-MDT0000 complete [ 1772.330587] LustreError: 6519:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.206.15@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1772.354831] LustreError: 6519:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 211 previous similar messages [ 1776.101252] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1776.118375] 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 [ 1776.143705] Lustre: Skipped 13 previous similar messages [ 1792.994587] Lustre: 3649:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789779177/real 1789779177] req@ffff99c3a6637b80 x1876717770459392/t0(0) o400->MGC192.168.206.115@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789779193 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1793.050617] Lustre: 3649:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 1793.061540] LustreError: MGC192.168.206.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1793.081214] LustreError: Skipped 3 previous similar messages [ 1794.074958] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1794.076856] LDISKFS-fs (dm-0): recovery complete [ 1794.097800] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1803.563182] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1803.585207] Lustre: Skipped 2 previous similar messages [ 1807.607582] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug -1 all [ 1874.500350] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 1874.515275] Lustre: 43955:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 08ac9537-ada7-468f-99be-ec876fad2e15@ [ 1874.530987] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 1874.752250] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:494 to 0x280000401:1537) [ 1874.752947] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:495 to 0x2c0000401:1537) [ 1882.047513] Lustre: DEBUG MARKER: oleg615-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1883.622651] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1891.930488] Lustre: DEBUG MARKER: == replay-dual test 16: fail MDS during recovery (3571) == 20:54:49 (1789779289) [ 1899.184543] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1901.568230] Lustre: Failing over lustre-MDT0000 [ 1901.808106] Lustre: server umount lustre-MDT0000 complete [ 1905.632657] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1923.088632] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1923.089983] LDISKFS-fs (dm-0): recovery complete [ 1923.095365] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1936.603816] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug -1 all [ 1961.093491] Lustre: Failing over lustre-MDT0000 [ 1961.111808] LustreError: 46399:0:(ldlm_lib.c:3029:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 1961.121496] Lustre: 45924:0:(ldlm_lib.c:2429:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 1961.127413] Lustre: 45924:0:(ldlm_lib.c:1939:abort_req_replay_queue()) @@@ aborted: req@ffff99c3b5e94e00 x1876717753495424/t0(73014444033) o36->8f0f7804-f3fd-45d1-b59c-eb1f56a8f568@192.168.206.15@tcp:529/0 lens 528/0 e 2 to 0 dl 1789779369 ref 1 fl Complete:/204/ffffffff rc 0/-1 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 1961.141174] Lustre: lustre-MDT0000-osd: cancel update llog [0x200000400:0x1:0x0] [ 1961.159098] Lustre: lustre-MDT0000: Not available for connect from 192.168.206.15@tcp (stopping) [ 1961.161973] Lustre: lustre-MDT0001-osp-MDT0000: cancel update llog [0x240000401:0x1:0x0] [ 1961.172712] LustreError: 45924:0:(client.c:1394:ptlrpc_import_delay_req()) @@@ IMP_CLOSED req@ffff99c382ab6d80 x1876717770554752/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 [ 1961.189079] LustreError: 45924: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 [ 1961.202397] LustreError: 45924:0:(llog.c:875:llog_process_thread()) lustre-MDT0001-osp-MDT0000 retry remote llog process [ 1961.208813] LustreError: 45924:0:(fid_request.c:217:seq_client_alloc_seq()) cli-cli-lustre-MDT0001-osp-MDT0000: Cannot allocate new meta-sequence: rc = -5 [ 1961.216265] LustreError: 45924:0:(fid_request.c:321:seq_client_alloc_fid()) cli-cli-lustre-MDT0001-osp-MDT0000: Can't allocate new sequence: rc = -5 [ 1961.489792] Lustre: server umount lustre-MDT0000 complete [ 1980.035622] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1988.590223] LustreError: 3646:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff99c3bfa23100 x1876717770563072/t0(0) o250->MGC192.168.206.115@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 [ 1988.853604] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1988.859177] Lustre: Skipped 4 previous similar messages [ 1993.165794] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug -1 all [ 1994.248504] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 1994.259078] Lustre: Skipped 19 previous similar messages [ 2059.500650] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 2059.511540] Lustre: 46856:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client d4ce5867-fd62-441f-b84e-0ca4af1fe692@ [ 2059.533882] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 2060.220842] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1551 to 0x2c0000401:1569) [ 2060.221626] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1550 to 0x280000401:1569) [ 2067.593481] Lustre: DEBUG MARKER: oleg615-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2069.357276] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2079.118227] Lustre: DEBUG MARKER: == replay-dual test 17: fail OST during recovery (3571) == 20:57:57 (1789779477) [ 2087.984145] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 2089.851601] Lustre: Failing over lustre-OST0000 [ 2090.010991] Lustre: server umount lustre-OST0000 complete [ 2090.984846] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 2112.277989] LDISKFS-fs (dm-2): 3 truncates cleaned up [ 2112.280492] LDISKFS-fs (dm-2): recovery complete [ 2112.289665] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2113.288245] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 4 clients reconnect [ 2113.294972] Lustre: Skipped 3 previous similar messages [ 2118.760863] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug -1 all [ 2143.206578] Lustre: Failing over lustre-OST0000 [ 2143.210176] LustreError: 49378:0:(ldlm_lib.c:3029:target_stop_recovery_thread()) lustre-OST0000: Aborting recovery [ 2143.214878] Lustre: 48808:0:(ldlm_lib.c:2429:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 2143.221756] Lustre: 48808:0:(ldlm_lib.c:2429:target_recovery_overseer()) Skipped 2 previous similar messages [ 2143.231302] LustreError: 48808:0:(ofd_obd.c:1325:ofd_iocontrol()) lustre-OST0000: iocontrol from 'tgt_recover_0' cmd=c00866c1 _IOWR('f', 193, 8) unrecognized: rc = -25 [ 2143.339453] Lustre: server umount lustre-OST0000 complete [ 2160.540548] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2166.719972] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug -1 all [ 2232.500242] Lustre: lustre-OST0000: recovery is timed out, evict stale exports [ 2232.523560] Lustre: 49819:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-OST0000: disconnect stale client 40c4dbf9-1d36-4172-8420-6517f96cb38b@ [ 2232.541291] Lustre: lustre-OST0000: disconnecting 1 stale clients [ 2232.558371] Lustre: lustre-OST0000: Recovery over after 1:10, of 4 clients 3 recovered and 1 was evicted. [ 2232.585529] Lustre: Skipped 4 previous similar messages [ 2237.618699] Lustre: DEBUG MARKER: oleg615-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 2239.229342] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 2249.201553] Lustre: DEBUG MARKER: == replay-dual test 18: ldlm_handle_enqueue succeeds on evicted export (3822) ========================================================== 21:00:47 (1789779647) [ 2253.131457] LustreError: 9752:0:(ldlm_lockd.c:1361:ldlm_handle_enqueue()) cfs_fail_timeout id 30b sleeping for 40000ms [ 2293.135132] LustreError: 9752:0:(ldlm_lockd.c:1361:ldlm_handle_enqueue()) cfs_fail_timeout id 30b awake [ 2305.585674] Lustre: DEBUG MARKER: == replay-dual test 19: resend of open request =========== 21:01:43 (1789779703) [ 2312.864423] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2314.133372] Lustre: *** cfs_fail_loc=157, val=2147483648*** [ 2314.141351] LustreError: 9752:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff99c39f588700 x1876717753620224/t0(0) o101->8f0f7804-f3fd-45d1-b59c-eb1f56a8f568@192.168.206.15@tcp:201/0 lens 576/688 e 0 to 0 dl 1789779796 ref 1 fl Interpret:/600/0 rc 0/0 job:'createmany.0' uid:0 gid:0 projid:0 [ 2401.050158] Lustre: lustre-MDT0000: Client 8f0f7804-f3fd-45d1-b59c-eb1f56a8f568 (at 192.168.206.15@tcp) reconnecting [ 2403.764040] Lustre: Failing over lustre-MDT0000 [ 2404.102372] Lustre: server umount lustre-MDT0000 complete [ 2406.199968] LustreError: 17877:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.206.15@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 2406.223164] LustreError: 17877:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 112 previous similar messages [ 2407.911988] 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 [ 2407.940192] Lustre: Skipped 15 previous similar messages [ 2424.225198] Lustre: 3650:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789779808/real 1789779808] req@ffff99c3b5e95f80 x1876717770767360/t0(0) o400->MGC192.168.206.115@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789779824 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2424.272079] Lustre: 3650:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 5 previous similar messages [ 2424.290315] LustreError: MGC192.168.206.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2424.307556] LustreError: Skipped 2 previous similar messages [ 2429.580090] LDISKFS-fs (dm-0): 4 truncates cleaned up [ 2429.584359] LDISKFS-fs (dm-0): recovery complete [ 2429.593508] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2433.522847] LustreError: 3646:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff99c3b5ff3800 x1876717770775808/t0(0) o250->MGC192.168.206.115@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 [ 2433.943985] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 2433.958889] Lustre: Skipped 4 previous similar messages [ 2438.302891] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug -1 all [ 2439.273698] Lustre: 52479:0:(ldlm_lib.c:2110:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 2439.481322] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1584 to 0x2c0000401:1601) [ 2439.482246] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1584 to 0x280000401:1601) [ 2447.465596] Lustre: DEBUG MARKER: oleg615-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2449.048068] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2456.577884] Lustre: DEBUG MARKER: == replay-dual test 20: recovery time is not increasing == 21:04:14 (1789779854) [ 2463.865944] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2466.034352] Lustre: Failing over lustre-MDT0000 [ 2466.248345] Lustre: server umount lustre-MDT0000 complete [ 2487.033820] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2487.036501] LDISKFS-fs (dm-0): recovery complete [ 2487.042530] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2495.462245] LustreError: 3646:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff99c3b5e96d80 x1876717770814080/t0(0) o250->MGC192.168.206.115@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 [ 2499.759692] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug -1 all [ 2638.500201] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 2638.515048] Lustre: 54416:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 492514b9-7e90-4c30-a281-31fb7c8aaf79@ [ 2638.530260] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 2638.644602] Lustre: 54416:0:(ldlm_lib.c:2110:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 2638.660957] Lustre: 54416:0:(ldlm_lib.c:2110:extend_recovery_timer()) Skipped 6 previous similar messages [ 2638.742694] Lustre: lustre-MDT0000-osp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 2638.759544] Lustre: Skipped 12 previous similar messages [ 2638.818115] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1603 to 0x2c0000401:1633) [ 2638.821105] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1584 to 0x280000401:1633) [ 2645.138068] Lustre: DEBUG MARKER: oleg615-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2646.547861] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2655.986170] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2657.968331] Lustre: Failing over lustre-MDT0000 [ 2658.232638] Lustre: server umount lustre-MDT0000 complete [ 2659.297076] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 2681.962703] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2681.969387] LDISKFS-fs (dm-0): recovery complete [ 2681.990544] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2685.408393] LustreError: 3646:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff99c3c1214e00 x1876717770895104/t0(0) o250->MGC192.168.206.115@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 [ 2685.856249] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 2685.860806] Lustre: Skipped 4 previous similar messages [ 2690.106804] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug -1 all [ 2827.500811] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 2827.528523] Lustre: 56203:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 645b9def-f3e3-40d0-85cd-24bf4b73bd0f@ [ 2827.547697] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 2827.624844] Lustre: 56203:0:(ldlm_lib.c:2110:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 2827.634878] Lustre: 56203:0:(ldlm_lib.c:2110:extend_recovery_timer()) Skipped 4 previous similar messages [ 2827.796967] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1603 to 0x2c0000401:1665) [ 2827.805611] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1635 to 0x280000401:1665) [ 2833.831833] Lustre: DEBUG MARKER: oleg615-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2835.295679] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2843.700019] Lustre: DEBUG MARKER: == replay-dual test 21a: commit on sharing =============== 21:10:41 (1789780241) [ 2852.037735] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2854.026766] Lustre: Failing over lustre-MDT0000 [ 2854.331951] Lustre: server umount lustre-MDT0000 complete [ 2874.989113] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2874.990543] LDISKFS-fs (dm-0): recovery complete [ 2875.004412] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2885.431489] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 2885.449044] Lustre: Skipped 4 previous similar messages [ 2890.385479] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug -1 all [ 3025.500316] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 3025.503139] Lustre: 58233:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 6298a189-9b47-4681-a95c-35475fb26938@ [ 3025.513828] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 3025.552164] Lustre: 58233:0:(ldlm_lib.c:2110:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3025.565675] Lustre: 58233:0:(ldlm_lib.c:2110:extend_recovery_timer()) Skipped 4 previous similar messages [ 3025.579427] Lustre: lustre-MDT0000: Recovery over after 2:20, of 3 clients 2 recovered and 1 was evicted. [ 3025.597739] Lustre: Skipped 3 previous similar messages [ 3025.684506] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1667 to 0x2c0000401:1697) [ 3025.688545] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1635 to 0x280000401:1697) [ 3035.845425] Lustre: DEBUG MARKER: SKIP: replay-dual test_21b skipping SLOW test 21b [ 3037.260473] Lustre: DEBUG MARKER: == replay-dual test 22a: c1 lfs mkdir -i 1 dir1, M1 drop reply [ 3038.239661] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 3038.249292] LustreError: 9752:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff99c3add5aa00 x1876717753741056/t4294967341(0) o36->8f0f7804-f3fd-45d1-b59c-eb1f56a8f568@192.168.206.15@tcp:169/0 lens 560/448 e 0 to 0 dl 1789780519 ref 1 fl Interpret:/200/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 3040.681323] Lustre: Failing over lustre-MDT0001 [ 3040.873621] Lustre: server umount lustre-MDT0001 complete [ 3041.559861] LustreError: 14187:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 192.168.206.15@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3041.579721] LustreError: 14187:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 144 previous similar messages [ 3043.811992] Lustre: lustre-MDT0001-lwp-OST0001: Connection to lustre-MDT0001 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 3043.815893] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 3043.834154] Lustre: Skipped 13 previous similar messages [ 3059.282305] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3059.867641] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 3059.886041] Lustre: Skipped 3 previous similar messages [ 3064.947744] Lustre: 6521:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff99c3add58380 x1876717753741056/t4294967341(0) o36->8f0f7804-f3fd-45d1-b59c-eb1f56a8f568@192.168.206.15@tcp:196/0 lens 560/2880 e 0 to 0 dl 1789780546 ref 1 fl Interpret:/202/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 3066.600415] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug -1 all [ 3074.900038] Lustre: DEBUG MARKER: oleg615-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 3076.280943] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3085.182215] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3087.717208] Lustre: Failing over lustre-MDT0000 [ 3088.065918] Lustre: server umount lustre-MDT0000 complete [ 3090.402611] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3107.295105] Lustre: 3650:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789780491/real 1789780491] req@ffff99c282d24a80 x1876717771082112/t0(0) o400->MGC192.168.206.115@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789780507 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3107.353702] Lustre: 3650:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 3107.371458] LustreError: MGC192.168.206.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3107.397757] LustreError: Skipped 3 previous similar messages [ 3111.335311] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3111.337938] LDISKFS-fs (dm-0): recovery complete [ 3111.349796] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3118.053298] LustreError: 3646:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff99c39f2d1880 x1876717771090944/t0(0) o250->MGC192.168.206.115@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 [ 3123.254802] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug -1 all [ 3123.743263] Lustre: 61297:0:(ldlm_lib.c:2110:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3123.840833] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1667 to 0x2c0000401:1729) [ 3123.842721] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1635 to 0x280000401:1729) [ 3133.319456] Lustre: DEBUG MARKER: oleg615-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3135.167629] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3144.698158] Lustre: DEBUG MARKER: == replay-dual test 22b: c1 lfs mkdir -i 1 d1, M1 drop reply [ 3146.016886] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 3146.024225] LustreError: 9752:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff99c28b72b800 x1876717753781888/t8589934617(0) o36->8f0f7804-f3fd-45d1-b59c-eb1f56a8f568@192.168.206.15@tcp:277/0 lens 560/448 e 0 to 0 dl 1789780627 ref 1 fl Interpret:/200/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 3148.498611] Lustre: Failing over lustre-MDT0000 [ 3148.912294] Lustre: server umount lustre-MDT0000 complete [ 3152.812124] LustreError: 6506:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1789780553 with bad export cookie 3717674891530897661 [ 3152.816438] Lustre: Failing over lustre-MDT0001 [ 3152.821316] LustreError: 6506:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 3152.862605] LustreError: 62440:0:(client.c:1394:ptlrpc_import_delay_req()) @@@ IMP_CLOSED req@ffff99c28b41df80 x1876717771126144/t0(0) o1000->lustre-MDT0000-osp-MDT0001@0@lo:24/4 lens 304/4320 e 0 to 0 dl 0 ref 2 fl Rpc:QU/200/ffffffff rc 0/-1 job:'umount.0' uid:0 gid:0 projid:4294967295 [ 3152.880499] LustreError: 62440:0:(client.c:1394:ptlrpc_import_delay_req()) Skipped 1 previous similar message [ 3152.887924] LustreError: 62440:0:(osp_object.c:618:osp_attr_get()) lustre-MDT0000-osp-MDT0001: osp_attr_get update error [0x200000401:0x1:0x0]: rc = -5 [ 3153.387238] Lustre: server umount lustre-MDT0001 complete [ 3173.138316] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3173.408466] LustreError: 63125:0:(llog.c:1655:llog_backup()) MGC192.168.206.115@tcp: failed to open log lustre-sptlrpc: rc = -108 [ 3173.420586] Lustre: 63125:0:(mgc_request_server.c:770:mgc_llog_local_copy()) MGC192.168.206.115@tcp: failed to copy new config lustre-sptlrpc: rc = -108 [ 3173.504548] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3177.974497] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x3397d59de416906d [ 3183.573126] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug -1 all [ 3184.253846] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug -1 all [ 3184.780449] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:36 to 0x280000400:65) [ 3184.781964] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:36 to 0x2c0000400:65) [ 3184.809162] Lustre: 63139:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff99c3b6020700 x1876717753781888/t8589934617(0) o36->8f0f7804-f3fd-45d1-b59c-eb1f56a8f568@192.168.206.15@tcp:316/0 lens 560/2880 e 0 to 0 dl 1789780666 ref 1 fl Interpret:/202/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 3190.239159] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1667 to 0x2c0000401:1761) [ 3190.239729] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1635 to 0x280000401:1761) [ 3196.983369] Lustre: DEBUG MARKER: oleg615-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 [ 3198.782486] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3200.687284] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3211.176901] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3213.217588] Lustre: Failing over lustre-MDT0000 [ 3213.449182] Lustre: server umount lustre-MDT0000 complete [ 3215.878831] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3237.023235] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3237.030659] LDISKFS-fs (dm-0): recovery complete [ 3237.073871] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3247.105204] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 3247.113231] Lustre: Skipped 22 previous similar messages [ 3247.152564] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug -1 all [ 3247.182400] Lustre: 65369:0:(ldlm_lib.c:2110:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3247.198045] Lustre: 65369:0:(ldlm_lib.c:2110:extend_recovery_timer()) Skipped 4 previous similar messages [ 3247.291803] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1667 to 0x2c0000401:1793) [ 3247.292134] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1635 to 0x280000401:1793) [ 3257.361503] Lustre: DEBUG MARKER: oleg615-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3259.742955] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3267.237082] Lustre: DEBUG MARKER: == replay-dual test 22c: c1 lfs mkdir -i 1 d1, M1 drop update [ 3268.453647] Lustre: *** cfs_fail_loc=1701, val=2147483648*** [ 3268.460111] LustreError: 8443:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff99c3b5fcc700 x1876717771203328/t107374182411(0) o1000->lustre-MDT0001-mdtlov_UUID@0@lo:330/0 lens 2520/4320 e 0 to 0 dl 1789780680 ref 1 fl Interpret:/200/0 rc 0/0 job:'osp_up0-1.0' uid:0 gid:0 projid:4294967295 [ 3271.411959] Lustre: Failing over lustre-MDT0000 [ 3271.672146] Lustre: server umount lustre-MDT0000 complete [ 3289.640041] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3299.673934] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3299.678764] Lustre: Skipped 6 previous similar messages [ 3304.625734] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug -1 all [ 3305.064888] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1635 to 0x280000401:1825) [ 3305.072953] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1667 to 0x2c0000401:1825) [ 3314.934713] Lustre: DEBUG MARKER: oleg615-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3316.607541] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3325.571310] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3327.869701] Lustre: Failing over lustre-MDT0000 [ 3328.291378] Lustre: server umount lustre-MDT0000 complete [ 3350.746502] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3350.751677] LDISKFS-fs (dm-0): recovery complete [ 3350.760422] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3357.173102] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x3397d59de416a6f5 [ 3361.873596] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug -1 all [ 3362.867470] Lustre: 68559:0:(ldlm_lib.c:2110:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3362.876865] Lustre: 68559:0:(ldlm_lib.c:2110:extend_recovery_timer()) Skipped 4 previous similar messages [ 3362.959493] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1667 to 0x2c0000401:1857) [ 3362.961520] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1635 to 0x280000401:1857) [ 3369.724198] Lustre: DEBUG MARKER: oleg615-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3371.650477] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3380.696226] Lustre: DEBUG MARKER: == replay-dual test 22d: c1 lfs mkdir -i 1 d1, M1 drop update [ 3385.134861] Lustre: *** cfs_fail_loc=1701, val=2147483648*** [ 3385.139262] LustreError: 64594:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff99c3b6023b80 x1876717771279232/t115964117001(0) o1000->lustre-MDT0001-mdtlov_UUID@0@lo:446/0 lens 2520/4320 e 0 to 0 dl 1789780796 ref 1 fl Interpret:/200/0 rc 0/0 job:'osp_up0-1.0' uid:0 gid:0 projid:4294967295 [ 3388.240373] Lustre: Failing over lustre-MDT0000 [ 3388.398078] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3388.486326] Lustre: server umount lustre-MDT0000 complete [ 3391.852231] LustreError: 8450:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1789780792 with bad export cookie 3717674891530905333 [ 3391.856866] Lustre: Failing over lustre-MDT0001 [ 3391.865704] LustreError: 8450:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 3 previous similar messages [ 3391.892244] LustreError: 69797:0:(ldlm_resource.c:1207:ldlm_resource_complain()) lustre-MDT0000-osp-MDT0001: namespace resource [0x2000013a1:0x78:0x0].0xf7117594 (ffff99c28b73e200) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 3391.946975] Lustre: lustre-MDT0001: Not available for connect from 192.168.206.15@tcp (stopping) [ 3391.955586] Lustre: Skipped 3 previous similar messages [ 3393.511121] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 3393.516170] Lustre: Skipped 1 previous similar message [ 3396.520341] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 3396.525257] Lustre: Skipped 3 previous similar messages [ 3398.546894] Lustre: server umount lustre-MDT0001 complete [ 3416.808277] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3416.854060] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3417.060521] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x3397d59de416ae50 [ 3417.670775] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_connect to node 0@lo failed: rc = -114 [ 3421.442159] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug -1 all [ 3421.897972] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug -1 all [ 3422.761475] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1635 to 0x280000401:1889) [ 3422.786538] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1667 to 0x2c0000401:1889) [ 3434.032666] Lustre: 70754:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff99c28be2fb80 x1876717753870848/t12884901939(0) o36->8f0f7804-f3fd-45d1-b59c-eb1f56a8f568@192.168.206.15@tcp:564/0 lens 560/2880 e 0 to 0 dl 1789780914 ref 1 fl Interpret:/202/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 3434.047484] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:70 to 0x2c0000400:97) [ 3434.065899] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:70 to 0x280000400:97) [ 3441.550975] Lustre: DEBUG MARKER: oleg615-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 [ 3443.588224] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3445.019904] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3453.890812] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3455.888555] Lustre: Failing over lustre-MDT0000 [ 3456.318680] Lustre: server umount lustre-MDT0000 complete [ 3479.006090] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3479.013153] LDISKFS-fs (dm-0): recovery complete [ 3479.025992] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3486.477993] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 3486.490788] Lustre: Skipped 9 previous similar messages [ 3488.499823] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug -1 all [ 3489.359057] Lustre: 72745:0:(ldlm_lib.c:2110:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3489.376901] Lustre: 72745:0:(ldlm_lib.c:2110:extend_recovery_timer()) Skipped 4 previous similar messages [ 3489.476748] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1635 to 0x280000401:1921) [ 3489.484105] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1667 to 0x2c0000401:1921) [ 3498.292252] Lustre: DEBUG MARKER: oleg615-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3499.910797] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3509.709883] Lustre: DEBUG MARKER: == replay-dual test 23a: c1 rmdir d1, M1 drop reply and fail, client2 mkdir d1 ========================================================== 21:21:47 (1789780907) [ 3511.231234] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 3511.240647] LustreError: 70513:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff99c28c77bb80 x1876717753913472/t17179869210(0) o36->8f0f7804-f3fd-45d1-b59c-eb1f56a8f568@192.168.206.15@tcp:641/0 lens 496/456 e 0 to 0 dl 1789780991 ref 1 fl Interpret:/200/0 rc 0/0 job:'rmdir.0' uid:0 gid:0 projid:4294967295 [ 3515.060488] Lustre: Failing over lustre-MDT0001 [ 3515.517864] Lustre: server umount lustre-MDT0001 complete [ 3534.330671] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3539.695884] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug -1 all [ 3540.027339] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:100 to 0x280000400:129) [ 3540.027524] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:100 to 0x2c0000400:129) [ 3540.054802] Lustre: 70514:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff99c282d26300 x1876717753913472/t17179869210(0) o36->8f0f7804-f3fd-45d1-b59c-eb1f56a8f568@192.168.206.15@tcp:670/0 lens 496/2888 e 0 to 0 dl 1789781020 ref 1 fl Interpret:/202/0 rc 0/0 job:'rmdir.0' uid:0 gid:0 projid:4294967295 [ 3548.622770] Lustre: DEBUG MARKER: oleg615-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 3550.137170] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3557.600431] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3559.859794] Lustre: Failing over lustre-MDT0000 [ 3560.258685] Lustre: server umount lustre-MDT0000 complete [ 3583.987001] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3583.989426] LDISKFS-fs (dm-0): recovery complete [ 3583.994884] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3586.536668] LustreError: 3646:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff99c3b5d1ea00 x1876717771398528/t0(0) o250->MGC192.168.206.115@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 [ 3586.558918] LustreError: 3646:0:(client.c:1404:ptlrpc_import_delay_req()) Skipped 1 previous similar message [ 3590.354810] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug -1 all [ 3592.262243] Lustre: 75910:0:(ldlm_lib.c:2110:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3592.278254] Lustre: 75910:0:(ldlm_lib.c:2110:extend_recovery_timer()) Skipped 4 previous similar messages [ 3592.492468] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1923 to 0x280000401:1953) [ 3592.496206] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1923 to 0x2c0000401:1953) [ 3599.320194] Lustre: DEBUG MARKER: oleg615-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3600.934302] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3609.481876] Lustre: DEBUG MARKER: == replay-dual test 23b: c1 rmdir d1, M1 drop reply and fail M0/M1, c2 mkdir d1 ========================================================== 21:23:27 (1789781007) [ 3610.792669] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 3610.801688] LustreError: 70754:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff99c3bfa79500 x1876717753946752/t21474836483(0) o36->8f0f7804-f3fd-45d1-b59c-eb1f56a8f568@192.168.206.15@tcp:741/0 lens 496/456 e 0 to 0 dl 1789781091 ref 1 fl Interpret:/200/0 rc 0/0 job:'rmdir.0' uid:0 gid:0 projid:4294967295 [ 3615.026184] Lustre: Failing over lustre-MDT0000 [ 3615.083203] LustreError: 6504:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1789781015 with bad export cookie 3717674891530912634 [ 3615.146274] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3615.704429] Lustre: server umount lustre-MDT0000 complete [ 3619.729908] Lustre: Failing over lustre-MDT0001 [ 3619.739786] LustreError: 6505:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1789781020 with bad export cookie 3717674891530912529 [ 3619.762704] LustreError: 6505:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 3620.607789] Lustre: server umount lustre-MDT0001 complete [ 3641.455293] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3641.931647] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3641.949529] LustreError: 77784:0:(llog.c:1655:llog_backup()) MGC192.168.206.115@tcp: failed to open log lustre-sptlrpc: rc = -108 [ 3641.962942] Lustre: 77784:0:(mgc_request_server.c:770:mgc_llog_local_copy()) MGC192.168.206.115@tcp: failed to copy new config lustre-sptlrpc: rc = -108 [ 3643.365579] LustreError: 77802:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3643.402749] LustreError: 77802:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 304 previous similar messages [ 3650.339886] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug -1 all [ 3650.693645] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug -1 all [ 3651.175023] Lustre: lustre-MDT0001: Recovery over after 0:06, of 3 clients 3 recovered and 0 were evicted. [ 3651.186874] Lustre: Skipped 12 previous similar messages [ 3651.262624] Lustre: 77802:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff99c3c11e6300 x1876717753946752/t21474836483(0) o36->8f0f7804-f3fd-45d1-b59c-eb1f56a8f568@192.168.206.15@tcp:26/0 lens 496/2888 e 0 to 0 dl 1789781131 ref 1 fl Interpret:/202/0 rc 0/0 job:'rmdir.0' uid:0 gid:0 projid:4294967295 [ 3651.275932] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:100 to 0x280000400:161) [ 3651.278523] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:100 to 0x2c0000400:161) [ 3659.536656] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1923 to 0x2c0000401:1985) [ 3659.537479] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1923 to 0x280000401:1985) [ 3664.478605] Lustre: DEBUG MARKER: oleg615-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 [ 3666.186936] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3667.811915] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3676.526560] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3679.677558] Lustre: Failing over lustre-MDT0000 [ 3680.224802] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3680.237162] LustreError: Skipped 2 previous similar messages [ 3680.243721] 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 [ 3680.254478] Lustre: Skipped 45 previous similar messages [ 3680.272306] Lustre: server umount lustre-MDT0000 complete [ 3701.858623] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3701.860745] LDISKFS-fs (dm-0): recovery complete [ 3701.874601] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3707.873062] Lustre: 3649:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789781023/real 1789781023] req@ffff99c38613c380 x1876717771431808/t0(0) o400->lustre-MDT0001-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1789781108 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3707.896598] Lustre: 3649:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 20 previous similar messages [ 3708.921329] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x3397d59de416d2bc [ 3709.422092] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 3709.438036] Lustre: Skipped 13 previous similar messages [ 3714.074706] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug -1 all [ 3714.790441] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1987 to 0x280000401:2017) [ 3714.791204] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1987 to 0x2c0000401:2017) [ 3724.338334] Lustre: DEBUG MARKER: oleg615-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3726.197282] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3734.788672] Lustre: DEBUG MARKER: == replay-dual test 23c: c1 rmdir d1, M0 drop update reply and fail M0, c2 mkdir d1 ========================================================== 21:25:33 (1789781133) [ 3736.278384] Lustre: *** cfs_fail_loc=1701, val=2147483648*** [ 3736.283408] LustreError: 8443:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff99c3a5f2c700 x1876717771510272/t137438953491(0) o1000->lustre-MDT0001-mdtlov_UUID@0@lo:42/0 lens 1984/4320 e 0 to 0 dl 1789781147 ref 1 fl Interpret:/200/0 rc 0/0 job:'osp_up0-1.0' uid:0 gid:0 projid:4294967295 [ 3740.005743] Lustre: Failing over lustre-MDT0000 [ 3740.158171] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3740.165460] Lustre: Skipped 3 previous similar messages [ 3740.581645] Lustre: server umount lustre-MDT0000 complete [ 3759.534426] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3759.747399] LustreError: MGC192.168.206.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3759.774241] LustreError: Skipped 9 previous similar messages [ 3764.843280] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug -1 all [ 3765.321624] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1987 to 0x280000401:2049) [ 3765.325174] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1987 to 0x2c0000401:2049) [ 3774.899097] Lustre: DEBUG MARKER: oleg615-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3776.453229] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3787.008367] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3789.187194] Lustre: Failing over lustre-MDT0000 [ 3789.500882] Lustre: server umount lustre-MDT0000 complete [ 3812.241149] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3812.243488] LDISKFS-fs (dm-0): recovery complete [ 3812.252771] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3821.745741] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug -1 all [ 3822.132027] Lustre: 83216:0:(ldlm_lib.c:2110:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3822.143721] Lustre: 83216:0:(ldlm_lib.c:2110:extend_recovery_timer()) Skipped 17 previous similar messages [ 3822.264059] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2051 to 0x2c0000401:2081) [ 3822.264560] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2051 to 0x280000401:2081) [ 3830.009747] Lustre: DEBUG MARKER: oleg615-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3831.538925] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3840.893801] Lustre: DEBUG MARKER: == replay-dual test 23d: c1 rmdir d1, M0 drop update reply and fail M0/M1, c2 mkdir d1 ========================================================== 21:27:18 (1789781238) [ 3845.903699] Lustre: *** cfs_fail_loc=1701, val=2147483648*** [ 3845.911419] LustreError: 8442:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff99c3861f1f80 x1876717771583104/t146028888081(0) o1000->lustre-MDT0001-mdtlov_UUID@0@lo:152/0 lens 1984/4320 e 0 to 0 dl 1789781257 ref 1 fl Interpret:/200/0 rc 0/0 job:'osp_up0-1.0' uid:0 gid:0 projid:4294967295 [ 3850.373913] Lustre: Failing over lustre-MDT0000 [ 3850.926464] Lustre: server umount lustre-MDT0000 complete [ 3854.366185] LustreError: 6504:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1789781255 with bad export cookie 3717674891530919802 [ 3854.371272] Lustre: Failing over lustre-MDT0001 [ 3854.372909] LustreError: 6504:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 3854.393477] LustreError: 84452:0:(ldlm_resource.c:1207:ldlm_resource_complain()) lustre-MDT0000-osp-MDT0001: namespace resource [0x2000013a1:0x80:0x0].0x0 (ffff99c3a0bd7700) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 3854.418301] Lustre: lustre-MDT0001: Not available for connect from 192.168.206.15@tcp (stopping) [ 3860.197363] Lustre: server umount lustre-MDT0001 complete [ 3881.482134] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3881.514940] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3881.852996] LustreError: 85160:0:(llog.c:1655:llog_backup()) MGC192.168.206.115@tcp: failed to open log lustre-sptlrpc: rc = -108 [ 3881.859726] Lustre: 85160:0:(mgc_request_server.c:770:mgc_llog_local_copy()) MGC192.168.206.115@tcp: failed to copy new config lustre-sptlrpc: rc = -108 [ 3900.350753] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 3900.360262] Lustre: Skipped 11 previous similar messages [ 3905.344937] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug -1 all [ 3905.630873] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug -1 all [ 3906.035798] Lustre: lustre-MDT0001-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 3906.047159] Lustre: Skipped 49 previous similar messages [ 3906.202856] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2051 to 0x2c0000401:2113) [ 3906.210630] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2051 to 0x280000401:2113) [ 3906.393255] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:100 to 0x280000400:193) [ 3906.398714] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:100 to 0x2c0000400:193) [ 3906.421814] Lustre: 85192:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff99c3bb3e8a80 x1876717754023808/t25769803783(0) o36->8f0f7804-f3fd-45d1-b59c-eb1f56a8f568@192.168.206.15@tcp:282/0 lens 496/2888 e 0 to 0 dl 1789781387 ref 1 fl Interpret:/202/0 rc 0/0 job:'rmdir.0' uid:0 gid:0 projid:4294967295 [ 3916.349573] Lustre: DEBUG MARKER: oleg615-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 [ 3918.378420] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3920.104574] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3930.587747] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3933.038713] Lustre: Failing over lustre-MDT0000 [ 3933.282212] Lustre: server umount lustre-MDT0000 complete [ 3956.325631] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3956.329801] LDISKFS-fs (dm-0): recovery complete [ 3956.338888] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3966.595480] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug -1 all [ 3968.309355] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2115 to 0x2c0000401:2145) [ 3968.314039] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2115 to 0x280000401:2145) [ 3976.476675] Lustre: DEBUG MARKER: oleg615-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3978.156286] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3987.079850] Lustre: DEBUG MARKER: == replay-dual test 24: reconstruct on non-existing object ========================================================== 21:29:45 (1789781385) [ 3988.140456] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 3988.147463] LustreError: 85192:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff99c388ff1500 x1876717754064640/t154618822673(0) o36->8f0f7804-f3fd-45d1-b59c-eb1f56a8f568@192.168.206.15@tcp:363/0 lens 488/456 e 0 to 0 dl 1789781468 ref 1 fl Interpret:/200/0 rc 0/0 job:'truncate.0' uid:0 gid:0 projid:4294967295 [ 4073.254562] Lustre: lustre-MDT0000: Client 8f0f7804-f3fd-45d1-b59c-eb1f56a8f568 (at 192.168.206.15@tcp) reconnecting [ 4073.282709] Lustre: 85172:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff99c39f2e7800 x1876717754064640/t154618822673(0) o36->8f0f7804-f3fd-45d1-b59c-eb1f56a8f568@192.168.206.15@tcp:448/0 lens 488/3152 e 0 to 0 dl 1789781553 ref 1 fl Interpret:/202/0 rc 0/0 job:'truncate.0' uid:0 gid:0 projid:4294967295 [ 4080.567423] Lustre: DEBUG MARKER: == replay-dual test 25: replay|resend ==================== 21:31:18 (1789781478) [ 4082.312862] Lustre: *** cfs_fail_loc=304, val=0*** [ 4084.345770] Lustre: Failing over lustre-OST0000 [ 4085.755567] Lustre: lustre-OST0000: Not available for connect from 0@lo (stopping) [ 4085.770298] Lustre: Skipped 7 previous similar messages [ 4086.513389] Lustre: server umount lustre-OST0000 complete [ 4105.093674] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4106.804898] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 4 clients reconnect [ 4106.813828] Lustre: Skipped 10 previous similar messages [ 4111.546808] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug -1 all [ 4120.743644] Lustre: DEBUG MARKER: oleg615-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 4122.398321] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4131.895853] Lustre: DEBUG MARKER: == replay-dual test 26: dbench and tar with mds failover ========================================================== 21:32:10 (1789781530) [ 4141.885339] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4145.468349] Lustre: DEBUG MARKER: test_26 fail mds1 1 times [ 4147.531493] Lustre: Failing over lustre-MDT0000 [ 4150.024117] Lustre: lustre-MDT0000: Not available for connect from 192.168.206.15@tcp (stopping) [ 4150.049044] Lustre: Skipped 4 previous similar messages [ 4152.863147] Lustre: server umount lustre-MDT0000 complete [ 4176.765774] LDISKFS-fs (dm-0): 3 truncates cleaned up [ 4176.769923] LDISKFS-fs (dm-0): recovery complete [ 4176.787766] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4182.500233] LustreError: 3646:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff99c382ab4e00 x1876717771792640/t0(0) o250->MGC192.168.206.115@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 [ 4182.521479] LustreError: 3646:0:(client.c:1404:ptlrpc_import_delay_req()) Skipped 8 previous similar messages [ 4187.562404] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug -1 all [ 4188.146894] Lustre: 91308:0:(ldlm_lib.c:2110:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 4188.176502] Lustre: 91308:0:(ldlm_lib.c:2110:extend_recovery_timer()) Skipped 17 previous similar messages [ 4190.787328] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2177 to 0x280000401:2209) [ 4190.794271] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2176 to 0x2c0000401:2209) [ 4198.926666] Lustre: DEBUG MARKER: oleg615-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4201.048991] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4215.333714] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 4219.659973] Lustre: DEBUG MARKER: test_26 fail mds2 2 times [ 4221.809058] Lustre: Failing over lustre-MDT0001 [ 4223.968684] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 4223.985745] LustreError: Skipped 3 previous similar messages [ 4224.211709] Lustre: server umount lustre-MDT0001 complete [ 4244.472145] LustreError: 85170:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4244.494763] LustreError: 85170:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 255 previous similar messages [ 4244.805434] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 4244.809118] LDISKFS-fs (dm-1): recovery complete [ 4244.821603] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4250.354094] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug -1 all [ 4252.600648] Lustre: lustre-MDT0001: Recovery over after 0:06, of 3 clients 3 recovered and 0 were evicted. [ 4252.611528] Lustre: Skipped 9 previous similar messages [ 4252.701201] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:272 to 0x280000400:289) [ 4252.702864] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:272 to 0x2c0000400:289) [ 4261.384071] Lustre: DEBUG MARKER: oleg615-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 4263.546493] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4275.766353] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4279.530394] Lustre: DEBUG MARKER: test_26 fail mds1 3 times [ 4281.580322] Lustre: Failing over lustre-MDT0000 [ 4281.598475] 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 [ 4281.619509] Lustre: Skipped 30 previous similar messages [ 4281.626511] Lustre: lustre-MDT0000: Not available for connect from 192.168.206.15@tcp (stopping) [ 4281.639062] Lustre: Skipped 7 previous similar messages [ 4281.997159] Lustre: server umount lustre-MDT0000 complete [ 4304.322370] LDISKFS-fs (dm-0): 3 truncates cleaned up [ 4304.325847] LDISKFS-fs (dm-0): recovery complete [ 4304.335263] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4313.588873] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x3397d59de4186a60 [ 4314.028375] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4314.044145] Lustre: Skipped 8 previous similar messages [ 4318.329473] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug -1 all [ 4321.184668] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2304 to 0x2c0000401:2337) [ 4321.187359] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2304 to 0x280000401:2337) [ 4328.465624] Lustre: DEBUG MARKER: oleg615-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4330.234086] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4376.110327] Lustre: DEBUG MARKER: == replay-dual test 28: lock replay should be ordered: waiting after granted ========================================================== 21:36:14 (1789781774) [ 4389.338686] Lustre: Failing over lustre-OST0000 [ 4389.488455] Lustre: server umount lustre-OST0000 complete [ 4407.136500] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4408.974770] Lustre: *** cfs_fail_loc=32a, val=0*** [ 4413.260968] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug -1 all [ 4422.099330] Lustre: DEBUG MARKER: oleg615-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 4423.731561] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4432.849953] Lustre: DEBUG MARKER: == replay-dual test 29: replay vs update with the same xid ========================================================== 21:37:11 (1789781831) [ 4433.946877] Lustre: DEBUG MARKER: SKIP: replay-dual test_29 needs >= 2 clients [ 4435.526604] Lustre: DEBUG MARKER: == replay-dual test 30: layout lock replay is not blocked on IO ========================================================== 21:37:13 (1789781833) [ 4438.491339] Lustre: Failing over lustre-MDT0000 [ 4438.808660] Lustre: server umount lustre-MDT0000 complete [ 4459.552823] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4459.774449] LustreError: MGC192.168.206.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4459.785249] LustreError: Skipped 5 previous similar messages [ 4464.602652] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug -1 all [ 4468.076044] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2361 to 0x2c0000401:2401) [ 4468.079074] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2361 to 0x280000401:2401) [ 4473.104979] Lustre: DEBUG MARKER: oleg615-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4474.724248] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4483.050455] Lustre: DEBUG MARKER: == replay-dual test 31: deadlock on file_remove_privs and occupied mod rpc slots ========================================================== 21:38:01 (1789781881) [ 4486.734374] Lustre: Failing over lustre-OST0000 [ 4486.918184] Lustre: server umount lustre-OST0000 complete [ 4505.132489] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4505.460539] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 4505.476899] Lustre: Skipped 8 previous similar messages [ 4506.869714] Lustre: lustre-OST0000-osc-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4506.875247] Lustre: Skipped 29 previous similar messages [ 4511.857158] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug -1 all [ 4521.579893] Lustre: DEBUG MARKER: oleg615-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 4523.198129] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in IDLE [ 4533.459314] Lustre: DEBUG MARKER: == replay-dual test 32: gap in update llog shouldn't break recovery ========================================================== 21:38:51 (1789781931) [ 4534.520404] Lustre: *** cfs_fail_loc=131d, val=10*** [ 4535.127081] Lustre: *** cfs_fail_loc=131d, val=4294967292*** [ 4535.131867] Lustre: Skipped 13 previous similar messages [ 4536.173180] Lustre: *** cfs_fail_loc=131d, val=4294967272*** [ 4536.176239] Lustre: Skipped 19 previous similar messages [ 4538.164629] Lustre: Failing over lustre-MDT0001 [ 4538.592443] Lustre: server umount lustre-MDT0001 complete [ 4542.616643] Lustre: Failing over lustre-MDT0000 [ 4542.996780] Lustre: server umount lustre-MDT0000 complete [ 4550.543840] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4551.208173] Lustre: *** cfs_fail_loc=131d, val=4294967266*** [ 4551.212615] Lustre: Skipped 5 previous similar messages [ 4556.402487] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug -1 all [ 4564.034961] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4564.115543] Lustre: *** cfs_fail_loc=131d, val=4294967262*** [ 4564.118702] Lustre: Skipped 3 previous similar messages [ 4569.694985] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug -1 all [ 4569.713518] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:332 to 0x2c0000400:353) [ 4569.715524] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:332 to 0x280000400:353) [ 4569.803127] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2361 to 0x2c0000401:2433) [ 4569.805422] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2441 to 0x280000401:2529) [ 4581.853771] Lustre: DEBUG MARKER: == replay-dual test 33: Check for OBD_INCOMPAT_MULTI_RPCS in last_rcvd after abort_recovery ========================================================== 21:39:39 (1789781979) [ 4588.377058] Lustre: Failing over lustre-MDT0001 [ 4588.756525] Lustre: server umount lustre-MDT0001 complete [ 4609.183320] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4615.116102] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug -1 all [ 4624.036360] Lustre: DEBUG MARKER: oleg615-client.virtnet: executing wait_import_state_mount REPLAY_WAIT mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 4625.599366] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in REPLAY_WAIT state after 0 sec [ 4626.659909] Lustre: lustre-MDT0001: Aborting client recovery [ 4626.664262] LustreError: 104027:0:(ldlm_lib.c:3029:target_stop_recovery_thread()) lustre-MDT0001: Aborting recovery [ 4626.669379] Lustre: 103392:0:(ldlm_lib.c:2429:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 4626.677556] Lustre: 103392:0:(ldlm_lib.c:2429:target_recovery_overseer()) Skipped 2 previous similar messages [ 4626.682829] Lustre: 103392:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0001: disconnect stale client 9b624a1c-04bc-4ea7-807b-0a965a4558a1@ [ 4626.694686] Lustre: lustre-MDT0001: disconnecting 1 stale clients [ 4626.719188] Lustre: lustre-MDT0001-osd: cancel update llog [0x240000400:0x1:0x0] [ 4626.755844] Lustre: lustre-MDT0000-osp-MDT0001: cancel update llog [0x200000401:0x1:0x0] [ 4626.867750] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:332 to 0x2c0000400:385) [ 4626.869933] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:332 to 0x280000400:385) [ 4631.519384] Lustre: 3649:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789781947/real 1789781947] req@ffff99c39f585f80 x1876717772814848/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1789782032 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4631.561114] Lustre: 3649:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 15 previous similar messages [ 4632.947291] Lustre: DEBUG MARKER: oleg615-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 4634.371529] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4638.113596] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0001.recovery_status 1475 [ 4645.152803] Lustre: Failing over lustre-MDT0001 [ 4645.493156] Lustre: server umount lustre-MDT0001 complete [ 4654.337521] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4659.888343] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug -1 all [ 4660.252892] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:332 to 0x2c0000400:417) [ 4660.256925] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:332 to 0x280000400:417) [ 4667.824359] Lustre: DEBUG MARKER: oleg615-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 4669.614361] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4674.053969] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0001.recovery_status 1475 [ 4682.029139] Lustre: DEBUG MARKER: == replay-dual test complete, duration 4371 sec ========== 21:41:20 (1789782080) [ 4683.613931] Lustre: DEBUG MARKER: === replay-dual: start cleanup 21:41:21 (1789782081) === [ 4693.563526] Lustre: DEBUG MARKER: === replay-dual: finish cleanup 21:41:31 (1789782091) === [ 4695.286915] Lustre: Failing over lustre-MDT0000 [ 4695.577908] Lustre: server umount lustre-MDT0000 complete [ 4720.349297] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4723.465773] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 4723.474955] Lustre: Skipped 10 previous similar messages [ 4725.020289] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4863.500197] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 4863.504431] Lustre: 107173:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 9b624a1c-04bc-4ea7-807b-0a965a4558a1@ [ 4863.522209] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 4863.542796] Lustre: lustre-MDT0000: Recovery over after 2:20, of 3 clients 2 recovered and 1 was evicted. [ 4863.556593] Lustre: Skipped 8 previous similar messages [ 4863.627378] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2361 to 0x2c0000401:2465) [ 4863.627495] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2441 to 0x280000401:2561) [ 4868.785504] Lustre: DEBUG MARKER: oleg615-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4870.177521] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4879.328960] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4879.335835] LustreError: Skipped 5 previous similar messages [ 4879.345343] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4879.356753] Lustre: Skipped 1 previous similar message [ 4880.993554] Lustre: server umount lustre-MDT0000 complete [ 4884.960189] LustreError: 102142:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4884.974130] LustreError: 102142:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 163 previous similar messages [ 4888.476844] LustreError: 91917:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1789782289 with bad export cookie 3717674891531114129 [ 4888.490321] LustreError: 91917:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 4888.836599] Lustre: server umount lustre-MDT0001 complete [ 4908.196529] Lustre: server umount lustre-OST0000 complete [ 4926.908134] Lustre: server umount lustre-OST0001 complete [ 4944.720891] Lustre: DEBUG MARKER: oleg615-server.virtnet: executing unload_modules_local [ 4948.236457] Key type lgssc unregistered [ 4948.569696] LNet: 110121:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 4948.574258] LNetError: 110121:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 4948.603259] LNet: Removed LNI 192.168.206.115@tcp [ 4949.679208] Key type .llcrypt unregistered [ 4949.684750] Key type ._llcrypt unregistered