[ 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 588004952 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2399.988 MHz processor [ 0.000000] last_pfn = 0x146e00 max_arch_pfn = 0x400000000 [ 0.000000] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT [ 0.000000] last_pfn = 0xbffce max_arch_pfn = 0x400000000 [ 0.000000] found SMP MP-table at [mem 0x000f54b0-0x000f54bf] [ 0.000000] RAMDISK: [mem 0xbcc54000-0xbffbffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F52D0 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE247C 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE2318 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 0022D8 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE238C 000090 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE241C 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE2454 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe2318-0xbffe238b] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe2317] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe238c-0xbffe241b] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe241c-0xbffe2453] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe2454-0xbffe247b] [ 0.000000] No NUMA configuration found [ 0.000000] Faking a node at [mem 0x0000000000000000-0x0000000146dfffff] [ 0.000000] NODE_DATA(0) allocated [mem 0x1465a3000-0x1465cdfff] [ 0.000000] Reserving 256MB of memory at 2752MB for crashkernel (System RAM: 4205MB) [ 0.000000] Zone ranges: [ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.000000] DMA32 [mem 0x0000000001000000-0x00000000ffffffff] [ 0.000000] Normal [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Device empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff] [ 0.000000] node 0: [mem 0x0000000000100000-0x00000000bffcdfff] [ 0.000000] node 0: [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Zeroed struct page in unavailable ranges: 4756 pages [ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x0000000146dfffff] [ 0.000000] ACPI: PM-Timer IO Port: 0x608 [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) [ 0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) [ 0.000000] Using ACPI (MADT) for SMP configuration information [ 0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000] TSC deadline timer available [ 0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs [ 0.000000] kvm-guest: KVM setup pv remote TLB flush [ 0.000000] kvm-guest: setup PV sched yield [ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff] [ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff] [ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff] [ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff] [ 0.000000] PM: Registered nosave memory: [mem 0xbffce000-0xbfffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xc0000000-0xfeffbfff] [ 0.000000] PM: Registered nosave memory: [mem 0xfeffc000-0xfeffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xff000000-0xfffbffff] [ 0.000000] PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff] [ 0.000000] [mem 0xc0000000-0xfeffbfff] available for PCI devices [ 0.000000] Booting paravirtualized kernel on KVM [ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns [ 0.000000] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1 [ 0.000000] percpu: Embedded 63 pages/cpu s221184 r8192 d28672 u524288 [ 0.000000] kvm-guest: PV spinlocks enabled [ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1059606 [ 0.000000] Policy zone: Normal [ 0.000000] Kernel command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] Specific versions of hardware are certified with Red Hat Enterprise Linux 8. Please see the list of hardware certified with Red Hat Enterprise Linux 8 at https://catalog.redhat.com. [ 0.000000] audit: disabled (until reboot) [ 0.000000] software IO TLB: area num 4. [ 0.000000] Memory: 2829652K/4306352K available (18435K kernel code, 11221K rwdata, 7248K rodata, 2908K init, 18040K bss, 524588K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] ftrace: allocating 41240 entries in 162 pages [ 0.000000] ftrace: allocated 162 pages with 3 groups [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] rcu: RCU event tracing is enabled. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ 0.000000] rcu: RCU callback double-/use-after-free debug enabled. [ 0.000000] Rude variant of Tasks RCU enabled. [ 0.000000] Tracing variant of Tasks RCU enabled. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 0.000000] NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16 [ 0.000000] random: get_random_bytes called from start_kernel+0x622/0x9a8 with crng_init=0 [ 0.001000] Console: colour *CGA 80x25 [ 0.001000] printk: console [ttyS1] enabled [ 0.001000] ACPI: Core revision 20220331 [ 0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.001013] APIC: Switch to symmetric I/O mode setup [ 0.002352] x2apic enabled [ 0.003009] Switched APIC routing to physical x2apic. [ 0.004013] kvm-guest: setup PV IPIs [ 0.007741] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.008000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x22982c12b6d, max_idle_ns: 440795281273 ns [ 0.008000] Calibrating delay loop (skipped) preset value.. 4799.97 BogoMIPS (lpj=2399988) [ 0.008015] pid_max: default: 32768 minimum: 301 [ 0.009148] LSM: Security Framework initializing [ 0.010076] Yama: becoming mindful. [ 0.011063] SELinux: Initializing. [ 0.012080] *** VALIDATE selinux *** [ 0.021855] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.027482] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.028222] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.029135] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.031016] *** VALIDATE tmpfs *** [ 0.033722] *** VALIDATE proc *** [ 0.035218] *** VALIDATE cgroup *** [ 0.036011] *** VALIDATE cgroup2 *** [ 0.037343] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.038195] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.039022] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.040090] Spectre V2 : User space: Vulnerable [ 0.041015] Speculative Store Bypass: Vulnerable [ 0.045129] debug: unmapping init [mem 0xffffffff8e859000-0xffffffff8e860fff] [ 0.047370] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.048964] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.050044] ... version: 2 [ 0.051024] ... bit width: 48 [ 0.052123] ... generic registers: 4 [ 0.053037] ... value mask: 0000ffffffffffff [ 0.054027] ... max period: 00007fffffffffff [ 0.055025] ... fixed-purpose events: 3 [ 0.056037] ... event mask: 000000070000000f [ 0.057373] rcu: Hierarchical SRCU implementation. [ 0.060286] smp: Bringing up secondary CPUs ... [ 0.061705] x86: Booting SMP configuration: [ 0.062047] .... node #0, CPUs: #1 #2 #3 [ 0.073269] smp: Brought up 1 node, 4 CPUs [ 0.075024] smpboot: Max logical packages: 1 [ 0.076013] smpboot: Total of 4 processors activated (19199.90 BogoMIPS) [ 0.135364] node 0 deferred pages initialised in 57ms [ 0.144171] devtmpfs: initialized [ 0.147307] x86/mm: Memory block size: 128MB [ 0.152475] gcov: version magic: 0x41383552 [ 0.153328] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.158283] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.163489] pinctrl core: initialized pinctrl subsystem [ 0.172331] [ 0.173028] ************************************************************* [ 0.177026] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.180016] ** ** [ 0.183030] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.188023] ** ** [ 0.193030] ** This means that this kernel is built to expose internal ** [ 0.196023] ** IOMMU data structures, which may compromise security on ** [ 0.199023] ** your system. ** [ 0.203035] ** ** [ 0.207036] ** If you see this message and you are not debugging the ** [ 0.211028] ** kernel, report this immediately to your vendor! ** [ 0.215046] ** ** [ 0.217023] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.220019] ************************************************************* [ 0.239000] NET: Registered protocol family 16 [ 0.243527] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.247108] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.251136] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.256270] cpuidle: using governor menu [ 0.257863] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.261957] PCI: Using configuration type 1 for base access [ 0.265181] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.278059] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.283031] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.289117] cryptd: max_cpu_qlen set to 1000 [ 0.292631] ACPI: Added _OSI(Module Device) [ 0.293021] ACPI: Added _OSI(Processor Device) [ 0.296014] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.300015] ACPI: Added _OSI(Processor Aggregator Device) [ 0.308508] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.317652] ACPI: Interpreter enabled [ 0.320069] ACPI: PM: (supports S0 S3 S4 S5) [ 0.322025] ACPI: Using IOAPIC for interrupt routing [ 0.324093] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.328404] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.340052] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.343058] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.347032] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.351076] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.356920] acpiphp: Slot [2] registered [ 0.359287] acpiphp: Slot [5] registered [ 0.362196] acpiphp: Slot [6] registered [ 0.364526] acpiphp: Slot [7] registered [ 0.368164] acpiphp: Slot [8] registered [ 0.370457] acpiphp: Slot [9] registered [ 0.373170] acpiphp: Slot [10] registered [ 0.375226] acpiphp: Slot [3] registered [ 0.377150] acpiphp: Slot [4] registered [ 0.379176] acpiphp: Slot [11] registered [ 0.381225] acpiphp: Slot [12] registered [ 0.383166] acpiphp: Slot [13] registered [ 0.385155] acpiphp: Slot [14] registered [ 0.387157] acpiphp: Slot [15] registered [ 0.389144] acpiphp: Slot [16] registered [ 0.390128] acpiphp: Slot [17] registered [ 0.392129] acpiphp: Slot [18] registered [ 0.394118] acpiphp: Slot [19] registered [ 0.396228] acpiphp: Slot [20] registered [ 0.398104] acpiphp: Slot [21] registered [ 0.400108] acpiphp: Slot [22] registered [ 0.401141] acpiphp: Slot [23] registered [ 0.403173] acpiphp: Slot [24] registered [ 0.405101] acpiphp: Slot [25] registered [ 0.407137] acpiphp: Slot [26] registered [ 0.409196] acpiphp: Slot [27] registered [ 0.411184] acpiphp: Slot [28] registered [ 0.413139] acpiphp: Slot [29] registered [ 0.415162] acpiphp: Slot [30] registered [ 0.417109] acpiphp: Slot [31] registered [ 0.419073] PCI host bridge to bus 0000:00 [ 0.420023] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.423026] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.425019] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.427028] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.438034] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.442038] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.444237] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.447127] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.449488] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.465803] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.472013] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.475022] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.477022] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.481025] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.487279] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.491256] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.495060] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.499297] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.509018] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.529036] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.537025] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.545896] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.559035] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.573021] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.603022] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.622019] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.633022] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.639025] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.665022] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.682747] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.686023] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.696016] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.726021] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.738802] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.745027] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.759016] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.793020] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.810711] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.821026] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.831017] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.854021] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 0.867552] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.873015] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.880021] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.900022] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 0.913866] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.915391] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.917453] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.923010] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.926274] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.932056] iommu: Default domain type: Passthrough [ 0.933473] SCSI subsystem initialized [ 0.934112] ACPI: bus type USB registered [ 0.935131] usbcore: registered new interface driver usbfs [ 0.937103] usbcore: registered new interface driver hub [ 0.938080] usbcore: registered new device driver usb [ 0.940126] pps_core: LinuxPPS API ver. 1 registered [ 0.942014] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.946167] PTP clock support registered [ 0.948247] EDAC MC: Ver: 3.0.0 [ 0.950069] PCI: Using ACPI for IRQ routing [ 0.950529] NetLabel: Initializing [ 0.951008] NetLabel: domain hash size = 128 [ 0.953010] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.955083] NetLabel: unlabeled traffic allowed by default [ 0.958113] vgaarb: loaded [ 0.960035] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.962013] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.970893] clocksource: Switched to clocksource kvm-clock [ 1.111975] VFS: Disk quotas dquot_6.6.0 [ 1.113510] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 1.115533] *** VALIDATE ramfs *** [ 1.116208] *** VALIDATE hugetlbfs *** [ 1.117155] pnp: PnP ACPI init [ 1.119643] pnp: PnP ACPI: found 6 devices [ 1.141583] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 1.145065] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 1.147509] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 1.149987] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 1.152752] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 1.155122] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 1.158030] NET: Registered protocol family 2 [ 1.160411] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 1.166102] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 1.180541] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 1.192919] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 1.200201] TCP: Hash tables configured (established 65536 bind 65536) [ 1.207598] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 1.212933] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 1.218646] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 1.226868] NET: Registered protocol family 1 [ 1.234859] RPC: Registered named UNIX socket transport module. [ 1.237573] RPC: Registered udp transport module. [ 1.239138] RPC: Registered tcp transport module. [ 1.241316] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 1.243611] NET: Registered protocol family 44 [ 1.245763] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 1.247987] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 1.250841] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 1.253329] PCI: CLS 0 bytes, default 64 [ 1.255494] Unpacking initramfs... [ 3.141669] debug: unmapping init [mem 0xffff89217cc54000-0xffff89217ffbffff] [ 3.146229] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 3.148418] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 3.151391] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x22982c12b6d, max_idle_ns: 440795281273 ns [ 4.451845] Initialise system trusted keyrings [ 4.453633] Key type blacklist registered [ 4.455694] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 4.465285] zbud: loaded [ 4.468251] *** VALIDATE nfs *** [ 4.469548] *** VALIDATE nfs4 *** [ 4.471230] pstore: using deflate compression [ 4.488571] Platform Keyring initialized [ 4.658364] NET: Registered protocol family 38 [ 4.660969] Key type asymmetric registered [ 4.666382] Asymmetric key parser 'x509' registered [ 4.669023] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 4.677197] io scheduler mq-deadline registered [ 4.682401] io scheduler kyber registered [ 4.685702] io scheduler bfq registered [ 4.690443] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 4.696471] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 4.702462] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 4.706520] ACPI: Power Button [PWRF] [ 4.713096] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 4.721597] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 4.741683] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 4.753115] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 4.781277] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 4.813301] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 4.844774] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 4.850242] Non-volatile memory driver v1.3 [ 4.852390] Linux agpgart interface v0.103 [ 4.892681] virtio_blk virtio1: [vda] 135992 512-byte logical blocks (69.6 MB/66.4 MiB) [ 4.895993] vda: detected capacity change from 0 to 69627904 [ 4.936483] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 4.940653] vdb: detected capacity change from 0 to 1073741824 [ 4.960194] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 4.963072] vdc: detected capacity change from 0 to 2621440000 [ 4.981448] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 4.985078] vdd: detected capacity change from 0 to 2621440000 [ 5.009403] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 5.013292] vde: detected capacity change from 0 to 4294967296 [ 5.032419] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 5.035467] vdf: detected capacity change from 0 to 4294967296 [ 5.048431] libphy: Fixed MDIO Bus: probed [ 5.057697] usbcore: registered new interface driver usbserial_generic [ 5.066953] usbserial: USB Serial support registered for generic [ 5.072851] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 5.108666] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 5.112778] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 5.117805] mousedev: PS/2 mouse device common for all mice [ 5.124774] rtc_cmos 00:05: RTC can wake from S4 [ 5.149161] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 5.150372] rtc_cmos 00:05: registered as rtc0 [ 5.156768] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 5.161721] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 5.165819] intel_pstate: CPU model not supported [ 5.170169] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 5.174202] hid: raw HID events driver (C) Jiri Kosina [ 5.177081] usbcore: registered new interface driver usbhid [ 5.179817] usbhid: USB HID core driver [ 5.181691] drop_monitor: Initializing network drop monitor service [ 5.184456] Initializing XFRM netlink socket [ 5.186798] NET: Registered protocol family 10 [ 5.191142] Segment Routing with IPv6 [ 5.192852] NET: Registered protocol family 17 [ 5.201508] mpls_gso: MPLS GSO support [ 5.236769] RAS: Correctable Errors collector initialized. [ 5.240337] AVX version of gcm_enc/dec engaged. [ 5.242854] AES CTR mode by8 optimization enabled [ 5.359585] sched_clock: Marking stable (5359566390, 0)->(6597428853, -1237862463) [ 5.363454] registered taskstats version 1 [ 5.365308] Loading compiled-in X.509 certificates [ 5.368401] zswap: loaded using pool lzo/zbud [ 5.411180] Key type big_key registered [ 5.437371] Key type encrypted registered [ 5.438941] ima: No TPM chip found, activating TPM-bypass! [ 5.441408] ima: Allocated hash algorithm: sha1 [ 5.443281] ima: No architecture policies found [ 5.444962] evm: Initialising EVM extended attributes: [ 5.446810] evm: security.selinux [ 5.447939] evm: security.ima [ 5.449342] evm: security.capability [ 5.450622] evm: HMAC attrs: 0x1 [ 5.454545] rtc_cmos 00:05: setting system clock to 2026-06-02 06:07:16 UTC (1780380436) [ 5.464517] debug: unmapping init [mem 0xffffffff8f803000-0xffffffff8f9fffff] [ 5.468818] debug: unmapping init [mem 0xffffffff8e582000-0xffffffff8e858fff] [ 5.480266] Write protecting the kernel read-only data: 28672k [ 5.483993] debug: unmapping init [mem 0xffffffff8cc03000-0xffffffff8cdfffff] [ 5.487331] debug: unmapping init [mem 0xffffffff8d514000-0xffffffff8d5fffff] [ 5.587474] 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) [ 5.604759] systemd[1]: Detected virtualization kvm. [ 5.608344] systemd[1]: Detected architecture x86-64. [ 5.612781] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 5.662811] systemd[1]: No hostname configured. [ 5.667326] systemd[1]: Set hostname to . [ 5.671344] random: systemd: uninitialized urandom read (16 bytes read) [ 5.676567] systemd[1]: Initializing machine ID from random generator. [ 5.868437] random: ln: uninitialized urandom read (6 bytes read) [ 6.493461] random: systemd: uninitialized urandom read (16 bytes read) [ 6.496649] systemd[1]: Reached target Swap. [ OK ] Reached target Swap. [ 6.550371] systemd[1]: Reached target Local File Systems. [ OK ] Reached target Local File Systems. [ 6.556708] systemd[1]: Listening on Journal Socket (/dev/log). [ OK ] Listening on Journal Socket (/dev/log). [ OK ] Listening on Journal Socket. [ OK ] Started Memstrack Anylazing Service. Starting Create Volatile Files and Directories... [ 6.715425] urandom_read: 5 callbacks suppressed [ 6.715446] random: systemd: uninitialized urandom read (16 bytes read) Starting Setup Virtual Console... [ 6.813071] random: systemd: uninitialized urandom read (16 bytes read) Starting Journal Service... [ OK ] Reached target Slices. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Listening on udev Control Socket. [ OK ] Reached target Initrd Root Device. [ OK ] Listening on udev Kernel Socket. [ OK ] Reached target Sockets. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Paths. Starting Apply Kernel Variables... [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Timers. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Setup Virtual Console. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Journal Service. [ OK ] Started Apply Kernel Variables. Starting Create Static Device Nodes in /dev... Starting dracut cmdline hook... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 9.093656] device-mapper: uevent: version 1.0.3 [ 9.103897] 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. [ 11.036677] random: fast init done [ 12.934919] virtio_net virtio0 ens2: renamed from eth0 [ 13.502991] scsi host0: ata_piix [ 13.540029] scsi host1: ata_piix [ 13.548858] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 13.551830] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 Starting dracut initqueue hook... [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ 20.073774] random: crng init done [ 20.260924] dracut-initqueue[569]: RTNETLINK answers: File exists Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. Mounting /sysroot... [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. [ 22.058833] 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 Paths. [ OK ] Stopped target Sockets. [ OK ] Stopped target Slices. [ OK ] Stopped target System Initialization. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped target Swap. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. Stopping udev Kernel Device Manager... [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Closed udev Control Socket. [ OK ] Closed udev Kernel Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 24.385737] printk: systemd: 22 output lines suppressed due to ratelimiting [ 24.975252] SELinux: Disabled at runtime. [ 25.051115] 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) [ 25.070217] systemd[1]: Detected virtualization kvm. [ 25.077993] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 26.235433] systemd[1]: initrd-switch-root.service: Succeeded. [ 26.245432] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 26.256261] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 26.277451] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 26.283529] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 26.320435] systemd[1]: Starting Journal Service... Starting Journal Service... [ 26.356289] systemd[1]: Mounting Kernel Debug File System... Mounting Kernel Debug File System... Mounting POSIX Message Queue File System... [ OK ] Stopped target Switch Root. [ OK ] Created slice User and Session Slice. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Created slice system-sshd\x2dkeygen.slice. Starting Apply Kernel Variables... [ OK ] Reached target rpc_pipefs.target. [ OK ] Listening on Process Core Dump Socket. [ OK ] Stopped target Initrd Root File System. [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Reached target RPC Port Mapper. [ OK ] Reached target Paths. [ OK ] Listening on udev Control Socket. [ OK ] Listening on udev Kernel Socket. Starting udev Coldplug all Devices... [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Slices. Activating swap /dev/disk/by-label/SWAP... [ OK ] Created slice system-getty.slice. [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Stopped target Initrd File Systems. [ 27.008954] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS Starting Remount Root and Kernel File Systems... Mounting Huge Pages File System... [ OK ] Mounted Kernel Debug File System. [ 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. [ OK ] Activated swap /dev/disk/by-label/SWAP. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Mounted Huge Pages File System. [ OK ] Started Journal Service. Starting Flush Journal to Persistent Storage... Starting Configure read-only root support... [ OK ] Reached target Swap. Starting Create Static Device Nodes in /dev... [ OK ] Started udev Coldplug all Devices. [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. Starting udev Kernel Device Manager... [ OK ] Reached target Local File Systems (Pre). Mounting /home/green/git/lustre-release... Mounting /mnt... [ OK ] Mounted /mnt. [ 28.399024] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 30.825423] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 31.242081] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 32.506194] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 32.547582] 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 (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)[ 37.733295] Key type dns_resolver registered [ ***] A start job is running for Configur…only root support (11s / no limit)[ 38.354442] NFS: Registering the id_resolver key type [ 38.356604] Key type id_resolver registered [ 38.358360] Key type id_legacy registered [ **] A start job is running for Configur…only root support (12s / no limit) [ OK ] Started Configure read-only root support. Starting Load/Save Random Seed... [ 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... [ OK ] Started Load/Save Random Seed. [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Create Volatile Files and Directories. Starting RPC Bind... Starting Update UTMP about System Boot/Shutdown... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. [ OK ] Started D-Bus System Message Bus. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting Network Manager... [ OK ] Started irqbalance daemon. [ OK ] Reached target sshd-keygen.target. Starting Restore /run/initramfs on shutdown... Starting Login Service... [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Started dnf makecache --timer. [ OK ] Reached target Timers. [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Network Manager. Starting Network Manager Wait Online... [ OK ] Reached target Network. Starting Dynamic System Tuning Daemon... Starting GSSAPI Proxy Daemon... Starting OpenSSH server daemon... [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Started Login Service. Starting Hostname Service... [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... [ OK ] Started OpenSSH server daemon. [ OK ] Started Permit User Sessions. [ OK ] Started Getty on tty1. [ OK ] Started Command Scheduler. [ OK ] Started Serial Getty on ttyS1. [ OK ] Started Serial Getty on ttyS0. [ OK ] Reached target Login Prompts. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting Notify NFS peers of a restart... Starting System Logging Service... Starting Crash recovery kernel arming... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg425-server login: [ 63.671406] hrtimer: interrupt took 6432670 ns [ 95.366249] libcfs: loading out-of-tree module taints kernel. [ 95.455934] Key type ._llcrypt registered [ 95.467787] Key type .llcrypt registered [ 95.588143] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_hostid [ 107.836920] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing load_modules_local [ 108.602866] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 108.614982] alg: No test for adler32 (adler32-zlib) [ 109.759076] Lustre: Lustre: Build Version: 2.17.53_57_ge5fd5c2 [ 110.181608] LNet: Added LNI 192.168.204.125@tcp [8/256/0/180] [ 111.840626] Key type lgssc registered [ 112.663666] Lustre: Echo OBD driver; http://www.lustre.org/ [ 122.212130] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 147.409801] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing load_modules_local [ 156.003556] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 156.032488] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 157.313719] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 157.355414] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 157.411808] Lustre: lustre-MDT0000: new disk, initializing [ 157.468239] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 157.481912] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 160.260346] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 171.277638] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 171.477263] Lustre: 6483:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 171.514960] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 171.519948] Lustre: Skipped 1 previous similar message [ 171.647299] Lustre: lustre-MDT0001: new disk, initializing [ 171.854972] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 171.930581] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 171.964608] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 178.004525] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 185.419218] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 199.988764] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 200.424574] Lustre: lustre-OST0000: new disk, initializing [ 200.429303] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 200.443045] Lustre: 8388:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 200.590367] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 206.350772] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 206.363291] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 206.409409] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 211.154118] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 228.911304] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 229.041093] Lustre: lustre-OST0001: new disk, initializing [ 229.044804] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 229.055292] Lustre: 9444:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 229.123594] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 235.854227] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 238.639304] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 238.655651] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 238.736302] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 252.115291] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 261.615272] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 269.152648] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing check_logdir /tmp/testlogs/ [ 274.464437] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing yml_node [ 279.209868] Lustre: DEBUG MARKER: Client: 2.17.53.57 [ 282.153610] Lustre: DEBUG MARKER: MDS: 2.17.53.57 [ 285.492368] Lustre: DEBUG MARKER: OSS: 2.17.53.57 [ 287.688891] Lustre: DEBUG MARKER: -----============= acceptance-small: replay-dual ============----- Tue Jun 2 02:11:57 EDT 2026 [ 307.253650] Lustre: DEBUG MARKER: excepting tests: 14b 21b [ 308.714788] Lustre: DEBUG MARKER: skipping tests SLOW=no: 21b [ 310.416857] Lustre: DEBUG MARKER: === replay-dual: start setup 02:12:20 (1780380740) === [ 315.836094] Lustre: DEBUG MARKER: oleg425-client.virtnet: executing check_config_client /mnt/lustre [ 336.523702] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 340.464069] Lustre: 13205:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 344.857655] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 350.914881] Lustre: DEBUG MARKER: === replay-dual: finish setup 02:13:01 (1780380781) === [ 353.152373] Lustre: DEBUG MARKER: == replay-dual test 0a: expired recovery with lost client ========================================================== 02:13:03 (1780380783) [ 361.545453] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 365.368708] Lustre: Failing over lustre-MDT0000 [ 365.660334] Lustre: server umount lustre-MDT0000 complete [ 366.561016] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 366.566466] 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 [ 371.685954] LustreError: 6490:0:(ldlm_lib.c:1179: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. [ 371.709072] LustreError: 6490:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 10 previous similar messages [ 372.901113] LustreError: 9315:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.204.25@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 372.938324] LustreError: 9315:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 1 previous similar message [ 376.801272] LustreError: 11004:0:(ldlm_lib.c:1179: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. [ 376.820522] LustreError: 11004:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 3 previous similar messages [ 381.935839] LustreError: 9315:0:(ldlm_lib.c:1179: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. [ 381.984966] LustreError: 9315:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 5 previous similar messages [ 382.943163] Lustre: 3639:0:(client.c:2480:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1780380797/real 1780380797] req@ffff8920c3c1c000 x1866864306286592/t0(0) o400->MGC192.168.204.125@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1780380813 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 382.974583] LustreError: MGC192.168.204.125@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 388.068889] LustreError: 6494:0:(ldlm_lib.c:1179: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. [ 388.101340] LustreError: 6494:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 11 previous similar messages [ 389.967896] LDISKFS-fs (dm-0): 10 truncates cleaned up [ 389.974282] LDISKFS-fs (dm-0): recovery complete [ 390.009700] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 393.212598] LustreError: 3636:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8921f36ad880 x1866864306296192/t0(0) o250->MGC192.168.204.125@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 [ 393.383318] Lustre: lustre-MDT0000: Not available for connect from 192.168.204.25@tcp (not set up) [ 393.405143] Lustre: Skipped 1 previous similar message [ 393.601806] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 395.475952] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 398.838693] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 399.125566] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 501.500292] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 501.510389] Lustre: 14735:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 549c1229-1f36-4ec7-a288-c1a202f4fd42@192.168.204.25@tcp [ 501.522371] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 501.543377] Lustre: lustre-MDT0000-osp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 501.548283] Lustre: 14735:0:(ldlm_lib.c:2932:target_recovery_thread()) too long recovery - read logs [ 501.560409] Lustre: Skipped 2 previous similar messages [ 501.566429] LustreError: dumping log to /tmp/lustre-log.1780380932.14735 [ 501.635579] Lustre: lustre-MDT0000: Recovery over after 1:46, of 3 clients 2 recovered and 1 was evicted. [ 501.685775] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:28 to 0x2c0000401:65) [ 501.688132] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:28 to 0x280000401:65) [ 526.263194] Lustre: DEBUG MARKER: == replay-dual test 0b: lost client during waiting for next transno ========================================================== 02:15:56 (1780380956) [ 534.018516] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 536.282274] Lustre: Failing over lustre-MDT0000 [ 536.659737] Lustre: server umount lustre-MDT0000 complete [ 537.076992] 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 [ 537.093140] Lustre: Skipped 6 previous similar messages [ 537.097658] LustreError: 12633:0:(ldlm_lib.c:1179: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. [ 537.116430] LustreError: 12633:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 11 previous similar messages [ 553.440713] Lustre: 3637:0:(client.c:2480:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1780380968/real 1780380968] req@ffff8920c5136300 x1866864306368256/t0(0) o400->MGC192.168.204.125@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1780380984 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 553.487190] LustreError: MGC192.168.204.125@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 553.520890] LustreError: 6494:0:(ldlm_lib.c:1179: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. [ 553.565056] LustreError: 6494:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 18 previous similar messages [ 560.428965] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 560.431941] LDISKFS-fs (dm-0): recovery complete [ 560.444185] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 564.172361] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 565.920263] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 569.356303] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 569.801710] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 582.976417] Lustre: lustre-MDT0000: Denying connection for new client f27c121b-949f-4aac-a822-227ecd95cfad (at 192.168.204.25@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:52 [ 588.462036] Lustre: lustre-MDT0000: Denying connection for new client f27c121b-949f-4aac-a822-227ecd95cfad (at 192.168.204.25@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:47 [ 593.569260] Lustre: lustre-MDT0000: Denying connection for new client f27c121b-949f-4aac-a822-227ecd95cfad (at 192.168.204.25@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:41 [ 598.689440] Lustre: lustre-MDT0001: haven't heard from client 549c1229-1f36-4ec7-a288-c1a202f4fd42 (at 192.168.204.25@tcp) in 101 seconds. I think it's dead, and I am evicting it. exp ffff8920c1e49000, cur 1780381029 deadline 1780381028 last 1780380928 [ 598.690504] Lustre: lustre-MDT0000: Denying connection for new client f27c121b-949f-4aac-a822-227ecd95cfad (at 192.168.204.25@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:36 [ 603.804537] Lustre: lustre-MDT0000: Denying connection for new client f27c121b-949f-4aac-a822-227ecd95cfad (at 192.168.204.25@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:31 [ 614.046410] Lustre: lustre-MDT0000: Denying connection for new client f27c121b-949f-4aac-a822-227ecd95cfad (at 192.168.204.25@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:21 [ 614.072497] Lustre: Skipped 1 previous similar message [ 634.520786] Lustre: lustre-MDT0000: Denying connection for new client f27c121b-949f-4aac-a822-227ecd95cfad (at 192.168.204.25@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:00 [ 634.533853] Lustre: Skipped 3 previous similar messages [ 635.503073] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 635.520106] Lustre: 16460:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client e699882a-6397-423f-aef4-56a3cc0f4b39@ [ 635.533123] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 670.360754] Lustre: lustre-MDT0000: Denying connection for new client f27c121b-949f-4aac-a822-227ecd95cfad (at 192.168.204.25@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 1 evicted) to recover in 1:06 [ 670.383235] Lustre: Skipped 6 previous similar messages [ 675.481551] Lustre: lustre-MDT0001: haven't heard from client df203986-7c82-4239-9b84-61da3cfc760f (at 192.168.204.25@tcp) in 104 seconds. I think it's dead, and I am evicting it. exp ffff8920c1fc7800, cur 1780381106 deadline 1780381102 last 1780381002 [ 736.503717] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 736.508311] Lustre: 16460:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client df203986-7c82-4239-9b84-61da3cfc760f@192.168.204.25@tcp [ 736.517371] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 736.526806] Lustre: 16460:0:(ldlm_lib.c:2069:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 736.553493] Lustre: 16460:0:(ldlm_lib.c:2932:target_recovery_thread()) too long recovery - read logs [ 736.555665] Lustre: lustre-MDT0000-osp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 736.570909] LustreError: dumping log to /tmp/lustre-log.1780381167.16460 [ 736.574945] Lustre: Skipped 2 previous similar messages [ 736.703575] Lustre: lustre-MDT0000: Recovery over after 2:51, of 3 clients 1 recovered and 2 were evicted. [ 736.761502] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:28 to 0x2c0000401:97) [ 736.764097] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:28 to 0x280000401:97) [ 744.857112] Lustre: DEBUG MARKER: == replay-dual test 1: |X| simple create ================= 02:19:34 (1780381174) [ 753.523410] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 755.894450] Lustre: Failing over lustre-MDT0000 [ 756.216351] Lustre: server umount lustre-MDT0000 complete [ 757.220385] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 757.236682] 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 [ 757.276181] LustreError: 6494:0:(ldlm_lib.c:1179: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. [ 757.346267] LustreError: 6494:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 10 previous similar messages [ 774.117581] Lustre: 3640:0:(client.c:2480:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1780381189/real 1780381189] req@ffff8921c82f8a80 x1866864306464000/t0(0) o400->MGC192.168.204.125@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1780381205 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 774.179975] LustreError: MGC192.168.204.125@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 780.074294] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 780.078770] LDISKFS-fs (dm-0): recovery complete [ 780.086743] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 784.375547] LustreError: 3636:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8921f63e1c00 x1866864306472448/t0(0) o250->MGC192.168.204.125@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 [ 784.832794] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 784.910890] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 785.137574] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 788.573366] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 790.010451] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 790.253105] Lustre: lustre-MDT0000: Recovery over after 0:05, of 3 clients 3 recovered and 0 were evicted. [ 790.309451] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:129) [ 790.312642] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:129) [ 797.964509] Lustre: DEBUG MARKER: oleg425-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 800.273376] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 809.963124] Lustre: DEBUG MARKER: == replay-dual test 2: |X| mkdir adir ==================== 02:20:40 (1780381240) [ 818.376599] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 820.299611] Lustre: Failing over lustre-MDT0000 [ 820.428397] Lustre: lustre-MDT0000: Not available for connect from 192.168.204.25@tcp (stopping) [ 820.438470] Lustre: Skipped 1 previous similar message [ 820.555809] Lustre: server umount lustre-MDT0000 complete [ 820.708563] 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 [ 820.725325] Lustre: Skipped 5 previous similar messages [ 825.498287] LustreError: 6490:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.204.25@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 825.521442] LustreError: 6490:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 41 previous similar messages [ 841.184886] Lustre: 3639:0:(client.c:2480:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1780381256/real 1780381256] req@ffff8921f28ec000 x1866864306499968/t0(0) o400->MGC192.168.204.125@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1780381272 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 841.224885] LustreError: MGC192.168.204.125@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 842.171237] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 842.174160] LDISKFS-fs (dm-0): recovery complete [ 842.180855] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 851.778270] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 851.830196] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 852.129976] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 855.671700] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 857.081328] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 857.096936] Lustre: Skipped 3 previous similar messages [ 857.185065] Lustre: lustre-MDT0000: Recovery over after 0:05, of 3 clients 3 recovered and 0 were evicted. [ 857.256889] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:161) [ 857.257748] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:161) [ 863.436305] Lustre: DEBUG MARKER: oleg425-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 865.349804] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 874.915507] Lustre: DEBUG MARKER: == replay-dual test 3: |X| mkdir adir, mkdir adir/bdir === 02:21:45 (1780381305) [ 884.505674] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 887.422258] Lustre: Failing over lustre-MDT0000 [ 887.786266] 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 [ 887.804521] Lustre: Skipped 1 previous similar message [ 887.938355] Lustre: server umount lustre-MDT0000 complete [ 908.191100] Lustre: 3640:0:(client.c:2480:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1780381323/real 1780381323] req@ffff8920c2e46680 x1866864306540928/t0(0) o400->MGC192.168.204.125@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1780381339 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 908.227640] LustreError: MGC192.168.204.125@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 912.344454] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 912.346706] LDISKFS-fs (dm-0): recovery complete [ 912.352850] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 918.497774] LustreError: 3636:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8921eb085880 x1866864306547712/t0(0) o250->MGC192.168.204.125@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 [ 919.116133] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 919.221661] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 919.724948] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 924.148810] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 924.159332] Lustre: Skipped 3 previous similar messages [ 924.322247] Lustre: lustre-MDT0000: Recovery over after 0:05, of 3 clients 3 recovered and 0 were evicted. [ 924.387784] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:193) [ 924.389420] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:193) [ 924.915673] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 933.438221] Lustre: DEBUG MARKER: oleg425-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 935.642654] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 946.095989] Lustre: DEBUG MARKER: == replay-dual test 4: |X| mkdir adir (-EEXIST), mkdir adir/bdir ========================================================== 02:22:56 (1780381376) [ 954.278504] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 956.507533] Lustre: Failing over lustre-MDT0000 [ 956.923518] Lustre: server umount lustre-MDT0000 complete [ 959.973600] 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 [ 959.983996] LustreError: 6488:0:(ldlm_lib.c:1179: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. [ 959.985899] Lustre: Skipped 5 previous similar messages [ 960.007125] LustreError: 6488:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 79 previous similar messages [ 976.352432] Lustre: 3640:0:(client.c:2480:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1780381391/real 1780381391] req@ffff8921fc546680 x1866864306586752/t0(0) o400->MGC192.168.204.125@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1780381407 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 976.392139] LustreError: MGC192.168.204.125@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 981.676154] LDISKFS-fs (dm-0): 4 truncates cleaned up [ 981.679921] LDISKFS-fs (dm-0): recovery complete [ 981.692276] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 988.210820] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 988.850938] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 993.280744] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 993.292777] Lustre: Skipped 3 previous similar messages [ 993.430949] Lustre: lustre-MDT0000: Recovery over after 0:05, of 3 clients 3 recovered and 0 were evicted. [ 993.532479] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:225) [ 993.533351] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:225) [ 994.658644] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 1005.333524] Lustre: DEBUG MARKER: oleg425-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1007.222390] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1016.536482] Lustre: DEBUG MARKER: == replay-dual test 5: open, unlink |X| close ============ 02:24:06 (1780381446) [ 1025.329559] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1027.323807] Lustre: Failing over lustre-MDT0000 [ 1027.628433] Lustre: server umount lustre-MDT0000 complete [ 1029.094246] 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 [ 1029.115746] Lustre: Skipped 2 previous similar messages [ 1045.472766] Lustre: 3639:0:(client.c:2480:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1780381460/real 1780381460] req@ffff8921fc551180 x1866864306628864/t0(0) o400->MGC192.168.204.125@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1780381476 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1045.499796] LustreError: MGC192.168.204.125@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1048.734911] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1048.740844] LDISKFS-fs (dm-0): recovery complete [ 1048.749282] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1055.720181] LustreError: 3636:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8921fb8b4700 x1866864306638464/t0(0) o250->MGC192.168.204.125@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.934094] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1055.942788] Lustre: Skipped 1 previous similar message [ 1056.009416] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1057.936887] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 1060.607245] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 1061.359752] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1061.368609] Lustre: Skipped 3 previous similar messages [ 1061.603434] Lustre: lustre-MDT0000: Recovery over after 0:04, of 3 clients 3 recovered and 0 were evicted. [ 1061.713597] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:257) [ 1061.722614] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:257) [ 1069.163497] Lustre: DEBUG MARKER: oleg425-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1071.624290] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1081.472647] Lustre: DEBUG MARKER: == replay-dual test 6: open1, open2, unlink |X| close1 [fail mds1] close2 ========================================================== 02:25:11 (1780381511) [ 1089.891358] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1091.570775] Lustre: Failing over lustre-MDT0000 [ 1091.800626] Lustre: server umount lustre-MDT0000 complete [ 1092.066129] 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 [ 1092.088422] Lustre: Skipped 5 previous similar messages [ 1108.447258] Lustre: 3638:0:(client.c:2480:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1780381523/real 1780381523] req@ffff8921f6cf9180 x1866864306664576/t0(0) o400->MGC192.168.204.125@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1780381539 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1108.464805] LustreError: MGC192.168.204.125@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1115.463730] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1115.470275] LDISKFS-fs (dm-0): recovery complete [ 1115.481670] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1118.689046] LustreError: 3636:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8921f6cf9180 x1866864306673024/t0(0) o250->MGC192.168.204.125@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 [ 1119.084680] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1119.395959] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 1124.254115] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 1124.406383] Lustre: lustre-MDT0000: Recovery over after 0:05, of 3 clients 3 recovered and 0 were evicted. [ 1124.450820] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:289) [ 1124.454685] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:289) [ 1132.748880] Lustre: DEBUG MARKER: oleg425-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1134.681475] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1143.694148] Lustre: DEBUG MARKER: == replay-dual test 8: replay of resent request ========== 02:26:13 (1780381573) [ 1151.548615] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1152.480920] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 1152.486056] LustreError: 6488:0:(ldlm_lib.c:3327:target_send_reply_msg()) @@@ dropping reply req@ffff8920c3cda300 x1866864294907776/t38654705670(0) o36->f27c121b-949f-4aac-a822-227ecd95cfad@192.168.204.25@tcp:239/0 lens 512/448 e 0 to 0 dl 1780381594 ref 1 fl Interpret:/200/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 1169.105480] Lustre: lustre-MDT0000: Client f27c121b-949f-4aac-a822-227ecd95cfad (at 192.168.204.25@tcp) reconnecting [ 1169.146933] Lustre: 9315:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff8920c6645180 x1866864294907776/t38654705670(0) o36->f27c121b-949f-4aac-a822-227ecd95cfad@192.168.204.25@tcp:256/0 lens 512/2880 e 0 to 0 dl 1780381611 ref 1 fl Interpret:/202/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 1172.670182] Lustre: Failing over lustre-MDT0000 [ 1173.126966] Lustre: server umount lustre-MDT0000 complete [ 1175.521480] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1175.522078] 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 [ 1175.557812] Lustre: Skipped 1 previous similar message [ 1191.906421] Lustre: 3637:0:(client.c:2480:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1780381606/real 1780381606] req@ffff8921eb084700 x1866864306710528/t0(0) o400->MGC192.168.204.125@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1780381622 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1191.930763] LustreError: MGC192.168.204.125@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1195.977040] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1195.979153] LDISKFS-fs (dm-0): recovery complete [ 1195.987542] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1201.136532] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x49c972b151307390 [ 1201.146506] Lustre: MGC192.168.204.125@tcp: Connection restored to 0@lo (at 0@lo) [ 1201.159661] Lustre: Skipped 7 previous similar messages [ 1201.618076] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1202.444211] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 1206.710093] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 1206.843555] Lustre: lustre-MDT0000: Recovery over after 0:04, of 3 clients 3 recovered and 0 were evicted. [ 1206.892713] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:321) [ 1206.893378] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:321) [ 1214.349679] Lustre: DEBUG MARKER: oleg425-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1216.405721] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1225.304848] Lustre: DEBUG MARKER: == replay-dual test 9: resending a replayed create ======= 02:27:35 (1780381655) [ 1233.501990] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1236.914361] Lustre: Failing over lustre-MDT0000 [ 1237.178427] Lustre: server umount lustre-MDT0000 complete [ 1237.472516] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1237.483825] LustreError: 6488:0:(ldlm_lib.c:1179: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. [ 1237.497494] LustreError: 6488:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 163 previous similar messages [ 1262.056525] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1262.058707] LDISKFS-fs (dm-0): recovery complete [ 1262.077274] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1263.665699] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1268.196842] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 1268.768234] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 1268.776799] LustreError: 31143:0:(ldlm_lib.c:3327:target_send_reply_msg()) @@@ dropping reply req@ffff8920c6733100 x1866864294925312/t42949672962(42949672962) o36->f27c121b-949f-4aac-a822-227ecd95cfad@192.168.204.25@tcp:351/0 lens 528/448 e 0 to 0 dl 1780381706 ref 1 fl Complete:/204/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 1279.684684] Lustre: lustre-MDT0000: Client f27c121b-949f-4aac-a822-227ecd95cfad (at 192.168.204.25@tcp) reconnected, waiting for 3 clients in recovery for 1:29 [ 1279.836103] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:353) [ 1279.837845] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:353) [ 1284.705459] Lustre: DEBUG MARKER: oleg425-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1286.728503] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1297.478731] Lustre: DEBUG MARKER: == replay-dual test 10: resending a replayed unlink ====== 02:28:47 (1780381727) [ 1305.895533] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1309.268079] Lustre: Failing over lustre-MDT0000 [ 1309.635276] Lustre: server umount lustre-MDT0000 complete [ 1309.677922] 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 [ 1309.697806] Lustre: Skipped 7 previous similar messages [ 1330.147526] Lustre: 3637:0:(client.c:2480:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1780381745/real 1780381745] req@ffff8921fb8b6a00 x1866864306785536/t0(0) o400->MGC192.168.204.125@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1780381761 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1330.166980] Lustre: 3637:0:(client.c:2480:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 1330.172443] LustreError: MGC192.168.204.125@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1330.177257] LustreError: Skipped 1 previous similar message [ 1332.146358] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1332.148973] LDISKFS-fs (dm-0): recovery complete [ 1332.155157] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1340.418576] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x49c972b151308001 [ 1340.939112] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1340.948947] Lustre: Skipped 3 previous similar messages [ 1341.054649] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1342.116660] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 1342.141907] Lustre: Skipped 1 previous similar message [ 1346.069742] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 1346.114986] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 1346.125980] LustreError: 33081:0:(ldlm_lib.c:3327:target_send_reply_msg()) @@@ dropping reply req@ffff8921d0251880 x1866864294944512/t47244640260(47244640260) o36->f27c121b-949f-4aac-a822-227ecd95cfad@192.168.204.25@tcp:429/0 lens 528/448 e 0 to 0 dl 1780381784 ref 1 fl Complete:/204/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 1357.531229] Lustre: lustre-MDT0000: Client f27c121b-949f-4aac-a822-227ecd95cfad (at 192.168.204.25@tcp) reconnected, waiting for 3 clients in recovery for 1:28 [ 1357.618994] Lustre: lustre-MDT0000: Recovery over after 0:15, of 3 clients 3 recovered and 0 were evicted. [ 1357.628022] Lustre: Skipped 1 previous similar message [ 1357.703924] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:385) [ 1357.707745] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:385) [ 1362.978468] Lustre: DEBUG MARKER: oleg425-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1365.024348] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1376.856688] Lustre: DEBUG MARKER: == replay-dual test 11: both clients timeout during replay ========================================================== 02:30:06 (1780381806) [ 1385.532942] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1389.174385] Lustre: Failing over lustre-MDT0000 [ 1389.514318] Lustre: server umount lustre-MDT0000 complete [ 1415.172799] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1415.179590] LDISKFS-fs (dm-0): recovery complete [ 1415.198543] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1418.730547] LustreError: 3636:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8921f6d1aa00 x1866864306834816/t0(0) o250->MGC192.168.204.125@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 [ 1418.909672] Lustre: lustre-MDT0000: Not available for connect from 192.168.204.25@tcp (not set up) [ 1418.926617] Lustre: Skipped 1 previous similar message [ 1424.463281] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 1424.475697] LustreError: 35004:0:(ldlm_lib.c:3327:target_send_reply_msg()) @@@ dropping reply req@ffff8921f6d18e00 x1866864294965120/t51539607554(51539607554) o36->f27c121b-949f-4aac-a822-227ecd95cfad@192.168.204.25@tcp:507/0 lens 528/448 e 0 to 0 dl 1780381862 ref 1 fl Complete:/204/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 1425.269511] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 1431.395775] Lustre: DEBUG MARKER: oleg425-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1437.350343] Lustre: lustre-MDT0000: Client f27c121b-949f-4aac-a822-227ecd95cfad (at 192.168.204.25@tcp) reconnected, waiting for 3 clients in recovery for 1:28 [ 1437.528868] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:417) [ 1437.529544] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:417) [ 1439.746277] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 6 sec [ 1448.036975] Lustre: DEBUG MARKER: == replay-dual test 12: open resend timeout ============== 02:31:17 (1780381877) [ 1457.450625] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1461.090066] Lustre: Failing over lustre-MDT0000 [ 1461.718397] Lustre: server umount lustre-MDT0000 complete [ 1463.277215] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1488.972833] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1488.979413] LDISKFS-fs (dm-0): recovery complete [ 1488.998621] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1492.458645] LustreError: 3636:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8921e79d7b80 x1866864306875008/t0(0) o250->MGC192.168.204.125@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 [ 1492.637819] Lustre: lustre-MDT0000: Not available for connect from 192.168.204.25@tcp (not set up) [ 1492.654372] Lustre: Skipped 1 previous similar message [ 1493.121859] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1493.140041] Lustre: Skipped 1 previous similar message [ 1498.089272] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1498.101208] Lustre: Skipped 17 previous similar messages [ 1498.256435] Lustre: *** cfs_fail_loc=302, val=2147483648*** [ 1499.384608] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 1513.606594] Lustre: lustre-MDT0000: Client f27c121b-949f-4aac-a822-227ecd95cfad (at 192.168.204.25@tcp) reconnected, waiting for 3 clients in recovery for 1:24 [ 1513.759878] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:449) [ 1513.760527] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:449) [ 1521.472228] Lustre: DEBUG MARKER: == replay-dual test 13: close resend timeout ============= 02:32:31 (1780381951) [ 1529.431637] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1532.243494] Lustre: Failing over lustre-MDT0000 [ 1532.458685] Lustre: server umount lustre-MDT0000 complete [ 1555.601763] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1555.608570] LDISKFS-fs (dm-0): recovery complete [ 1555.621151] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1559.011057] LustreError: 3636:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8921ffb67480 x1866864306909056/t0(0) o250->MGC192.168.204.125@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 [ 1563.867234] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 1564.759737] Lustre: *** cfs_fail_loc=115, val=2147483648*** [ 1581.269403] Lustre: lustre-MDT0000: Client f27c121b-949f-4aac-a822-227ecd95cfad (at 192.168.204.25@tcp) reconnected, waiting for 3 clients in recovery for 1:24 [ 1581.495151] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:481) [ 1581.501871] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:481) [ 1589.530344] Lustre: DEBUG MARKER: SKIP: replay-dual test_14b skipping ALWAYS excluded test 14b [ 1591.770450] Lustre: DEBUG MARKER: == replay-dual test 15a: timeout waiting for lost client during replay, 1 client completes ========================================================== 02:33:41 (1780382021) [ 1600.713053] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1604.194957] Lustre: Failing over lustre-MDT0000 [ 1604.493650] Lustre: server umount lustre-MDT0000 complete [ 1607.136497] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1607.150388] 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 [ 1607.173075] Lustre: Skipped 14 previous similar messages [ 1625.060804] Lustre: 3639:0:(client.c:2480:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1780382039/real 1780382039] req@ffff8921f6f02680 x1866864306941184/t0(0) o400->MGC192.168.204.125@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1780382055 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1625.081978] Lustre: 3639:0:(client.c:2480:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 1625.087832] LustreError: MGC192.168.204.125@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1625.098098] LustreError: Skipped 3 previous similar messages [ 1628.522465] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1628.530705] LDISKFS-fs (dm-0): recovery complete [ 1628.538897] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1635.297520] LustreError: 3636:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8921eb081c00 x1866864306949760/t0(0) o250->MGC192.168.204.125@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 [ 1636.510336] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 1636.518212] Lustre: Skipped 3 previous similar messages [ 1640.571436] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 1706.500310] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 1706.507481] Lustre: 40529:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client d6f6413d-68a9-45d2-8b85-e234ed8e6f3b@ [ 1706.515242] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 1707.411114] Lustre: lustre-MDT0000: Recovery over after 1:11, of 3 clients 2 recovered and 1 was evicted. [ 1707.444699] Lustre: Skipped 3 previous similar messages [ 1707.509658] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:494 to 0x280000401:513) [ 1707.515918] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:495 to 0x2c0000401:513) [ 1713.889706] Lustre: DEBUG MARKER: oleg425-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1716.606412] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1731.647940] Lustre: DEBUG MARKER: == replay-dual test 15c: remove multiple OST orphans ===== 02:36:01 (1780382161) [ 1740.488750] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1875.494151] Lustre: Failing over lustre-MDT0000 [ 1875.620869] Lustre: lustre-MDT0000: Not available for connect from 192.168.204.25@tcp (stopping) [ 1875.995558] Lustre: server umount lustre-MDT0000 complete [ 1876.455429] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1876.478791] LustreError: 6490:0:(ldlm_lib.c:1179: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. [ 1876.533919] LustreError: 6490:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 232 previous similar messages [ 1902.942216] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1902.950550] LDISKFS-fs (dm-0): recovery complete [ 1902.965471] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1917.410444] LustreError: 3636:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8921fc547b80 x1866864307084416/t0(0) o250->MGC192.168.204.125@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 [ 1917.841419] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1917.846935] Lustre: Skipped 4 previous similar messages [ 1917.907863] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1917.923105] Lustre: Skipped 2 previous similar messages [ 1921.797783] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 1989.500202] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 1989.508668] Lustre: 42439:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 2907dfc1-85eb-496c-9898-40b47e1a7eba@ [ 1989.522758] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 1989.732352] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:495 to 0x2c0000401:1537) [ 1989.745602] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:494 to 0x280000401:1537) [ 1996.386725] Lustre: DEBUG MARKER: oleg425-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1998.254137] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2009.351489] Lustre: DEBUG MARKER: == replay-dual test 16: fail MDS during recovery (3571) == 02:40:39 (1780382439) [ 2019.151140] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2023.007701] Lustre: Failing over lustre-MDT0000 [ 2023.436224] Lustre: server umount lustre-MDT0000 complete [ 2047.952643] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2047.956069] LDISKFS-fs (dm-0): recovery complete [ 2047.965032] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2054.222077] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x49c972b15132a26a [ 2054.240936] Lustre: MGC192.168.204.125@tcp: Connection restored to 0@lo (at 0@lo) [ 2054.257139] Lustre: Skipped 15 previous similar messages [ 2059.672049] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 2087.753256] Lustre: Failing over lustre-MDT0000 [ 2087.774352] LustreError: 44767:0:(ldlm_lib.c:2985:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 2087.793044] Lustre: 44309:0:(ldlm_lib.c:2388:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 2087.826474] Lustre: 44309:0:(ldlm_lib.c:1898:abort_req_replay_queue()) @@@ aborted: req@ffff8920c8708a80 x1866864297422848/t0(73014444033) o36->f27c121b-949f-4aac-a822-227ecd95cfad@192.168.204.25@tcp:423/0 lens 528/0 e 3 to 0 dl 1780382533 ref 1 fl Complete:/204/ffffffff rc 0/-1 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 2087.882760] Lustre: lustre-MDT0000-osd: cancel update llog [0x200000400:0x1:0x0] [ 2087.937619] Lustre: lustre-MDT0000: Not available for connect from 192.168.204.25@tcp (stopping) [ 2087.943680] Lustre: lustre-MDT0001-osp-MDT0000: cancel update llog [0x240000401:0x1:0x0] [ 2087.979768] LustreError: 44309:0:(client.c:1380:ptlrpc_import_delay_req()) @@@ IMP_CLOSED req@ffff8920c12d1880 x1866864307170816/t0(0) o700->lustre-MDT0001-osp-MDT0000@0@lo:30/10 lens 264/248 e 0 to 0 dl 0 ref 2 fl Rpc:QU/200/ffffffff rc 0/-1 job:'tgt_recover_0.0' uid:0 gid:0 projid:4294967295 [ 2088.023541] LustreError: 44309:0:(fid_request.c:213:seq_client_alloc_seq()) cli-cli-lustre-MDT0001-osp-MDT0000: Cannot allocate new meta-sequence: rc = -5 [ 2088.036404] LustreError: 44309:0:(fid_request.c:316:seq_client_alloc_fid()) cli-cli-lustre-MDT0001-osp-MDT0000: Can't allocate new sequence: rc = -5 [ 2088.490675] Lustre: server umount lustre-MDT0000 complete [ 2110.233665] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2121.102387] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 2188.500245] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 2188.517649] Lustre: 45225:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client d24f33e5-ce55-43d2-b584-5b8bbe1dcd83@ [ 2188.522788] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 2189.678147] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1550 to 0x280000401:1569) [ 2189.680102] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1551 to 0x2c0000401:1569) [ 2195.410166] Lustre: DEBUG MARKER: oleg425-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2198.299816] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2214.388365] Lustre: DEBUG MARKER: == replay-dual test 17: fail OST during recovery (3571) == 02:44:03 (1780382643) [ 2225.873496] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 2228.343386] Lustre: Failing over lustre-OST0000 [ 2228.503758] Lustre: server umount lustre-OST0000 complete [ 2228.707708] LustreError: lustre-OST0000-osc-MDT0001: operation ost_statfs to node 0@lo failed: rc = -107 [ 2228.721403] Lustre: lustre-OST0000-osc-MDT0001: Connection to lustre-OST0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 2228.730475] Lustre: Skipped 14 previous similar messages [ 2257.868167] LDISKFS-fs (dm-2): 3 truncates cleaned up [ 2257.878718] LDISKFS-fs (dm-2): recovery complete [ 2257.893499] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2259.610323] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 4 clients reconnect [ 2259.624475] Lustre: Skipped 3 previous similar messages [ 2266.280746] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 2292.141750] Lustre: Failing over lustre-OST0000 [ 2292.150754] LustreError: 47614:0:(ldlm_lib.c:2985:target_stop_recovery_thread()) lustre-OST0000: Aborting recovery [ 2292.165915] Lustre: 47067:0:(ldlm_lib.c:2388:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 2292.180943] Lustre: 47067:0:(ldlm_lib.c:2388:target_recovery_overseer()) Skipped 2 previous similar messages [ 2292.196993] LustreError: 47067:0:(ofd_obd.c:1324:ofd_iocontrol()) lustre-OST0000: iocontrol from 'tgt_recover_0' cmd=c00866c1 _IOWR('f', 193, 8) unrecognized: rc = -25 [ 2292.219318] Lustre: lustre-OST0000: Recovery over after 0:33, of 4 clients 0 recovered and 4 were evicted. [ 2292.235499] Lustre: Skipped 3 previous similar messages [ 2292.433048] Lustre: server umount lustre-OST0000 complete [ 2312.683212] Lustre: 3636:0:(client.c:2480:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1780382690/real 1780382690] req@ffff8921f6d49f80 x1866864307252352/t0(0) o400->lustre-OST0000-osc-MDT0001@0@lo:28/4 lens 224/224 e 3 to 1 dl 1780382743 ref 1 fl Rpc:XQr/2c0/ffffffff rc 0/-1 job:'ldlm_lock_repla.0' uid:0 gid:0 projid:4294967295 [ 2312.741478] Lustre: 3636:0:(client.c:2480:ptlrpc_expire_one_request()) Skipped 4 previous similar messages [ 2313.803645] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2321.748553] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 2385.502837] Lustre: lustre-OST0000: recovery is timed out, evict stale exports [ 2385.517675] Lustre: 48053:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-OST0000: disconnect stale client 943a35b7-fa39-42b9-b43e-75cdce9ff2c1@ [ 2385.553086] Lustre: lustre-OST0000: disconnecting 1 stale clients [ 2392.073321] Lustre: DEBUG MARKER: oleg425-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 2394.996109] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 2407.693886] Lustre: DEBUG MARKER: == replay-dual test 18: ldlm_handle_enqueue succeeds on evicted export (3822) ========================================================== 02:47:17 (1780382837) [ 2412.570728] LustreError: 9315:0:(ldlm_lockd.c:1361:ldlm_handle_enqueue()) cfs_fail_timeout id 30b sleeping for 40000ms [ 2452.607572] LustreError: 9315:0:(ldlm_lockd.c:1361:ldlm_handle_enqueue()) cfs_fail_timeout id 30b awake [ 2469.047481] Lustre: DEBUG MARKER: == replay-dual test 19: resend of open request =========== 02:48:19 (1780382899) [ 2476.715532] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2478.209903] Lustre: *** cfs_fail_loc=157, val=2147483648*** [ 2478.221733] LustreError: 6489:0:(ldlm_lib.c:3327:target_send_reply_msg()) @@@ dropping reply req@ffff8920c7921500 x1866864297551616/t0(0) o101->f27c121b-949f-4aac-a822-227ecd95cfad@192.168.204.25@tcp:125/0 lens 576/688 e 0 to 0 dl 1780382990 ref 1 fl Interpret:/600/0 rc 0/0 job:'createmany.0' uid:0 gid:0 projid:0 [ 2563.738215] Lustre: lustre-MDT0000: Client f27c121b-949f-4aac-a822-227ecd95cfad (at 192.168.204.25@tcp) reconnecting [ 2567.794372] Lustre: Failing over lustre-MDT0000 [ 2568.203390] Lustre: server umount lustre-MDT0000 complete [ 2568.681724] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 2568.701380] LustreError: 6494:0:(ldlm_lib.c:1179: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. [ 2568.717548] LustreError: 6494:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 137 previous similar messages [ 2587.616798] LustreError: MGC192.168.204.125@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2587.634956] LustreError: Skipped 3 previous similar messages [ 2592.307480] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2592.313331] LDISKFS-fs (dm-0): recovery complete [ 2592.321238] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2597.898039] LustreError: 3636:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8920c1e29f80 x1866864307409792/t0(0) o250->MGC192.168.204.125@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 [ 2598.392823] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 2598.403678] Lustre: Skipped 4 previous similar messages [ 2598.507268] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 2598.512611] Lustre: Skipped 4 previous similar messages [ 2603.638235] Lustre: 50590:0:(ldlm_lib.c:2069:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 2603.852922] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1584 to 0x280000401:1601) [ 2603.853870] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1584 to 0x2c0000401:1601) [ 2604.293562] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 2616.355601] Lustre: DEBUG MARKER: oleg425-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2619.791645] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2630.579206] Lustre: DEBUG MARKER: == replay-dual test 20: recovery time is not increasing == 02:51:00 (1780383060) [ 2640.119589] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2642.959104] Lustre: Failing over lustre-MDT0000 [ 2643.246234] Lustre: server umount lustre-MDT0000 complete [ 2666.568794] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2666.576665] LDISKFS-fs (dm-0): recovery complete [ 2666.587545] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2675.350290] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 2675.712223] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 2675.722054] Lustre: Skipped 13 previous similar messages [ 2812.500229] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 2812.509890] Lustre: 52416:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client dffd59b3-f37a-4a6f-a6cf-a95df5699587@ [ 2812.521445] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 2812.602397] Lustre: 52416:0:(ldlm_lib.c:2069:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 2812.614026] Lustre: 52416:0:(ldlm_lib.c:2069:extend_recovery_timer()) Skipped 6 previous similar messages [ 2812.782726] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1603 to 0x2c0000401:1633) [ 2812.783815] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1584 to 0x280000401:1633) [ 2818.521370] Lustre: DEBUG MARKER: oleg425-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2820.957063] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2833.372929] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2836.226951] Lustre: Failing over lustre-MDT0000 [ 2836.771455] Lustre: server umount lustre-MDT0000 complete [ 2838.503393] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 2838.526158] 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 [ 2838.551860] Lustre: Skipped 9 previous similar messages [ 2861.639563] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2861.644619] LDISKFS-fs (dm-0): recovery complete [ 2861.659224] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2867.511642] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 2867.529445] Lustre: Skipped 3 previous similar messages [ 2871.484260] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 3007.500598] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 3007.510403] Lustre: 54088:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client b8fe81c6-b964-41bf-891e-06ab5fbe61f7@ [ 3007.534618] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 3007.583425] Lustre: 54088:0:(ldlm_lib.c:2069:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3007.606430] Lustre: 54088:0:(ldlm_lib.c:2069:extend_recovery_timer()) Skipped 4 previous similar messages [ 3007.682949] Lustre: lustre-MDT0000: Recovery over after 2:20, of 3 clients 2 recovered and 1 was evicted. [ 3007.701216] Lustre: Skipped 3 previous similar messages [ 3007.747136] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1603 to 0x2c0000401:1665) [ 3007.747788] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1635 to 0x280000401:1665) [ 3013.029383] Lustre: DEBUG MARKER: oleg425-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3015.147179] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3029.703851] Lustre: DEBUG MARKER: == replay-dual test 21a: commit on sharing =============== 02:57:39 (1780383459) [ 3041.507415] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3044.331880] Lustre: Failing over lustre-MDT0000 [ 3044.740273] Lustre: server umount lustre-MDT0000 complete [ 3061.729586] Lustre: 3638:0:(client.c:2480:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1780383476/real 1780383476] req@ffff8921f3772680 x1866864307612800/t0(0) o400->MGC192.168.204.125@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1780383492 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3061.780340] Lustre: 3638:0:(client.c:2480:ptlrpc_expire_one_request()) Skipped 4 previous similar messages [ 3070.805669] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3070.808463] LDISKFS-fs (dm-0): recovery complete [ 3070.816512] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3071.982533] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x49c972b15132d275 [ 3076.243239] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 3214.501242] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 3214.517900] Lustre: 56009:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 8ebd12da-ef4d-41b6-8e59-048551693161@ [ 3214.549607] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 3214.601953] Lustre: 56009:0:(ldlm_lib.c:2069:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3214.619897] Lustre: 56009:0:(ldlm_lib.c:2069:extend_recovery_timer()) Skipped 4 previous similar messages [ 3214.699281] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1667 to 0x280000401:1697) [ 3214.700467] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1603 to 0x2c0000401:1697) [ 3227.175886] Lustre: DEBUG MARKER: SKIP: replay-dual test_21b skipping SLOW test 21b [ 3230.260896] Lustre: DEBUG MARKER: == replay-dual test 22a: c1 lfs mkdir -i 1 dir1, M1 drop reply [ 3232.012713] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 3232.016434] LustreError: 9315:0:(ldlm_lib.c:3327:target_send_reply_msg()) @@@ dropping reply req@ffff8921ea45c700 x1866864297676544/t4294967346(0) o36->f27c121b-949f-4aac-a822-227ecd95cfad@192.168.204.25@tcp:122/0 lens 560/448 e 0 to 0 dl 1780383742 ref 1 fl Interpret:/200/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 3235.251527] Lustre: Failing over lustre-MDT0001 [ 3235.667311] Lustre: server umount lustre-MDT0001 complete [ 3236.052944] LustreError: 6490:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0001: not available for connect from 192.168.204.25@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3236.100559] LustreError: 6490:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 145 previous similar messages [ 3236.329573] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 3256.200306] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3256.483980] Lustre: lustre-MDT0001: Not available for connect from 192.168.204.25@tcp (not set up) [ 3256.490938] Lustre: Skipped 1 previous similar message [ 3256.697669] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 3256.706328] Lustre: Skipped 3 previous similar messages [ 3256.753547] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 3256.767511] Lustre: Skipped 3 previous similar messages [ 3261.764839] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 3262.031588] Lustre: 6490:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff8921f2801500 x1866864297676544/t4294967346(0) o36->f27c121b-949f-4aac-a822-227ecd95cfad@192.168.204.25@tcp:153/0 lens 560/2880 e 0 to 0 dl 1780383773 ref 1 fl Interpret:/202/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 3270.056171] Lustre: DEBUG MARKER: oleg425-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 3271.931824] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3285.562631] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3289.171777] Lustre: Failing over lustre-MDT0000 [ 3289.448041] Lustre: lustre-MDT0000: Not available for connect from 192.168.204.25@tcp (stopping) [ 3289.670153] Lustre: server umount lustre-MDT0000 complete [ 3308.495960] LustreError: MGC192.168.204.125@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3308.507818] LustreError: Skipped 3 previous similar messages [ 3314.322172] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3314.329155] LDISKFS-fs (dm-0): recovery complete [ 3314.339443] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3318.769215] LustreError: 3636:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8921fc4e0380 x1866864307734400/t0(0) o250->MGC192.168.204.125@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 [ 3318.799254] LustreError: 3636:0:(client.c:1390:ptlrpc_import_delay_req()) Skipped 4 previous similar messages [ 3323.703790] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 3324.431303] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 3324.448382] Lustre: Skipped 15 previous similar messages [ 3324.494623] Lustre: 58960:0:(ldlm_lib.c:2069:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3324.661260] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1603 to 0x2c0000401:1729) [ 3324.671528] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1667 to 0x280000401:1729) [ 3334.609900] Lustre: DEBUG MARKER: oleg425-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3337.939186] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3352.664241] Lustre: DEBUG MARKER: == replay-dual test 22b: c1 lfs mkdir -i 1 d1, M1 drop reply [ 3354.540151] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 3354.551877] LustreError: 6488:0:(ldlm_lib.c:3327:target_send_reply_msg()) @@@ dropping reply req@ffff8921f2801c00 x1866864297719296/t8589934617(0) o36->f27c121b-949f-4aac-a822-227ecd95cfad@192.168.204.25@tcp:245/0 lens 560/448 e 0 to 0 dl 1780383865 ref 1 fl Interpret:/200/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 3357.834639] Lustre: Failing over lustre-MDT0000 [ 3358.044340] Lustre: server umount lustre-MDT0000 complete [ 3362.777944] Lustre: Failing over lustre-MDT0001 [ 3362.782282] LustreError: 6473:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1780383793 with bad export cookie 5316906940984646474 [ 3362.807298] LustreError: 6473:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 3363.124353] Lustre: server umount lustre-MDT0001 complete [ 3383.445399] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3383.451220] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3383.724661] LustreError: 60698:0:(llog.c:1646:llog_backup()) MGC192.168.204.125@tcp: failed to open log lustre-sptlrpc: rc = -108 [ 3383.730951] Lustre: 60698:0:(mgc_request_server.c:770:mgc_llog_local_copy()) MGC192.168.204.125@tcp: failed to copy new config lustre-sptlrpc: rc = -108 [ 3387.876932] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x49c972b15132e2ba [ 3394.485182] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 3394.679550] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:36 to 0x280000400:65) [ 3394.692868] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:36 to 0x2c0000400:65) [ 3394.782897] Lustre: 60709:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff8921fc4e3100 x1866864297719296/t8589934617(0) o36->f27c121b-949f-4aac-a822-227ecd95cfad@192.168.204.25@tcp:285/0 lens 560/2880 e 0 to 0 dl 1780383905 ref 1 fl Interpret:/202/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 3394.834611] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 3402.080286] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1603 to 0x2c0000401:1761) [ 3402.083068] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1667 to 0x280000401:1761) [ 3406.993132] Lustre: DEBUG MARKER: oleg425-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 3410.046165] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3411.683611] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3425.169902] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3429.272046] Lustre: Failing over lustre-MDT0000 [ 3429.624658] Lustre: server umount lustre-MDT0000 complete [ 3453.619696] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3453.625696] LDISKFS-fs (dm-0): recovery complete [ 3453.635345] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3456.502557] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x49c972b15132eb6c [ 3462.222329] Lustre: 62791:0:(ldlm_lib.c:2069:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3462.264311] Lustre: 62791:0:(ldlm_lib.c:2069:extend_recovery_timer()) Skipped 4 previous similar messages [ 3462.467836] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1603 to 0x2c0000401:1793) [ 3462.468909] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1667 to 0x280000401:1793) [ 3463.600718] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 3475.102648] Lustre: DEBUG MARKER: oleg425-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3477.714570] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3492.369079] Lustre: DEBUG MARKER: == replay-dual test 22c: c1 lfs mkdir -i 1 d1, M1 drop update [ 3493.951575] Lustre: *** cfs_fail_loc=1701, val=2147483648*** [ 3493.955148] LustreError: 8383:0:(ldlm_lib.c:3327:target_send_reply_msg()) @@@ dropping reply req@ffff8920c787b800 x1866864307849984/t107374182414(0) o1000->lustre-MDT0001-mdtlov_UUID@0@lo:315/0 lens 2520/4320 e 0 to 0 dl 1780383935 ref 1 fl Interpret:/200/0 rc 0/0 job:'osp_up0-1.0' uid:0 gid:0 projid:4294967295 [ 3498.031924] Lustre: Failing over lustre-MDT0000 [ 3498.467919] 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 [ 3498.482411] Lustre: Skipped 24 previous similar messages [ 3498.578330] Lustre: server umount lustre-MDT0000 complete [ 3520.444558] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3529.732123] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x49c972b15132f2f1 [ 3530.909981] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 3530.929490] Lustre: Skipped 6 previous similar messages [ 3534.764157] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 3535.417599] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1667 to 0x280000401:1825) [ 3535.419078] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1603 to 0x2c0000401:1825) [ 3543.162222] Lustre: DEBUG MARKER: oleg425-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3545.314236] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3556.548629] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3559.018293] Lustre: Failing over lustre-MDT0000 [ 3559.409544] Lustre: server umount lustre-MDT0000 complete [ 3587.572366] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3587.575479] LDISKFS-fs (dm-0): recovery complete [ 3587.589526] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3607.566413] Lustre: 65760:0:(ldlm_lib.c:2069:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3607.605894] Lustre: 65760:0:(ldlm_lib.c:2069:extend_recovery_timer()) Skipped 4 previous similar messages [ 3607.687438] Lustre: lustre-MDT0000: Recovery over after 0:04, of 3 clients 3 recovered and 0 were evicted. [ 3607.722287] Lustre: Skipped 7 previous similar messages [ 3607.785414] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1667 to 0x280000401:1857) [ 3607.792636] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1603 to 0x2c0000401:1857) [ 3608.273264] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 3617.501336] Lustre: DEBUG MARKER: oleg425-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3619.692873] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3630.570406] Lustre: DEBUG MARKER: == replay-dual test 22d: c1 lfs mkdir -i 1 d1, M1 drop update [ 3635.255931] Lustre: *** cfs_fail_loc=1701, val=2147483648*** [ 3635.260671] LustreError: 8383:0:(ldlm_lib.c:3327:target_send_reply_msg()) @@@ dropping reply req@ffff8921f6888000 x1866864307931776/t115964117002(0) o1000->lustre-MDT0001-mdtlov_UUID@0@lo:457/0 lens 2520/4320 e 0 to 0 dl 1780384077 ref 1 fl Interpret:/200/0 rc 0/0 job:'osp_up0-1.0' uid:0 gid:0 projid:4294967295 [ 3639.031315] Lustre: Failing over lustre-MDT0000 [ 3639.316963] Lustre: server umount lustre-MDT0000 complete [ 3643.525967] LustreError: 7414:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1780384074 with bad export cookie 5316906940984654195 [ 3643.536101] Lustre: Failing over lustre-MDT0001 [ 3643.563104] LustreError: 7414:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 3643.588569] LustreError: 66885:0:(ldlm_resource.c:1180:ldlm_resource_complain()) lustre-MDT0000-osp-MDT0001: namespace resource [0x2000013a1:0x79:0x0].0xf7117594 (ffff8921c395d700) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 3648.501794] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 3648.509564] Lustre: Skipped 2 previous similar messages [ 3649.438866] Lustre: server umount lustre-MDT0001 complete [ 3670.241117] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3670.269907] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3670.598268] LustreError: 67595:0:(llog.c:1646:llog_backup()) MGC192.168.204.125@tcp: failed to open log lustre-sptlrpc: rc = -108 [ 3670.610864] Lustre: 67595:0:(mgc_request_server.c:770:mgc_llog_local_copy()) MGC192.168.204.125@tcp: failed to copy new config lustre-sptlrpc: rc = -108 [ 3689.443047] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x49c972b1513300ea [ 3689.638906] Lustre: lustre-MDT0001: Not available for connect from 192.168.204.25@tcp (not set up) [ 3689.659910] Lustre: Skipped 3 previous similar messages [ 3695.319579] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 3695.722602] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1667 to 0x280000401:1889) [ 3695.725174] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1603 to 0x2c0000401:1889) [ 3695.899341] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:70 to 0x280000400:97) [ 3695.901581] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:70 to 0x2c0000400:97) [ 3695.935085] Lustre: 67607:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff8921ea4f7800 x1866864297814656/t12884901939(0) o36->f27c121b-949f-4aac-a822-227ecd95cfad@192.168.204.25@tcp:586/0 lens 560/2880 e 0 to 0 dl 1780384206 ref 1 fl Interpret:/202/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 3696.071816] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 3704.096660] Lustre: DEBUG MARKER: oleg425-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 3706.188694] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3707.800584] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3717.701611] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3720.473819] Lustre: Failing over lustre-MDT0000 [ 3720.815650] Lustre: server umount lustre-MDT0000 complete [ 3738.079487] Lustre: 3637:0:(client.c:2480:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1780384152/real 1780384152] req@ffff8920c7920700 x1866864307972992/t0(0) o400->MGC192.168.204.125@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1780384168 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3738.122693] Lustre: 3637:0:(client.c:2480:ptlrpc_expire_one_request()) Skipped 17 previous similar messages [ 3743.956784] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3743.962783] LDISKFS-fs (dm-0): recovery complete [ 3743.974900] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3753.524566] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 3753.987135] Lustre: 69687:0:(ldlm_lib.c:2069:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3754.008230] Lustre: 69687:0:(ldlm_lib.c:2069:extend_recovery_timer()) Skipped 4 previous similar messages [ 3754.108350] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1603 to 0x2c0000401:1921) [ 3754.109751] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1667 to 0x280000401:1921) [ 3761.210178] Lustre: DEBUG MARKER: oleg425-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3762.866948] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3771.953625] Lustre: DEBUG MARKER: == replay-dual test 23a: c1 rmdir d1, M1 drop reply and fail, client2 mkdir d1 ========================================================== 03:10:02 (1780384202) [ 3773.458521] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 3773.468273] LustreError: 69054:0:(ldlm_lib.c:3327:target_send_reply_msg()) @@@ dropping reply req@ffff8921c960c000 x1866864297861760/t17179869210(0) o36->f27c121b-949f-4aac-a822-227ecd95cfad@192.168.204.25@tcp:664/0 lens 496/456 e 0 to 0 dl 1780384284 ref 1 fl Interpret:/200/0 rc 0/0 job:'rmdir.0' uid:0 gid:0 projid:4294967295 [ 3777.083795] Lustre: Failing over lustre-MDT0001 [ 3779.569383] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 3779.569755] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 3779.582798] LustreError: Skipped 4 previous similar messages [ 3779.596256] Lustre: Skipped 2 previous similar messages [ 3783.503916] Lustre: server umount lustre-MDT0001 complete [ 3803.238954] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3808.420613] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 3808.847193] Lustre: 67608:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff8921c960f100 x1866864297861760/t17179869210(0) o36->f27c121b-949f-4aac-a822-227ecd95cfad@192.168.204.25@tcp:699/0 lens 496/2888 e 0 to 0 dl 1780384319 ref 1 fl Interpret:/202/0 rc 0/0 job:'rmdir.0' uid:0 gid:0 projid:4294967295 [ 3808.851710] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:100 to 0x280000400:129) [ 3808.863625] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:100 to 0x2c0000400:129) [ 3816.124626] Lustre: DEBUG MARKER: oleg425-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 3818.021274] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3828.743517] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3831.281969] Lustre: Failing over lustre-MDT0000 [ 3831.602851] Lustre: server umount lustre-MDT0000 complete [ 3836.101757] LustreError: 67609:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.204.25@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3836.133559] LustreError: 67609:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 312 previous similar messages [ 3853.319414] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3853.322118] LDISKFS-fs (dm-0): recovery complete [ 3853.327609] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3861.234400] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3861.241142] Lustre: Skipped 10 previous similar messages [ 3861.295204] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 3861.298147] Lustre: Skipped 10 previous similar messages [ 3865.865273] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 3866.639853] Lustre: 72632:0:(ldlm_lib.c:2069:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3866.650347] Lustre: 72632:0:(ldlm_lib.c:2069:extend_recovery_timer()) Skipped 4 previous similar messages [ 3866.824412] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1923 to 0x280000401:1953) [ 3866.827948] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1923 to 0x2c0000401:1953) [ 3874.172937] Lustre: DEBUG MARKER: oleg425-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3876.147681] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3886.559644] Lustre: DEBUG MARKER: == replay-dual test 23b: c1 rmdir d1, M1 drop reply and fail M0/M1, c2 mkdir d1 ========================================================== 03:11:56 (1780384316) [ 3888.709747] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 3888.724128] LustreError: 67607:0:(ldlm_lib.c:3327:target_send_reply_msg()) @@@ dropping reply req@ffff8921c906d880 x1866864297897856/t21474836483(0) o36->f27c121b-949f-4aac-a822-227ecd95cfad@192.168.204.25@tcp:24/0 lens 496/456 e 0 to 0 dl 1780384399 ref 1 fl Interpret:/200/0 rc 0/0 job:'rmdir.0' uid:0 gid:0 projid:4294967295 [ 3892.980312] Lustre: Failing over lustre-MDT0000 [ 3893.211789] Lustre: server umount lustre-MDT0000 complete [ 3898.349646] LustreError: 6474:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1780384329 with bad export cookie 5316906940984661363 [ 3898.367409] LustreError: 6474:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 3 previous similar messages [ 3898.369711] Lustre: Failing over lustre-MDT0001 [ 3898.988378] Lustre: server umount lustre-MDT0001 complete [ 3919.834817] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3919.973945] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3920.203858] LustreError: 74393:0:(llog.c:1646:llog_backup()) MGC192.168.204.125@tcp: failed to open log lustre-sptlrpc: rc = -108 [ 3920.212456] Lustre: 74393:0:(mgc_request_server.c:770:mgc_llog_local_copy()) MGC192.168.204.125@tcp: failed to copy new config lustre-sptlrpc: rc = -108 [ 3923.948553] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x49c972b151331cd5 [ 3928.384292] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 3929.022266] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 3930.116387] Lustre: lustre-MDT0001-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 3930.133613] Lustre: Skipped 43 previous similar messages [ 3930.695750] Lustre: 74442:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff8921fc6d0a80 x1866864297897856/t21474836483(0) o36->f27c121b-949f-4aac-a822-227ecd95cfad@192.168.204.25@tcp:66/0 lens 496/2888 e 0 to 0 dl 1780384441 ref 1 fl Interpret:/202/0 rc 0/0 job:'rmdir.0' uid:0 gid:0 projid:4294967295 [ 3930.696908] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:100 to 0x280000400:161) [ 3930.700466] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:100 to 0x2c0000400:161) [ 3937.651259] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1923 to 0x2c0000401:1985) [ 3937.652329] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1923 to 0x280000401:1985) [ 3941.560587] Lustre: DEBUG MARKER: oleg425-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 3943.598760] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3945.377336] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3954.845856] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3957.007089] Lustre: Failing over lustre-MDT0000 [ 3957.409664] Lustre: server umount lustre-MDT0000 complete [ 3978.207491] LustreError: MGC192.168.204.125@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3978.226053] LustreError: Skipped 8 previous similar messages [ 3978.756282] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3978.759259] LDISKFS-fs (dm-0): recovery complete [ 3978.767109] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3988.467428] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x49c972b15133251e [ 3993.368908] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 3994.326241] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1987 to 0x280000401:2017) [ 3994.327142] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1987 to 0x2c0000401:2017) [ 4001.626679] Lustre: DEBUG MARKER: oleg425-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4003.301879] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4011.579903] Lustre: DEBUG MARKER: == replay-dual test 23c: c1 rmdir d1, M0 drop update reply and fail M0, c2 mkdir d1 ========================================================== 03:14:02 (1780384442) [ 4012.877374] Lustre: *** cfs_fail_loc=1701, val=2147483648*** [ 4012.883173] LustreError: 8383:0:(ldlm_lib.c:3327:target_send_reply_msg()) @@@ dropping reply req@ffff8921c8525880 x1866864308156160/t137438953491(0) o1000->lustre-MDT0001-mdtlov_UUID@0@lo:79/0 lens 1984/4320 e 0 to 0 dl 1780384454 ref 1 fl Interpret:/200/0 rc 0/0 job:'osp_up0-1.0' uid:0 gid:0 projid:4294967295 [ 4016.412696] Lustre: Failing over lustre-MDT0000 [ 4016.730576] Lustre: server umount lustre-MDT0000 complete [ 4034.600212] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4038.553622] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 4040.234772] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1987 to 0x280000401:2049) [ 4040.234782] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1987 to 0x2c0000401:2049) [ 4044.706658] Lustre: DEBUG MARKER: oleg425-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4046.276854] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4054.879953] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4056.585366] Lustre: Failing over lustre-MDT0000 [ 4056.813830] Lustre: server umount lustre-MDT0000 complete [ 4077.604106] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 4077.606546] LDISKFS-fs (dm-0): recovery complete [ 4077.615673] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4087.278566] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x49c972b1513331e3 [ 4091.601695] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 4092.966215] Lustre: 79466:0:(ldlm_lib.c:2069:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 4092.980664] Lustre: 79466:0:(ldlm_lib.c:2069:extend_recovery_timer()) Skipped 17 previous similar messages [ 4093.152398] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2051 to 0x2c0000401:2081) [ 4093.152726] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2051 to 0x280000401:2081) [ 4098.104610] Lustre: DEBUG MARKER: oleg425-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4099.884502] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4107.582250] Lustre: DEBUG MARKER: == replay-dual test 23d: c1 rmdir d1, M0 drop update reply and fail M0/M1, c2 mkdir d1 ========================================================== 03:15:38 (1780384538) [ 4111.893599] Lustre: *** cfs_fail_loc=1701, val=2147483648*** [ 4111.897201] LustreError: 8383:0:(ldlm_lib.c:3327:target_send_reply_msg()) @@@ dropping reply req@ffff8921c893ed80 x1866864308222720/t146028888081(0) o1000->lustre-MDT0001-mdtlov_UUID@0@lo:178/0 lens 1984/4320 e 0 to 0 dl 1780384553 ref 1 fl Interpret:/200/0 rc 0/0 job:'osp_up0-1.0' uid:0 gid:0 projid:4294967295 [ 4115.255043] Lustre: Failing over lustre-MDT0000 [ 4115.530592] Lustre: server umount lustre-MDT0000 complete [ 4118.501703] 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 [ 4118.520571] Lustre: Skipped 45 previous similar messages [ 4118.801456] Lustre: Failing over lustre-MDT0001 [ 4118.803926] LustreError: 7414:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1780384549 with bad export cookie 5316906940984668643 [ 4118.828627] LustreError: 7414:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 4118.859277] Lustre: lustre-MDT0001: Not available for connect from 192.168.204.25@tcp (stopping) [ 4118.867067] Lustre: Skipped 2 previous similar messages [ 4119.197552] Lustre: server umount lustre-MDT0001 complete [ 4137.353926] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4137.356708] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4137.589645] LustreError: 81298:0:(llog.c:1646:llog_backup()) MGC192.168.204.125@tcp: failed to open log lustre-sptlrpc: rc = -108 [ 4137.595810] Lustre: 81298:0:(mgc_request_server.c:770:mgc_llog_local_copy()) MGC192.168.204.125@tcp: failed to copy new config lustre-sptlrpc: rc = -108 [ 4143.514468] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4143.526766] Lustre: Skipped 11 previous similar messages [ 4146.875918] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 4147.277954] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 4148.793331] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2051 to 0x2c0000401:2113) [ 4148.794234] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2051 to 0x280000401:2113) [ 4148.862060] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:100 to 0x2c0000400:193) [ 4148.885451] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:100 to 0x280000400:193) [ 4148.927757] Lustre: 81311:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff8921fb911880 x1866864297974912/t25769803783(0) o36->f27c121b-949f-4aac-a822-227ecd95cfad@192.168.204.25@tcp:284/0 lens 496/2888 e 0 to 0 dl 1780384659 ref 1 fl Interpret:/202/0 rc 0/0 job:'rmdir.0' uid:0 gid:0 projid:4294967295 [ 4154.153216] Lustre: DEBUG MARKER: oleg425-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 4155.905600] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4157.365802] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4167.621072] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4169.792280] Lustre: Failing over lustre-MDT0000 [ 4170.128611] Lustre: server umount lustre-MDT0000 complete [ 4191.769853] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 4191.775523] LDISKFS-fs (dm-0): recovery complete [ 4191.788396] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4204.869637] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 4206.841120] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2115 to 0x280000401:2145) [ 4206.841765] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2115 to 0x2c0000401:2145) [ 4212.038981] Lustre: DEBUG MARKER: oleg425-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4213.450684] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4220.556455] Lustre: DEBUG MARKER: == replay-dual test 24: reconstruct on non-existing object ========================================================== 03:17:31 (1780384651) [ 4221.375192] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 4221.377510] LustreError: 81311:0:(ldlm_lib.c:3327:target_send_reply_msg()) @@@ dropping reply req@ffff8921c432d500 x1866864298011264/t154618822673(0) o36->f27c121b-949f-4aac-a822-227ecd95cfad@192.168.204.25@tcp:357/0 lens 488/456 e 0 to 0 dl 1780384732 ref 1 fl Interpret:/200/0 rc 0/0 job:'truncate.0' uid:0 gid:0 projid:4294967295 [ 4306.591232] Lustre: lustre-MDT0000: Client f27c121b-949f-4aac-a822-227ecd95cfad (at 192.168.204.25@tcp) reconnecting [ 4306.615531] Lustre: 81309:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff8921c42dd880 x1866864298011264/t154618822673(0) o36->f27c121b-949f-4aac-a822-227ecd95cfad@192.168.204.25@tcp:442/0 lens 488/3152 e 0 to 0 dl 1780384817 ref 1 fl Interpret:/202/0 rc 0/0 job:'truncate.0' uid:0 gid:0 projid:4294967295 [ 4312.949913] Lustre: DEBUG MARKER: == replay-dual test 25: replay|resend ==================== 03:19:03 (1780384743) [ 4314.837263] Lustre: *** cfs_fail_loc=304, val=0*** [ 4316.453755] Lustre: Failing over lustre-OST0000 [ 4316.546275] Lustre: server umount lustre-OST0000 complete [ 4332.905084] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4334.584938] Lustre: lustre-OST0000: Recovery over after 0:01, of 4 clients 4 recovered and 0 were evicted. [ 4334.588830] Lustre: Skipped 13 previous similar messages [ 4338.264913] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 4344.399641] Lustre: DEBUG MARKER: oleg425-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 4345.690353] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4353.843950] Lustre: DEBUG MARKER: == replay-dual test 26: dbench and tar with mds failover ========================================================== 03:19:44 (1780384784) [ 4362.399992] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4365.724438] Lustre: DEBUG MARKER: test_26 fail mds1 1 times [ 4367.373587] Lustre: Failing over lustre-MDT0000 [ 4367.565028] Lustre: lustre-MDT0000: Not available for connect from 192.168.204.25@tcp (stopping) [ 4367.573069] Lustre: Skipped 1 previous similar message [ 4367.687916] Lustre: server umount lustre-MDT0000 complete [ 4384.223103] Lustre: 3638:0:(client.c:2480:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1780384799/real 1780384799] req@ffff8920c787aa00 x1866864308405888/t0(0) o400->MGC192.168.204.125@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1780384815 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4384.256131] Lustre: 3638:0:(client.c:2480:ptlrpc_expire_one_request()) Skipped 23 previous similar messages [ 4387.230707] LDISKFS-fs (dm-0): 4 truncates cleaned up [ 4387.232794] LDISKFS-fs (dm-0): recovery complete [ 4387.238625] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4394.468564] LustreError: 3636:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8921d177d500 x1866864308417024/t0(0) o250->MGC192.168.204.125@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 [ 4394.485289] LustreError: 3636:0:(client.c:1390:ptlrpc_import_delay_req()) Skipped 6 previous similar messages [ 4398.063524] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 4400.109251] Lustre: 87083:0:(ldlm_lib.c:2069:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 4400.118299] Lustre: 87083:0:(ldlm_lib.c:2069:extend_recovery_timer()) Skipped 17 previous similar messages [ 4402.139180] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2179 to 0x2c0000401:2209) [ 4402.143822] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2180 to 0x280000401:2209) [ 4405.127497] Lustre: DEBUG MARKER: oleg425-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4406.438475] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4417.571847] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 4421.014902] Lustre: DEBUG MARKER: test_26 fail mds2 2 times [ 4422.731859] Lustre: Failing over lustre-MDT0001 [ 4423.081893] Lustre: server umount lustre-MDT0001 complete [ 4423.156907] LustreError: lustre-MDT0001-osp-MDT0000: operation out_update to node 0@lo failed: rc = -107 [ 4423.164575] LustreError: Skipped 4 previous similar messages [ 4436.125296] LustreError: 81309:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0001: not available for connect from 192.168.204.25@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4436.148274] LustreError: 81309:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 281 previous similar messages [ 4442.627111] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 4442.630280] LDISKFS-fs (dm-1): recovery complete [ 4442.649116] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4446.674921] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 4450.169342] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:270 to 0x280000400:289) [ 4450.169652] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:270 to 0x2c0000400:289) [ 4453.568247] Lustre: DEBUG MARKER: oleg425-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 4454.984471] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4464.273909] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4467.241789] Lustre: DEBUG MARKER: test_26 fail mds1 3 times [ 4468.433847] Lustre: Failing over lustre-MDT0000 [ 4468.738622] Lustre: server umount lustre-MDT0000 complete [ 4486.998390] LDISKFS-fs (dm-0): 3 truncates cleaned up [ 4487.001982] LDISKFS-fs (dm-0): recovery complete [ 4487.014073] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4487.376273] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4487.381317] Lustre: Skipped 11 previous similar messages [ 4487.434519] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4487.445573] Lustre: Skipped 11 previous similar messages [ 4490.381775] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 4493.741791] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2277 to 0x2c0000401:2305) [ 4493.746083] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2276 to 0x280000401:2305) [ 4496.700326] Lustre: DEBUG MARKER: oleg425-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4498.259880] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4507.250190] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 4510.905920] Lustre: DEBUG MARKER: test_26 fail mds2 4 times [ 4512.575333] Lustre: Failing over lustre-MDT0001 [ 4512.611789] LustreError: 91459:0:(ldlm_resource.c:1180:ldlm_resource_complain()) lustre-MDT0000-osp-MDT0001: namespace resource [0x2000013a1:0x18e:0x0].0x0 (ffff8921ea96b100) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 4512.638859] Lustre: lustre-MDT0001: Not available for connect from 192.168.204.25@tcp (stopping) [ 4512.642961] Lustre: Skipped 1 previous similar message [ 4518.128130] Lustre: server umount lustre-MDT0001 complete [ 4539.426090] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 4539.430195] LDISKFS-fs (dm-1): recovery complete [ 4539.442421] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4543.507737] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 4545.007576] Lustre: lustre-MDT0001-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 4545.012060] Lustre: Skipped 43 previous similar messages [ 4546.777381] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:378 to 0x280000400:417) [ 4546.777952] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:377 to 0x2c0000400:417) [ 4551.003563] Lustre: DEBUG MARKER: oleg425-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 4553.380893] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4614.427743] Lustre: DEBUG MARKER: == replay-dual test 28: lock replay should be ordered: waiting after granted ========================================================== 03:24:05 (1780385045) [ 4628.795179] Lustre: Failing over lustre-OST0000 [ 4628.874856] Lustre: server umount lustre-OST0000 complete [ 4644.514378] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4646.062933] Lustre: *** cfs_fail_loc=32a, val=0*** [ 4649.061169] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 4654.170934] Lustre: DEBUG MARKER: oleg425-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 4655.302351] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4663.870977] Lustre: DEBUG MARKER: == replay-dual test 29: replay vs update with the same xid ========================================================== 03:24:54 (1780385094) [ 4665.205333] Lustre: DEBUG MARKER: SKIP: replay-dual test_29 needs >= 2 clients [ 4666.578536] Lustre: DEBUG MARKER: == replay-dual test 30: layout lock replay is not blocked on IO ========================================================== 03:24:57 (1780385097) [ 4669.254381] Lustre: Failing over lustre-MDT0000 [ 4669.588844] Lustre: server umount lustre-MDT0000 complete [ 4686.333117] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4686.414417] LustreError: MGC192.168.204.125@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4686.422420] LustreError: Skipped 6 previous similar messages [ 4689.829248] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 4692.199635] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2381 to 0x280000401:2401) [ 4692.203769] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2379 to 0x2c0000401:2401) [ 4695.199822] Lustre: DEBUG MARKER: oleg425-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4696.485523] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4702.039269] Lustre: DEBUG MARKER: == replay-dual test 31: deadlock on file_remove_privs and occupied mod rpc slots ========================================================== 03:25:32 (1780385132) [ 4704.148068] Lustre: Failing over lustre-OST0000 [ 4704.213444] Lustre: server umount lustre-OST0000 complete [ 4719.569320] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4723.603326] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 4729.367828] Lustre: DEBUG MARKER: oleg425-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 4730.643133] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in IDLE [ 4737.437167] Lustre: DEBUG MARKER: == replay-dual test 32: gap in update llog shouldn't break recovery ========================================================== 03:26:08 (1780385168) [ 4738.143725] Lustre: *** cfs_fail_loc=131d, val=10*** [ 4738.687439] Lustre: *** cfs_fail_loc=131d, val=4294967292*** [ 4738.690102] Lustre: Skipped 13 previous similar messages [ 4740.946980] Lustre: Failing over lustre-MDT0001 [ 4741.266213] Lustre: server umount lustre-MDT0001 complete [ 4743.138528] Lustre: lustre-MDT0001-osp-MDT0000: Connection to lustre-MDT0001 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 4743.155062] Lustre: Skipped 30 previous similar messages [ 4744.195956] Lustre: Failing over lustre-MDT0000 [ 4744.498298] Lustre: server umount lustre-MDT0000 complete [ 4749.968725] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4750.354887] Lustre: *** cfs_fail_loc=131d, val=4294967266*** [ 4750.357482] Lustre: Skipped 25 previous similar messages [ 4753.818962] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 4759.398503] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4759.491738] Lustre: *** cfs_fail_loc=131d, val=4294967262*** [ 4759.494378] Lustre: Skipped 3 previous similar messages [ 4759.594679] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4759.601148] Lustre: Skipped 10 previous similar messages [ 4762.361579] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 4765.229364] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:433 to 0x2c0000400:449) [ 4765.231707] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:434 to 0x280000400:449) [ 4765.271552] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2441 to 0x280000401:2529) [ 4765.272412] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2379 to 0x2c0000401:2433) [ 4772.351433] Lustre: DEBUG MARKER: == replay-dual test 33: Check for OBD_INCOMPAT_MULTI_RPCS in last_rcvd after abort_recovery ========================================================== 03:26:43 (1780385203) [ 4777.234468] Lustre: Failing over lustre-MDT0001 [ 4777.408906] Lustre: server umount lustre-MDT0001 complete [ 4794.627407] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4797.951796] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 4802.254402] Lustre: DEBUG MARKER: oleg425-client.virtnet: executing wait_import_state_mount REPLAY_WAIT mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 4803.510378] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in REPLAY_WAIT state after 0 sec [ 4804.109609] Lustre: lustre-MDT0001: Aborting client recovery [ 4804.116885] LustreError: 100735:0:(ldlm_lib.c:2985:target_stop_recovery_thread()) lustre-MDT0001: Aborting recovery [ 4804.122278] Lustre: 100215:0:(ldlm_lib.c:2388:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 4804.133317] Lustre: 100215:0:(ldlm_lib.c:2388:target_recovery_overseer()) Skipped 2 previous similar messages [ 4804.143592] Lustre: 100215:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0001: disconnect stale client 5b5da403-e831-4607-844a-fbb3ad2eaee5@ [ 4804.152423] Lustre: lustre-MDT0001: disconnecting 1 stale clients [ 4804.164668] Lustre: lustre-MDT0001-osd: cancel update llog [0x240000400:0x1:0x0] [ 4804.176265] Lustre: lustre-MDT0000-osp-MDT0001: cancel update llog [0x200000401:0x1:0x0] [ 4804.221618] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:434 to 0x280000400:481) [ 4804.227029] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:433 to 0x2c0000400:481) [ 4806.794595] Lustre: DEBUG MARKER: oleg425-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 4807.820725] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4809.817362] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0001.recovery_status 1475 [ 4816.194848] Lustre: Failing over lustre-MDT0001 [ 4816.371088] Lustre: server umount lustre-MDT0001 complete [ 4822.538642] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4825.848229] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug -1 all [ 4827.459527] Lustre: lustre-MDT0001: Denying connection for new client 00a8be40-96b3-4b75-9380-11a349ca7e03 (at 192.168.204.25@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 2:17 [ 4827.475585] Lustre: Skipped 12 previous similar messages [ 4828.178278] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:434 to 0x280000400:513) [ 4828.178754] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:433 to 0x2c0000400:513) [ 4830.189633] Lustre: DEBUG MARKER: oleg425-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 4831.380790] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4833.579107] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0001.recovery_status 1475 [ 4839.134906] Lustre: DEBUG MARKER: == replay-dual test complete, duration 4550 sec ========== 03:27:49 (1780385269) [ 4840.192672] Lustre: DEBUG MARKER: === replay-dual: start cleanup 03:27:50 (1780385270) === [ 4847.324624] Lustre: DEBUG MARKER: === replay-dual: finish cleanup 03:27:57 (1780385277) === [ 4848.647607] Lustre: Failing over lustre-MDT0000 [ 4848.808306] Lustre: server umount lustre-MDT0000 complete [ 4868.909428] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4872.262385] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5010.500487] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 5010.515087] Lustre: 103631:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 5b5da403-e831-4607-844a-fbb3ad2eaee5@ [ 5010.526889] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 5010.544317] Lustre: lustre-MDT0000: Recovery over after 2:20, of 3 clients 2 recovered and 1 was evicted. [ 5010.551112] Lustre: Skipped 11 previous similar messages [ 5010.589128] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2441 to 0x280000401:2561) [ 5010.592640] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2379 to 0x2c0000401:2465) [ 5014.591573] Lustre: DEBUG MARKER: oleg425-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 5016.422596] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5023.204687] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5023.215600] Lustre: Skipped 10 previous similar messages [ 5027.966085] Lustre: server umount lustre-MDT0000 complete [ 5036.341205] LustreError: 90886:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1780385467 with bad export cookie 5316906940984917668 [ 5036.355538] LustreError: 90886:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 5036.699561] Lustre: server umount lustre-MDT0001 complete [ 5054.637703] Lustre: server umount lustre-OST0000 complete [ 5072.871670] Lustre: server umount lustre-OST0001 complete [ 5090.993485] Lustre: DEBUG MARKER: oleg425-server.virtnet: executing unload_modules_local [ 5095.129031] Key type lgssc unregistered [ 5095.635365] LNet: 106440:0:(lib-ptl.c:967:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 5095.647257] LNetError: 106440:0:(acceptor.c:246:lnet_acceptor_remove_socket()) Interface ens2 not found [ 5096.678317] LNet: Removed LNI 192.168.204.125@tcp [ 5097.453178] Key type .llcrypt unregistered [ 5097.456438] Key type ._llcrypt unregistered