[ 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 483850389 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2399.998 MHz processor [ 0.000000] last_pfn = 0x146e00 max_arch_pfn = 0x400000000 [ 0.000000] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT [ 0.000000] last_pfn = 0xbffce max_arch_pfn = 0x400000000 [ 0.000000] found SMP MP-table at [mem 0x000f54b0-0x000f54bf] [ 0.000000] RAMDISK: [mem 0xbcc54000-0xbffbffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F52D0 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE247C 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE2318 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 0022D8 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE238C 000090 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE241C 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE2454 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe2318-0xbffe238b] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe2317] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe238c-0xbffe241b] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe241c-0xbffe2453] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe2454-0xbffe247b] [ 0.000000] No NUMA configuration found [ 0.000000] Faking a node at [mem 0x0000000000000000-0x0000000146dfffff] [ 0.000000] NODE_DATA(0) allocated [mem 0x1465a3000-0x1465cdfff] [ 0.000000] Reserving 256MB of memory at 2752MB for crashkernel (System RAM: 4205MB) [ 0.000000] Zone ranges: [ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.000000] DMA32 [mem 0x0000000001000000-0x00000000ffffffff] [ 0.000000] Normal [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Device empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff] [ 0.000000] node 0: [mem 0x0000000000100000-0x00000000bffcdfff] [ 0.000000] node 0: [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Zeroed struct page in unavailable ranges: 4756 pages [ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x0000000146dfffff] [ 0.000000] ACPI: PM-Timer IO Port: 0x608 [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) [ 0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) [ 0.000000] Using ACPI (MADT) for SMP configuration information [ 0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000] TSC deadline timer available [ 0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs [ 0.000000] kvm-guest: KVM setup pv remote TLB flush [ 0.000000] kvm-guest: setup PV sched yield [ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff] [ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff] [ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff] [ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff] [ 0.000000] PM: Registered nosave memory: [mem 0xbffce000-0xbfffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xc0000000-0xfeffbfff] [ 0.000000] PM: Registered nosave memory: [mem 0xfeffc000-0xfeffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xff000000-0xfffbffff] [ 0.000000] PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff] [ 0.000000] [mem 0xc0000000-0xfeffbfff] available for PCI devices [ 0.000000] Booting paravirtualized kernel on KVM [ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns [ 0.000000] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1 [ 0.000000] percpu: Embedded 63 pages/cpu s221184 r8192 d28672 u524288 [ 0.000000] kvm-guest: PV spinlocks enabled [ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1059606 [ 0.000000] Policy zone: Normal [ 0.000000] Kernel command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] Specific versions of hardware are certified with Red Hat Enterprise Linux 8. Please see the list of hardware certified with Red Hat Enterprise Linux 8 at https://catalog.redhat.com. [ 0.000000] audit: disabled (until reboot) [ 0.000000] software IO TLB: area num 4. [ 0.000000] Memory: 2895240K/4306352K available (18435K kernel code, 11221K rwdata, 7248K rodata, 2908K init, 18040K bss, 524584K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] ftrace: allocating 41240 entries in 162 pages [ 0.000000] ftrace: allocated 162 pages with 3 groups [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] rcu: RCU event tracing is enabled. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ 0.000000] rcu: RCU callback double-/use-after-free debug enabled. [ 0.000000] Rude variant of Tasks RCU enabled. [ 0.000000] Tracing variant of Tasks RCU enabled. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 0.000000] NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16 [ 0.000000] random: get_random_bytes called from start_kernel+0x622/0x9a8 with crng_init=0 [ 0.001000] Console: colour *CGA 80x25 [ 0.001000] printk: console [ttyS1] enabled [ 0.001000] ACPI: Core revision 20220331 [ 0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.001009] APIC: Switch to symmetric I/O mode setup [ 0.003388] x2apic enabled [ 0.004008] Switched APIC routing to physical x2apic. [ 0.005014] kvm-guest: setup PV IPIs [ 0.007827] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.008000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.008020] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.009013] pid_max: default: 32768 minimum: 301 [ 0.010119] LSM: Security Framework initializing [ 0.011051] Yama: becoming mindful. [ 0.013028] SELinux: Initializing. [ 0.014068] *** VALIDATE selinux *** [ 0.022809] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.026744] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.028157] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.029114] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.030129] *** VALIDATE tmpfs *** [ 0.031489] *** VALIDATE proc *** [ 0.033214] *** VALIDATE cgroup *** [ 0.033975] *** VALIDATE cgroup2 *** [ 0.035131] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.036153] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.037008] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.038021] Spectre V2 : User space: Vulnerable [ 0.039009] Speculative Store Bypass: Vulnerable [ 0.041575] debug: unmapping init [mem 0xffffffffb2a59000-0xffffffffb2a60fff] [ 0.043168] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.044692] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.045024] ... version: 2 [ 0.046011] ... bit width: 48 [ 0.047010] ... generic registers: 4 [ 0.048017] ... value mask: 0000ffffffffffff [ 0.049015] ... max period: 00007fffffffffff [ 0.050014] ... fixed-purpose events: 3 [ 0.051013] ... event mask: 000000070000000f [ 0.052280] rcu: Hierarchical SRCU implementation. [ 0.054327] smp: Bringing up secondary CPUs ... [ 0.055575] x86: Booting SMP configuration: [ 0.056026] .... node #0, CPUs: #1 #2 #3 [ 0.059315] smp: Brought up 1 node, 4 CPUs [ 0.061011] smpboot: Max logical packages: 1 [ 0.062020] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.126000] node 0 deferred pages initialised in 63ms [ 0.130136] devtmpfs: initialized [ 0.131192] x86/mm: Memory block size: 128MB [ 0.133691] gcov: version magic: 0x41383552 [ 0.135214] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.136073] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.137226] pinctrl core: initialized pinctrl subsystem [ 0.138173] [ 0.138782] ************************************************************* [ 0.139015] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.140011] ** ** [ 0.141010] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.142011] ** ** [ 0.143014] ** This means that this kernel is built to expose internal ** [ 0.144012] ** IOMMU data structures, which may compromise security on ** [ 0.145012] ** your system. ** [ 0.146014] ** ** [ 0.147010] ** If you see this message and you are not debugging the ** [ 0.148009] ** kernel, report this immediately to your vendor! ** [ 0.149010] ** ** [ 0.150012] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.151011] ************************************************************* [ 0.152879] NET: Registered protocol family 16 [ 0.153438] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.154055] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.155050] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.157158] cpuidle: using governor menu [ 0.159182] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.162799] PCI: Using configuration type 1 for base access [ 0.164116] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.174058] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.175014] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.176159] cryptd: max_cpu_qlen set to 1000 [ 0.178235] ACPI: Added _OSI(Module Device) [ 0.179014] ACPI: Added _OSI(Processor Device) [ 0.180011] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.181013] ACPI: Added _OSI(Processor Aggregator Device) [ 0.184875] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.186584] ACPI: Interpreter enabled [ 0.187062] ACPI: PM: (supports S0 S3 S4 S5) [ 0.188013] ACPI: Using IOAPIC for interrupt routing [ 0.189100] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.190377] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.198775] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.199031] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.200017] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.201077] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.203405] acpiphp: Slot [2] registered [ 0.204080] acpiphp: Slot [5] registered [ 0.204991] acpiphp: Slot [6] registered [ 0.205102] acpiphp: Slot [7] registered [ 0.206108] acpiphp: Slot [8] registered [ 0.207108] acpiphp: Slot [9] registered [ 0.208122] acpiphp: Slot [10] registered [ 0.209190] acpiphp: Slot [3] registered [ 0.210115] acpiphp: Slot [4] registered [ 0.211112] acpiphp: Slot [11] registered [ 0.212081] acpiphp: Slot [12] registered [ 0.213065] acpiphp: Slot [13] registered [ 0.214142] acpiphp: Slot [14] registered [ 0.215093] acpiphp: Slot [15] registered [ 0.216129] acpiphp: Slot [16] registered [ 0.217088] acpiphp: Slot [17] registered [ 0.218106] acpiphp: Slot [18] registered [ 0.219114] acpiphp: Slot [19] registered [ 0.220084] acpiphp: Slot [20] registered [ 0.221090] acpiphp: Slot [21] registered [ 0.222135] acpiphp: Slot [22] registered [ 0.223115] acpiphp: Slot [23] registered [ 0.224142] acpiphp: Slot [24] registered [ 0.225104] acpiphp: Slot [25] registered [ 0.226118] acpiphp: Slot [26] registered [ 0.227122] acpiphp: Slot [27] registered [ 0.228177] acpiphp: Slot [28] registered [ 0.230100] acpiphp: Slot [29] registered [ 0.231134] acpiphp: Slot [30] registered [ 0.233101] acpiphp: Slot [31] registered [ 0.234085] PCI host bridge to bus 0000:00 [ 0.235019] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.237023] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.238018] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.241023] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.243020] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.246024] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.248171] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.251010] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.254320] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.263885] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.269060] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.271017] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.274018] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.277017] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.280439] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.282858] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.286081] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.291471] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.298025] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.313025] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.321000] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.326291] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.334017] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.341015] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.362026] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.373253] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.381022] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.393027] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.421016] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.432736] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.447014] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.455015] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.482025] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.493399] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.501013] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.510014] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.532017] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.542150] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.553024] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.561023] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.581029] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 0.592497] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.599015] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.608015] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.633023] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 0.651619] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.653396] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.656390] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.659405] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.661164] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.666023] iommu: Default domain type: Passthrough [ 0.667563] SCSI subsystem initialized [ 0.670152] ACPI: bus type USB registered [ 0.672125] usbcore: registered new interface driver usbfs [ 0.674084] usbcore: registered new interface driver hub [ 0.676081] usbcore: registered new device driver usb [ 0.678186] pps_core: LinuxPPS API ver. 1 registered [ 0.680013] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.684058] PTP clock support registered [ 0.686093] EDAC MC: Ver: 3.0.0 [ 0.688648] PCI: Using ACPI for IRQ routing [ 0.690949] NetLabel: Initializing [ 0.692014] NetLabel: domain hash size = 128 [ 0.693010] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.695073] NetLabel: unlabeled traffic allowed by default [ 0.697088] vgaarb: loaded [ 0.698237] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.700010] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.704352] clocksource: Switched to clocksource kvm-clock [ 0.808373] VFS: Disk quotas dquot_6.6.0 [ 0.809879] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.812620] *** VALIDATE ramfs *** [ 0.813819] *** VALIDATE hugetlbfs *** [ 0.816482] pnp: PnP ACPI init [ 0.819210] pnp: PnP ACPI: found 6 devices [ 0.836732] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.841017] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.843196] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.845644] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.848349] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.850807] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.853821] NET: Registered protocol family 2 [ 0.857361] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.862203] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.866396] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.871977] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.875125] TCP: Hash tables configured (established 65536 bind 65536) [ 0.877933] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.880883] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.883628] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.886219] NET: Registered protocol family 1 [ 0.888405] RPC: Registered named UNIX socket transport module. [ 0.890592] RPC: Registered udp transport module. [ 0.892222] RPC: Registered tcp transport module. [ 0.893931] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.896226] NET: Registered protocol family 44 [ 0.897657] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.899514] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.901728] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.904239] PCI: CLS 0 bytes, default 64 [ 0.905875] Unpacking initramfs... [ 2.300215] debug: unmapping init [mem 0xffff9db3fcc54000-0xffff9db3fffbffff] [ 2.304388] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.306872] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.309971] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 2.792726] Initialise system trusted keyrings [ 2.794643] Key type blacklist registered [ 2.796357] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.804675] zbud: loaded [ 2.807501] *** VALIDATE nfs *** [ 2.808475] *** VALIDATE nfs4 *** [ 2.810114] pstore: using deflate compression [ 2.813239] Platform Keyring initialized [ 2.917114] NET: Registered protocol family 38 [ 2.920580] Key type asymmetric registered [ 2.922062] Asymmetric key parser 'x509' registered [ 2.923814] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 2.927056] io scheduler mq-deadline registered [ 2.928533] io scheduler kyber registered [ 2.929867] io scheduler bfq registered [ 2.931417] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 2.933893] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 2.936358] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 2.938813] ACPI: Power Button [PWRF] [ 2.943721] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 2.951519] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 2.968204] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 2.976353] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 2.992975] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 3.022765] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.053518] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.059536] Non-volatile memory driver v1.3 [ 3.061530] Linux agpgart interface v0.103 [ 3.090481] virtio_blk virtio1: [vda] 147232 512-byte logical blocks (75.4 MB/71.9 MiB) [ 3.093610] vda: detected capacity change from 0 to 75382784 [ 3.110056] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.113323] vdb: detected capacity change from 0 to 1073741824 [ 3.129881] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.132547] vdc: detected capacity change from 0 to 2621440000 [ 3.152341] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.155722] vdd: detected capacity change from 0 to 2621440000 [ 3.177779] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.180556] vde: detected capacity change from 0 to 4294967296 [ 3.196982] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.199727] vdf: detected capacity change from 0 to 4294967296 [ 3.209434] libphy: Fixed MDIO Bus: probed [ 3.216740] usbcore: registered new interface driver usbserial_generic [ 3.218646] usbserial: USB Serial support registered for generic [ 3.221301] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.226469] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.228414] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.231199] mousedev: PS/2 mouse device common for all mice [ 3.234331] rtc_cmos 00:05: RTC can wake from S4 [ 3.241193] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.241294] rtc_cmos 00:05: registered as rtc0 [ 3.246239] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.248206] intel_pstate: CPU model not supported [ 3.250735] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.253832] hid: raw HID events driver (C) Jiri Kosina [ 3.258494] usbcore: registered new interface driver usbhid [ 3.258560] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.259765] usbhid: USB HID core driver [ 3.259899] drop_monitor: Initializing network drop monitor service [ 3.265560] Initializing XFRM netlink socket [ 3.266707] NET: Registered protocol family 10 [ 3.269812] Segment Routing with IPv6 [ 3.271069] NET: Registered protocol family 17 [ 3.272767] mpls_gso: MPLS GSO support [ 3.277990] RAS: Correctable Errors collector initialized. [ 3.280176] AVX version of gcm_enc/dec engaged. [ 3.281527] AES CTR mode by8 optimization enabled [ 3.354881] sched_clock: Marking stable (3354857167, 0)->(4321792618, -966935451) [ 3.358461] registered taskstats version 1 [ 3.360866] Loading compiled-in X.509 certificates [ 3.362163] zswap: loaded using pool lzo/zbud [ 3.384118] Key type big_key registered [ 3.395447] Key type encrypted registered [ 3.396640] ima: No TPM chip found, activating TPM-bypass! [ 3.398629] ima: Allocated hash algorithm: sha1 [ 3.399914] ima: No architecture policies found [ 3.401362] evm: Initialising EVM extended attributes: [ 3.403107] evm: security.selinux [ 3.404021] evm: security.ima [ 3.404786] evm: security.capability [ 3.405858] evm: HMAC attrs: 0x1 [ 3.408347] rtc_cmos 00:05: setting system clock to 2026-09-11 10:26:47 UTC (1789122407) [ 3.415209] debug: unmapping init [mem 0xffffffffb3a03000-0xffffffffb3bfffff] [ 3.417427] debug: unmapping init [mem 0xffffffffb2782000-0xffffffffb2a58fff] [ 3.425058] Write protecting the kernel read-only data: 28672k [ 3.427819] debug: unmapping init [mem 0xffffffffb0e03000-0xffffffffb0ffffff] [ 3.429882] debug: unmapping init [mem 0xffffffffb1714000-0xffffffffb17fffff] [ 3.461122] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 3.468630] systemd[1]: Detected virtualization kvm. [ 3.470352] systemd[1]: Detected architecture x86-64. [ 3.471733] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.498306] systemd[1]: No hostname configured. [ 3.500241] systemd[1]: Set hostname to . [ 3.502088] random: systemd: uninitialized urandom read (16 bytes read) [ 3.504892] systemd[1]: Initializing machine ID from random generator. [ 3.547530] random: ln: uninitialized urandom read (6 bytes read) [ 3.617743] random: systemd: uninitialized urandom read (16 bytes read) [ 3.621740] systemd[1]: Listening on Journal Socket (/dev/log). [ OK ] Listening on Journal Socket (/dev/log). [ 3.627226] systemd[1]: Reached target Timers. [ OK ] Reached target Timers. [ 3.630730] systemd[1]: Reached target Local File Systems. [ OK ] Reached target Local File Systems. [ OK ] Reached target Slices. [ OK ] Listening on udev Control Socket. [ OK ] Listening on udev Kernel Socket. [ OK ] Listening on Journal Socket. Starting Setup Virtual Console... [ OK ] Started Memstrack Anylazing Service. Starting Journal Service... [ OK ] Reached target Sockets. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. [ OK ] Reached target Swap. [ OK ] Reached target Initrd Root Device. Starting Apply Kernel Variables... Starting 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 Apply Kernel Variables. [ OK ] Started Create Volatile Files and Directories. Starting Create Static Device Nodes in /dev... Starting dracut cmdline hook... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started Journal Service. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 4.190966] device-mapper: uevent: version 1.0.3 [ 4.193324] 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... [ 4.520273] random: fast init done Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. Starting dracut initqueue hook... [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ 4.858071] virtio_net virtio0 ens2: renamed from eth0 [ 4.886441] scsi host0: ata_piix [ 4.904484] scsi host1: ata_piix [ 4.905842] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 4.910172] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 8.551229] dracut-initqueue[581]: RTNETLINK answers: File exists [ 9.910893] random: crng init done [ 9.912332] random: 7 urandom warning(s) missed due to ratelimiting 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. [ 10.265891] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Timers. [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Sockets. [ OK ] Stopped target Paths. [ OK ] Stopped target Slices. [ OK ] Stopped target System Initialization. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. Stopping udev Kernel Device Manager... [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped target Local File Systems. [ OK ] Stopped target Swap. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Closed udev Control Socket. [ OK ] Closed udev Kernel Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 11.308933] printk: systemd: 26 output lines suppressed due to ratelimiting [ 11.574115] SELinux: Disabled at runtime. [ 11.633991] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 11.643188] systemd[1]: Detected virtualization kvm. [ 11.644968] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 12.133829] systemd[1]: initrd-switch-root.service: Succeeded. [ 12.136985] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 12.142117] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 12.147268] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 12.149465] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 12.157138] systemd[1]: Starting Journal Service... Starting Journal Service... [ 12.164968] systemd[1]: Starting Create list of required static device nodes for the current kernel... Starting Create list of required st…ce nodes for the current kernel... [ OK ] Stopped target Switch Root. [ OK ] Created slice system-getty.slice. [ OK ] Stopped target Initrd File Systems. [ OK ] Listening on udev Control Socket. Mounting Kernel Debug File System... [ OK ] Created slice User and Session Slice. Mounting Huge Pages File System... Starting Remount Root and Kernel File Systems... Activating swap /dev/disk/by-label/SWAP... Starting Apply Kernel Variables... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Listening on RPCbind Server Acti[ 12.261136] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS vation Socket. [ OK ] Reached target RPC Port Mapper. [ OK ] Reached target Slices. [ OK ] Listening on Process Core Dump Socket. [ OK ] Listening on udev Kernel Socket. [ OK ] Reached target rpc_pipefs.target. [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. [ OK ] Created slice system-serial\x2dgetty.slice. Mounting POSIX Message Queue File System... Starting udev Coldplug all Devices... [ OK ] Stopped target Initrd Root File System. [ OK ] Started Journal Service. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Mounted Kernel Debug File System. [ OK ] Mounted Huge Pages File System. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Started Apply Kernel Variables. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Reached target Swap. Starting Configure read-only root support... Starting Create Static Device Nodes in /dev... Starting Flush Journal to Persistent Storage... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Reached target Local File Systems (Pre). Mounting /home/green/git/lustre-release... Mounting /mnt... Starting udev Kernel Device Manager... [ OK ] Started udev Coldplug all Devices. [ OK ] Mounted /mnt. [ 12.594608] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 12.894564] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 12.928859] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 13.028705] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 13.046623] EDAC sbridge: Ver: 1.1.2 [ 14.811145] Key type dns_resolver registered [ 15.121068] NFS: Registering the id_resolver key type [ 15.123879] Key type id_resolver registered [ 15.125898] Key type id_legacy registered [ OK ] Started Configure read-only root support. Starting Load/Save Random Seed... [ OK ] Reached target Local File Systems. Starting Rebuild Dynamic Linker Cache... Starting Mark the need to relabel after reboot... Starting Create Volatile Files and Directories... [ OK ] Started Load/Save Random Seed. [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Create Volatile Files and Directories. Starting Update UTMP about System Boot/Shutdown... Starting RPC Bind... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Started daily 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 irqbalance daemon. [ OK ] Started D-Bus System Message Bus. Starting Login Service... [ OK ] Started dnf makecache --timer. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Reached target Timers. Starting Network Manager... Starting Restore /run/initramfs on shutdown... [ OK ] Reached target sshd-keygen.target. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Login Service. [ OK ] Started Network Manager. [ OK ] Reached target Network. Starting Dynamic System Tuning Daemon... Starting GSSAPI Proxy Daemon... Starting OpenSSH server daemon... Starting Network Manager Wait Online... Starting Hostname Service... [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Started OpenSSH server daemon. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... [ OK ] Started Permit User Sessions. [ OK ] Started Getty on tty1. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Command Scheduler. [ OK ] Started Serial Getty on ttyS1. [ OK ] Reached target Login Prompts. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting Notify NFS peers of a restart... Starting Crash recovery kernel arming... Starting System Logging Service... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Starting Authorization Manager... [ OK ] Started Authorization Manager. [ OK ] Started Dynamic System Tuning Daemon. [ OK ] Reached target Multi-User System. [ OK ] Reached target Graphical Interface. Starting Update UTMP about System Runlevel Changes... [ OK ] Started Update UTMP about System Runlevel Changes. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg650-server login: [ 39.842734] libcfs: loading out-of-tree module taints kernel. [ 39.864098] Key type ._llcrypt registered [ 39.865418] Key type .llcrypt registered [ 39.910497] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_hostid [ 56.995991] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing load_modules_local [ 58.365203] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 58.375178] alg: No test for adler32 (adler32-zlib) [ 59.729394] Lustre: Lustre: Build Version: 2.17.57_139_gd84534a [ 60.613868] LNet: Added LNI 192.168.206.150@tcp [8/256/0/180] [ 62.368487] Key type lgssc registered [ 63.994580] Lustre: Echo OBD driver; http://www.lustre.org/ [ 76.031703] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 110.866360] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing load_modules_local [ 122.837754] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 122.871192] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 124.144791] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 124.196872] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 124.296808] Lustre: lustre-MDT0000: new disk, initializing [ 124.373668] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 124.391773] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 128.344910] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 141.506666] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 141.627251] Lustre: 6507:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 141.660755] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 141.664283] Lustre: Skipped 1 previous similar message [ 141.786357] Lustre: lustre-MDT0001: new disk, initializing [ 141.853370] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 141.893178] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 141.914036] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 146.502753] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 151.722475] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 161.113495] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 161.373515] Lustre: lustre-OST0000: new disk, initializing [ 161.378739] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 161.386435] Lustre: 8446:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 161.462111] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 165.986047] hrtimer: interrupt took 2497758 ns [ 166.669959] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 166.936396] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 166.942797] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 167.038064] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 181.064973] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 181.259902] Lustre: lustre-OST0001: new disk, initializing [ 181.264264] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 181.269950] Lustre: 9520:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 181.364154] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 188.057852] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 191.009880] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 191.016774] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 191.101293] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 199.874056] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 209.569309] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 214.799643] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing check_logdir /tmp/testlogs/ [ 219.414317] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing yml_node [ 222.891682] Lustre: DEBUG MARKER: Client: 2.17.57.139 [ 225.166474] Lustre: DEBUG MARKER: MDS: 2.17.57.139 [ 227.936448] Lustre: DEBUG MARKER: OSS: 2.17.57.139 [ 229.325424] Lustre: DEBUG MARKER: -----============= acceptance-small: replay-dual ============----- Fri Sep 11 06:30:32 EDT 2026 [ 244.955292] Lustre: DEBUG MARKER: excepting tests: 14b 21b [ 246.420543] Lustre: DEBUG MARKER: skipping tests SLOW=no: 21b [ 248.003889] Lustre: DEBUG MARKER: === replay-dual: start setup 06:30:51 (1789122651) === [ 253.120054] Lustre: DEBUG MARKER: oleg650-client.virtnet: executing check_config_client /mnt/lustre [ 270.988236] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 274.319467] Lustre: 13375:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 277.810644] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 285.221086] Lustre: Setting parameter lustre.lod.lustre-MDT0000-mdtlov.enable_compr_rotational=1 in log params [ 291.814684] Lustre: Setting parameter lustre.lod.lustre-MDT0001-mdtlov.enable_compr_rotational=1 in log params [ 297.717964] Lustre: DEBUG MARKER: === replay-dual: finish setup 06:31:40 (1789122700) === [ 300.923872] Lustre: DEBUG MARKER: == replay-dual test 0a: expired recovery with lost client ========================================================== 06:31:43 (1789122703) [ 308.572919] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 312.578148] Lustre: Failing over lustre-MDT0000 [ 312.977367] Lustre: server umount lustre-MDT0000 complete [ 315.874525] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 315.887174] 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 [ 316.900106] Lustre: lustre-MDT0000-lwp-MDT0001: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 316.923677] Lustre: Skipped 1 previous similar message [ 320.336151] LustreError: 6517:0:(ldlm_lib.c:1228:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.206.50@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 320.358118] LustreError: 6517:0:(ldlm_lib.c:1228:target_handle_connect()) Skipped 9 previous similar messages [ 322.023227] LustreError: 6521:0:(ldlm_lib.c:1228:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 322.052792] LustreError: 6521:0:(ldlm_lib.c:1228:target_handle_connect()) Skipped 3 previous similar messages [ 325.460068] LustreError: 6516:0:(ldlm_lib.c:1228:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.206.50@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 330.586146] LustreError: 8170:0:(ldlm_lib.c:1228:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.206.50@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 330.615111] LustreError: 8170:0:(ldlm_lib.c:1228:target_handle_connect()) Skipped 6 previous similar messages [ 332.258897] Lustre: 3644:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789122720/real 1789122720] req@ffff9db3498e8780 x1876030876941056/t0(0) o400->MGC192.168.206.150@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789122736 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 332.301908] LustreError: MGC192.168.206.150@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 334.925260] LDISKFS-fs (dm-0): 10 truncates cleaned up [ 334.928264] LDISKFS-fs (dm-0): recovery complete [ 334.940305] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 335.694757] LustreError: 8170:0:(ldlm_lib.c:1228:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.206.50@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 335.715463] LustreError: 8170:0:(ldlm_lib.c:1228:target_handle_connect()) Skipped 5 previous similar messages [ 342.513872] LustreError: 3641:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9db477650000 x1876030876949504/t0(0) o250->MGC192.168.206.150@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 [ 342.806820] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 344.560605] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 347.323816] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 348.146074] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 449.500132] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 449.515189] Lustre: 15618:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 75589e9f-64e7-425f-b298-b47bebf156d4@192.168.206.50@tcp [ 449.551683] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 449.585290] Lustre: 15618:0:(ldlm_lib.c:3014:target_recovery_thread()) too long recovery - read logs [ 449.587638] Lustre: lustre-MDT0000-osp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 449.602194] LustreError: dumping log to /tmp/lustre-log.1789122853.15618 [ 449.626402] Lustre: Skipped 2 previous similar messages [ 449.825899] Lustre: lustre-MDT0000: Recovery over after 1:45, of 3 clients 2 recovered and 1 was evicted. [ 449.889869] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:28 to 0x2c0000401:65) [ 449.890093] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:28 to 0x280000401:65) [ 469.029315] Lustre: DEBUG MARKER: == replay-dual test 0b: lost client during waiting for next transno ========================================================== 06:34:32 (1789122872) [ 475.397815] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 478.010311] Lustre: Failing over lustre-MDT0000 [ 478.101179] Lustre: lustre-MDT0000: Not available for connect from 192.168.206.50@tcp (stopping) [ 478.459181] Lustre: server umount lustre-MDT0000 complete [ 480.226101] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 480.231957] 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 [ 480.243299] Lustre: Skipped 1 previous similar message [ 480.253049] LustreError: 6521:0:(ldlm_lib.c:1228: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. [ 480.270782] LustreError: 6521:0:(ldlm_lib.c:1228:target_handle_connect()) Skipped 10 previous similar messages [ 496.613710] LustreError: 6515:0:(ldlm_lib.c:1228: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. [ 496.643214] LustreError: 6515:0:(ldlm_lib.c:1228:target_handle_connect()) Skipped 18 previous similar messages [ 497.635145] Lustre: 3645:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789122885/real 1789122885] req@ffff9db34a5343c0 x1876030877018752/t0(0) o400->MGC192.168.206.150@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789122901 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 497.689992] LustreError: MGC192.168.206.150@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 502.843043] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 502.846292] LDISKFS-fs (dm-0): recovery complete [ 502.853859] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 507.873983] LustreError: 3641:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9db4764a21c0 x1876030877027200/t0(0) o250->MGC192.168.206.150@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 [ 508.314092] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 508.758319] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 512.238941] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 513.541673] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 525.034407] Lustre: lustre-MDT0000: Denying connection for new client 0962e95a-44c1-40b9-9d50-31fc44a9fb3e (at 192.168.206.50@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:53 [ 530.254647] Lustre: lustre-MDT0000: Denying connection for new client 0962e95a-44c1-40b9-9d50-31fc44a9fb3e (at 192.168.206.50@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:48 [ 535.373570] Lustre: lustre-MDT0000: Denying connection for new client 0962e95a-44c1-40b9-9d50-31fc44a9fb3e (at 192.168.206.50@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:43 [ 540.494320] Lustre: lustre-MDT0000: Denying connection for new client 0962e95a-44c1-40b9-9d50-31fc44a9fb3e (at 192.168.206.50@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:38 [ 545.614141] Lustre: lustre-MDT0000: Denying connection for new client 0962e95a-44c1-40b9-9d50-31fc44a9fb3e (at 192.168.206.50@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:32 [ 549.360456] Lustre: lustre-MDT0001: haven't heard from client 75589e9f-64e7-425f-b298-b47bebf156d4 (at 192.168.206.50@tcp) in 103 seconds. I think it's dead, and I am evicting it. exp ffff9db34739a800, cur 1789122953 deadline 1789122950 last 1789122850 [ 555.855062] Lustre: lustre-MDT0000: Denying connection for new client 0962e95a-44c1-40b9-9d50-31fc44a9fb3e (at 192.168.206.50@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:22 [ 555.881395] Lustre: Skipped 1 previous similar message [ 576.330524] Lustre: lustre-MDT0000: Denying connection for new client 0962e95a-44c1-40b9-9d50-31fc44a9fb3e (at 192.168.206.50@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:02 [ 576.339728] Lustre: Skipped 3 previous similar messages [ 578.500168] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 578.508733] Lustre: 17361:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 664c9f2a-2502-4873-bc3f-cbf16723749e@ [ 578.530441] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 612.174400] Lustre: lustre-MDT0000: Denying connection for new client 0962e95a-44c1-40b9-9d50-31fc44a9fb3e (at 192.168.206.50@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 1 evicted) to recover in 1:07 [ 612.189146] Lustre: Skipped 6 previous similar messages [ 615.918211] Lustre: lustre-MDT0001: haven't heard from client eb0a76ff-e24c-409e-94ef-8586f956857f (at 192.168.206.50@tcp) in 103 seconds. I think it's dead, and I am evicting it. exp ffff9db47cd52800, cur 1789123020 deadline 1789123017 last 1789122917 [ 678.732707] Lustre: lustre-MDT0000: Denying connection for new client 0962e95a-44c1-40b9-9d50-31fc44a9fb3e (at 192.168.206.50@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 1 evicted) to recover in 0:00 [ 678.765736] Lustre: Skipped 12 previous similar messages [ 679.500156] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 679.502839] Lustre: 17361:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client eb0a76ff-e24c-409e-94ef-8586f956857f@192.168.206.50@tcp [ 679.534611] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 679.544166] Lustre: 17361:0:(ldlm_lib.c:2148:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 679.568332] Lustre: 17361:0:(ldlm_lib.c:3014:target_recovery_thread()) too long recovery - read logs [ 679.568834] Lustre: lustre-MDT0000-osp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 679.581615] LustreError: dumping log to /tmp/lustre-log.1789123083.17361 [ 679.587666] Lustre: Skipped 2 previous similar messages [ 679.788870] Lustre: lustre-MDT0000: Recovery over after 2:51, of 3 clients 1 recovered and 2 were evicted. [ 679.844838] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:28 to 0x280000401:97) [ 679.845284] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:28 to 0x2c0000401:97) [ 691.997202] Lustre: DEBUG MARKER: == replay-dual test 1: |X| simple create ================= 06:38:14 (1789123094) [ 700.427753] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 702.337115] Lustre: Failing over lustre-MDT0000 [ 702.628221] Lustre: server umount lustre-MDT0000 complete [ 702.955596] 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 [ 702.961189] Lustre: Skipped 3 previous similar messages [ 702.966727] LustreError: 6516:0:(ldlm_lib.c:1228: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. [ 702.997574] LustreError: 6516:0:(ldlm_lib.c:1228:target_handle_connect()) Skipped 17 previous similar messages [ 724.448116] Lustre: 3644:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789123112/real 1789123112] req@ffff9db448dfda40 x1876030877117312/t0(0) o400->MGC192.168.206.150@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789123128 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 724.474323] LustreError: MGC192.168.206.150@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 724.812038] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 724.814952] LDISKFS-fs (dm-0): recovery complete [ 724.821959] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 734.697214] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xa43d17e00a054428 [ 734.724126] Lustre: MGC192.168.206.150@tcp: Connection restored to 0@lo (at 0@lo) [ 735.116271] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 735.252602] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 736.057480] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 739.467073] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 740.490550] Lustre: lustre-MDT0000: Recovery over after 0:04, of 3 clients 3 recovered and 0 were evicted. [ 740.568371] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:129) [ 740.573140] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:129) [ 748.821491] Lustre: DEBUG MARKER: oleg650-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 750.305552] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 759.867321] Lustre: DEBUG MARKER: == replay-dual test 2: |X| mkdir adir ==================== 06:39:22 (1789123162) [ 767.764800] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 769.344594] Lustre: Failing over lustre-MDT0000 [ 769.567423] Lustre: server umount lustre-MDT0000 complete [ 771.047404] 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 [ 771.064198] LustreError: 6520:0:(ldlm_lib.c:1228: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. [ 771.082171] Lustre: Skipped 4 previous similar messages [ 771.135101] LustreError: 6520:0:(ldlm_lib.c:1228:target_handle_connect()) Skipped 47 previous similar messages [ 787.429860] Lustre: 3645:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789123175/real 1789123175] req@ffff9db44879e940 x1876030877153792/t0(0) o400->MGC192.168.206.150@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789123191 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 787.482867] LustreError: MGC192.168.206.150@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 795.965067] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 795.968612] LDISKFS-fs (dm-0): recovery complete [ 795.974627] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 797.088540] LustreError: 21016:0:(import.c:339:ptlrpc_invalidate_import()) MGS: timeout waiting for callback (1 != 0) [ 797.100816] LustreError: 21016:0:(import.c:363:ptlrpc_invalidate_import()) @@@ still on sending list req@ffff9db46e5f7840 x1876030877159808/t0(0) o250->MGC192.168.206.150@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 1789123201 ref 1 fl Rpc:NQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 797.133872] LustreError: 21016:0:(import.c:373:ptlrpc_invalidate_import()) MGS: Unregistering RPCs found (0). Network is sluggish? Waiting for them to error out. [ 797.668553] LustreError: 3641:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9db34634da40 x1876030877162496/t0(0) o250->MGC192.168.206.150@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 [ 798.118811] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 798.219735] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 799.391669] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 803.316857] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 803.323692] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 803.337668] Lustre: Skipped 4 previous similar messages [ 803.416822] Lustre: lustre-MDT0000: Recovery over after 0:04, of 3 clients 3 recovered and 0 were evicted. [ 803.473502] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:161) [ 803.485991] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:161) [ 810.980893] Lustre: DEBUG MARKER: oleg650-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 812.246648] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 819.652404] Lustre: DEBUG MARKER: == replay-dual test 3: |X| mkdir adir, mkdir adir/bdir === 06:40:22 (1789123222) [ 827.657020] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 829.277359] Lustre: Failing over lustre-MDT0000 [ 829.408854] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 829.415407] 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 [ 829.421889] Lustre: Skipped 2 previous similar messages [ 829.470203] Lustre: server umount lustre-MDT0000 complete [ 850.425377] Lustre: 3644:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789123238/real 1789123238] req@ffff9db446a16580 x1876030877194112/t0(0) o400->MGC192.168.206.150@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789123254 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 850.497845] LustreError: MGC192.168.206.150@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 852.458704] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 852.461881] LDISKFS-fs (dm-0): recovery complete [ 852.470520] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 860.133737] LustreError: 3641:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9db467e9b840 x1876030877202560/t0(0) o250->MGC192.168.206.150@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 [ 860.504080] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 861.536882] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 865.646930] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 865.793886] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 865.799477] Lustre: Skipped 3 previous similar messages [ 865.892159] Lustre: lustre-MDT0000: Recovery over after 0:04, of 3 clients 3 recovered and 0 were evicted. [ 865.928311] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:193) [ 865.935037] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:193) [ 875.280856] Lustre: DEBUG MARKER: oleg650-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 877.195470] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 885.998053] Lustre: DEBUG MARKER: == replay-dual test 4: |X| mkdir adir (-EEXIST), mkdir adir/bdir ========================================================== 06:41:28 (1789123288) [ 893.896476] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 895.909777] Lustre: Failing over lustre-MDT0000 [ 896.462422] Lustre: server umount lustre-MDT0000 complete [ 896.997530] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 897.007211] 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 [ 897.024912] Lustre: Skipped 3 previous similar messages [ 899.560319] LustreError: 8170:0:(ldlm_lib.c:1228: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. [ 899.585554] LustreError: 8170:0:(ldlm_lib.c:1228:target_handle_connect()) Skipped 85 previous similar messages [ 915.941250] Lustre: 3642:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789123303/real 1789123303] req@ffff9db467e9a940 x1876030877234944/t0(0) o400->MGC192.168.206.150@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789123319 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 915.987385] LustreError: MGC192.168.206.150@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 918.098551] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 918.101295] LDISKFS-fs (dm-0): recovery complete [ 918.107942] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 926.429754] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 926.439324] Lustre: Skipped 1 previous similar message [ 926.481442] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 927.344375] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 929.747879] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 931.838375] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 931.844123] Lustre: Skipped 3 previous similar messages [ 931.926296] Lustre: lustre-MDT0000: Recovery over after 0:04, of 3 clients 3 recovered and 0 were evicted. [ 931.967029] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:225) [ 931.967721] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:225) [ 937.740395] Lustre: DEBUG MARKER: oleg650-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 939.168392] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 946.978146] Lustre: DEBUG MARKER: == replay-dual test 5: open, unlink |X| close ============ 06:42:30 (1789123350) [ 954.025392] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 955.898305] Lustre: Failing over lustre-MDT0000 [ 956.041096] Lustre: server umount lustre-MDT0000 complete [ 957.415616] 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 [ 957.428342] Lustre: Skipped 6 previous similar messages [ 973.792340] Lustre: 3642:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789123361/real 1789123361] req@ffff9db475e0bc00 x1876030877268224/t0(0) o400->MGC192.168.206.150@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789123377 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 973.813891] LustreError: MGC192.168.206.150@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 977.461630] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 977.467628] LDISKFS-fs (dm-0): recovery complete [ 977.495163] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 983.327280] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 983.949717] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 987.372509] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 988.800718] Lustre: lustre-MDT0000: Recovery over after 0:05, of 3 clients 3 recovered and 0 were evicted. [ 988.831983] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:257) [ 988.833018] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:257) [ 996.553867] Lustre: DEBUG MARKER: oleg650-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 997.930541] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1005.301671] Lustre: DEBUG MARKER: == replay-dual test 6: open1, open2, unlink |X| close1 [fail mds1] close2 ========================================================== 06:43:28 (1789123408) [ 1012.430684] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1014.157352] Lustre: Failing over lustre-MDT0000 [ 1014.250045] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1014.264279] Lustre: Skipped 2 previous similar messages [ 1014.405706] Lustre: server umount lustre-MDT0000 complete [ 1035.461780] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1035.463822] LDISKFS-fs (dm-0): recovery complete [ 1035.469513] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1035.597900] LustreError: MGC192.168.206.150@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1035.948495] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1036.108841] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 1040.337799] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 1040.888593] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 1040.893736] Lustre: Skipped 7 previous similar messages [ 1040.960572] Lustre: lustre-MDT0000: Recovery over after 0:04, of 3 clients 3 recovered and 0 were evicted. [ 1041.010060] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:289) [ 1041.011066] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:289) [ 1049.596988] Lustre: DEBUG MARKER: oleg650-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1051.034778] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1058.865562] Lustre: DEBUG MARKER: == replay-dual test 8: replay of resent request ========== 06:44:21 (1789123461) [ 1065.796207] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1066.663151] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 1066.667855] LustreError: 6516:0:(ldlm_lib.c:3411:target_send_reply_msg()) @@@ dropping reply req@ffff9db3481df0c0 x1876030858217600/t38654705670(0) o36->0962e95a-44c1-40b9-9d50-31fc44a9fb3e@192.168.206.50@tcp:736/0 lens 512/448 e 0 to 0 dl 1789123481 ref 1 fl Interpret:/200/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 1083.250683] Lustre: lustre-MDT0000: Client 0962e95a-44c1-40b9-9d50-31fc44a9fb3e (at 192.168.206.50@tcp) reconnecting [ 1083.287310] Lustre: 6516:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9db46e630000 x1876030858217600/t38654705670(0) o36->0962e95a-44c1-40b9-9d50-31fc44a9fb3e@192.168.206.50@tcp:753/0 lens 512/2880 e 0 to 0 dl 1789123498 ref 1 fl Interpret:/202/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 1085.543769] Lustre: Failing over lustre-MDT0000 [ 1085.805713] Lustre: server umount lustre-MDT0000 complete [ 1086.951064] 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 [ 1086.952703] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1086.962737] Lustre: Skipped 5 previous similar messages [ 1103.328301] Lustre: 3643:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789123491/real 1789123491] req@ffff9db44af0c780 x1876030877340800/t0(0) o400->MGC192.168.206.150@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789123507 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1103.354895] LustreError: MGC192.168.206.150@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1107.918920] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1107.920663] LDISKFS-fs (dm-0): recovery complete [ 1107.927913] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1113.575986] LustreError: 3641:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9db46e746d00 x1876030877350400/t0(0) o250->MGC192.168.206.150@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 [ 1113.821717] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1113.832237] Lustre: Skipped 2 previous similar messages [ 1113.914406] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1113.938547] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 1117.556323] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 1119.275765] Lustre: lustre-MDT0000: Recovery over after 0:06, of 3 clients 3 recovered and 0 were evicted. [ 1119.321648] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:321) [ 1119.321695] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:321) [ 1125.612575] Lustre: DEBUG MARKER: oleg650-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1127.140683] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1134.577981] Lustre: DEBUG MARKER: == replay-dual test 9: resending a replayed create ======= 06:45:37 (1789123537) [ 1140.711306] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1143.065213] Lustre: Failing over lustre-MDT0000 [ 1143.336261] Lustre: server umount lustre-MDT0000 complete [ 1144.804453] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1160.039389] LustreError: 13915:0:(ldlm_lib.c:1228:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.206.50@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1160.055787] LustreError: 13915:0:(ldlm_lib.c:1228:target_handle_connect()) Skipped 161 previous similar messages [ 1165.097653] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1165.100775] LDISKFS-fs (dm-0): recovery complete [ 1165.108795] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1170.408641] LustreError: 3641:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9db475e18000 x1876030877381760/t0(0) o250->MGC192.168.206.150@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 [ 1170.760716] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1174.632895] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 1176.058381] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1176.070382] Lustre: Skipped 7 previous similar messages [ 1176.074424] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 1176.078572] LustreError: 32858:0:(ldlm_lib.c:3411:target_send_reply_msg()) @@@ dropping reply req@ffff9db44af121c0 x1876030858234240/t42949672962(42949672962) o36->0962e95a-44c1-40b9-9d50-31fc44a9fb3e@192.168.206.50@tcp:86/0 lens 528/448 e 0 to 0 dl 1789123586 ref 1 fl Complete:/204/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 1186.677939] Lustre: lustre-MDT0000: Client 0962e95a-44c1-40b9-9d50-31fc44a9fb3e (at 192.168.206.50@tcp) reconnected, waiting for 3 clients in recovery for 1:29 [ 1186.809701] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:353) [ 1186.810774] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:353) [ 1192.237391] Lustre: DEBUG MARKER: oleg650-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1193.764550] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1202.388630] Lustre: DEBUG MARKER: == replay-dual test 10: resending a replayed unlink ====== 06:46:45 (1789123605) [ 1209.183589] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1211.759126] Lustre: Failing over lustre-MDT0000 [ 1211.880737] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1211.893626] Lustre: Skipped 4 previous similar messages [ 1212.141974] Lustre: server umount lustre-MDT0000 complete [ 1233.655676] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1233.657513] LDISKFS-fs (dm-0): recovery complete [ 1233.668674] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1233.794381] LustreError: MGC192.168.206.150@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1233.807028] LustreError: Skipped 1 previous similar message [ 1238.230592] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 1239.073209] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 1239.082669] LustreError: 34913:0:(ldlm_lib.c:3411:target_send_reply_msg()) @@@ dropping reply req@ffff9db47bc2de00 x1876030858252928/t47244640260(47244640260) o36->0962e95a-44c1-40b9-9d50-31fc44a9fb3e@192.168.206.50@tcp:152/0 lens 528/448 e 0 to 0 dl 1789123652 ref 1 fl Complete:/204/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 1254.309960] Lustre: lustre-MDT0000: Client 0962e95a-44c1-40b9-9d50-31fc44a9fb3e (at 192.168.206.50@tcp) reconnected, waiting for 3 clients in recovery for 1:25 [ 1254.423676] Lustre: lustre-MDT0000: Recovery over after 0:17, of 3 clients 3 recovered and 0 were evicted. [ 1254.431614] Lustre: Skipped 1 previous similar message [ 1254.480740] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:385) [ 1254.483334] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:385) [ 1260.586811] Lustre: DEBUG MARKER: oleg650-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1262.065887] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1271.484804] Lustre: DEBUG MARKER: == replay-dual test 11: both clients timeout during replay ========================================================== 06:47:54 (1789123674) [ 1278.932777] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1281.645349] Lustre: Failing over lustre-MDT0000 [ 1282.026454] Lustre: server umount lustre-MDT0000 complete [ 1285.089190] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1285.097806] 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 [ 1285.108767] Lustre: Skipped 13 previous similar messages [ 1301.473031] Lustre: 3644:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789123689/real 1789123689] req@ffff9db446a170c0 x1876030877449088/t0(0) o400->MGC192.168.206.150@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789123705 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1301.519504] Lustre: 3644:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 1303.951233] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1303.954247] LDISKFS-fs (dm-0): recovery complete [ 1303.965101] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1311.713533] LustreError: 3641:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9db347fd8f00 x1876030877457536/t0(0) o250->MGC192.168.206.150@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 [ 1312.231205] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1312.243035] Lustre: Skipped 1 previous similar message [ 1313.261626] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 1313.273155] Lustre: Skipped 2 previous similar messages [ 1316.871517] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 1317.390389] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 1317.392568] LustreError: 36978:0:(ldlm_lib.c:3411:target_send_reply_msg()) @@@ dropping reply req@ffff9db347fda1c0 x1876030858270208/t51539607554(51539607554) o36->0962e95a-44c1-40b9-9d50-31fc44a9fb3e@192.168.206.50@tcp:228/0 lens 528/448 e 0 to 0 dl 1789123728 ref 1 fl Complete:/204/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 1324.673776] Lustre: DEBUG MARKER: oleg650-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1328.511261] Lustre: lustre-MDT0000: Client 0962e95a-44c1-40b9-9d50-31fc44a9fb3e (at 192.168.206.50@tcp) reconnected, waiting for 3 clients in recovery for 1:28 [ 1328.699864] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:417) [ 1328.703245] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:417) [ 1330.653937] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 4 sec [ 1338.175506] Lustre: DEBUG MARKER: == replay-dual test 12: open resend timeout ============== 06:49:01 (1789123741) [ 1345.385218] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1348.275531] Lustre: Failing over lustre-MDT0000 [ 1348.521431] Lustre: server umount lustre-MDT0000 complete [ 1349.089880] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1369.552811] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1369.556324] LDISKFS-fs (dm-0): recovery complete [ 1369.563210] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1379.809626] LustreError: 3641:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9db449852580 x1876030877495296/t0(0) o250->MGC192.168.206.150@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 [ 1380.179260] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1380.189454] Lustre: Skipped 3 previous similar messages [ 1384.076667] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 1385.573137] Lustre: *** cfs_fail_loc=302, val=2147483648*** [ 1402.239351] Lustre: lustre-MDT0000: Client 0962e95a-44c1-40b9-9d50-31fc44a9fb3e (at 192.168.206.50@tcp) reconnected, waiting for 3 clients in recovery for 1:24 [ 1402.422279] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:449) [ 1402.423613] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:449) [ 1411.345156] Lustre: DEBUG MARKER: == replay-dual test 13: close resend timeout ============= 06:50:14 (1789123814) [ 1419.592881] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1422.363678] Lustre: Failing over lustre-MDT0000 [ 1422.630697] Lustre: server umount lustre-MDT0000 complete [ 1422.818461] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1442.785136] Lustre: 3645:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789123830/real 1789123830] req@ffff9db34ad99a40 x1876030877525760/t0(0) o400->MGC192.168.206.150@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789123846 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1442.808148] Lustre: 3645:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 1444.078635] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1444.081057] LDISKFS-fs (dm-0): recovery complete [ 1444.086941] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1452.436903] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1452.449045] Lustre: Skipped 1 previous similar message [ 1456.661340] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 1457.651049] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 1457.668547] Lustre: Skipped 15 previous similar messages [ 1457.741189] Lustre: *** cfs_fail_loc=115, val=2147483648*** [ 1474.396648] Lustre: lustre-MDT0000: Client 0962e95a-44c1-40b9-9d50-31fc44a9fb3e (at 192.168.206.50@tcp) reconnected, waiting for 3 clients in recovery for 1:24 [ 1474.494602] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:481) [ 1474.497500] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:481) [ 1479.682823] Lustre: DEBUG MARKER: SKIP: replay-dual test_14b skipping ALWAYS excluded test 14b [ 1481.241199] Lustre: DEBUG MARKER: == replay-dual test 15a: timeout waiting for lost client during replay, 1 client completes ========================================================== 06:51:24 (1789123884) [ 1488.118813] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1491.596477] Lustre: Failing over lustre-MDT0000 [ 1492.081421] Lustre: server umount lustre-MDT0000 complete [ 1509.856733] LustreError: MGC192.168.206.150@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1509.883365] LustreError: Skipped 3 previous similar messages [ 1515.395677] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1515.399094] LDISKFS-fs (dm-0): recovery complete [ 1515.406739] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1523.548095] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 1589.501516] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 1589.509963] Lustre: 42657:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 1a80c5ad-2df3-4bc9-a7e4-700360658954@ [ 1589.522641] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 1590.236983] Lustre: lustre-MDT0000: Recovery over after 1:11, of 3 clients 2 recovered and 1 was evicted. [ 1590.240242] Lustre: Skipped 3 previous similar messages [ 1590.259443] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:495 to 0x2c0000401:513) [ 1590.259452] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:494 to 0x280000401:513) [ 1597.315315] Lustre: DEBUG MARKER: oleg650-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1599.308843] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1612.298428] Lustre: DEBUG MARKER: == replay-dual test 15c: remove multiple OST orphans ===== 06:53:35 (1789124015) [ 1620.047392] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1714.059874] Lustre: Failing over lustre-MDT0000 [ 1714.149958] 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 [ 1714.151982] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1714.178495] Lustre: Skipped 15 previous similar messages [ 1714.189270] Lustre: Skipped 3 previous similar messages [ 1714.429212] Lustre: server umount lustre-MDT0000 complete [ 1716.564314] LustreError: 8170:0:(ldlm_lib.c:1228:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.206.50@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1716.580134] LustreError: 8170:0:(ldlm_lib.c:1228:target_handle_connect()) Skipped 202 previous similar messages [ 1735.648124] Lustre: 3643:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789124123/real 1789124123] req@ffff9db35135e940 x1876030877673984/t0(0) o400->MGC192.168.206.150@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789124139 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1735.669658] Lustre: 3643:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 1737.457889] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1737.465197] LDISKFS-fs (dm-0): recovery complete [ 1737.472249] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1745.889330] LustreError: 3641:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9db476498000 x1876030877682048/t0(0) o250->MGC192.168.206.150@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 [ 1746.357455] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1746.371019] Lustre: Skipped 1 previous similar message [ 1747.351271] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 1747.371739] Lustre: Skipped 3 previous similar messages [ 1751.009527] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 1817.500360] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 1817.504331] Lustre: 44668:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 2ce215eb-4c03-4efe-a43b-6729d0030f7e@ [ 1817.515620] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 1817.613832] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:495 to 0x2c0000401:1537) [ 1817.616487] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:494 to 0x280000401:1537) [ 1822.973094] Lustre: DEBUG MARKER: oleg650-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1824.194587] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1832.648897] Lustre: DEBUG MARKER: == replay-dual test 16: fail MDS during recovery (3571) == 06:57:15 (1789124235) [ 1840.874535] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1843.372695] Lustre: Failing over lustre-MDT0000 [ 1843.674578] Lustre: server umount lustre-MDT0000 complete [ 1848.289693] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1864.937683] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1864.943149] LDISKFS-fs (dm-0): recovery complete [ 1864.972408] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1874.933241] LustreError: 3641:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9db47bc40000 x1876030877741696/t0(0) o250->MGC192.168.206.150@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 [ 1879.953721] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 1903.819833] Lustre: Failing over lustre-MDT0000 [ 1903.834259] LustreError: 47119:0:(ldlm_lib.c:3067:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 1903.840717] Lustre: 46646:0:(ldlm_lib.c:2467:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 1903.846106] Lustre: 46646:0:(ldlm_lib.c:1977:abort_req_replay_queue()) @@@ aborted: req@ffff9db350ade580 x1876030860718976/t0(73014444033) o36->0962e95a-44c1-40b9-9d50-31fc44a9fb3e@192.168.206.50@tcp:61/0 lens 528/0 e 2 to 0 dl 1789124316 ref 1 fl Complete:/204/ffffffff rc 0/-1 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 1903.865547] Lustre: lustre-MDT0000-osd: cancel update llog [0x200000400:0x1:0x0] [ 1903.880620] Lustre: lustre-MDT0000: Not available for connect from 192.168.206.50@tcp (stopping) [ 1903.900404] Lustre: lustre-MDT0001-osp-MDT0000: cancel update llog [0x240000401:0x1:0x0] [ 1903.910331] LustreError: 46646:0:(client.c:1394:ptlrpc_import_delay_req()) @@@ IMP_CLOSED req@ffff9db3510fad00 x1876030877762816/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 [ 1903.933403] LustreError: 46646:0:(fid_request.c:217:seq_client_alloc_seq()) cli-cli-lustre-MDT0001-osp-MDT0000: Cannot allocate new meta-sequence: rc = -5 [ 1903.939446] LustreError: 46646:0:(fid_request.c:321:seq_client_alloc_fid()) cli-cli-lustre-MDT0001-osp-MDT0000: Can't allocate new sequence: rc = -5 [ 1904.127506] Lustre: server umount lustre-MDT0000 complete [ 1921.757140] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1922.088566] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1922.091486] Lustre: Skipped 4 previous similar messages [ 1926.430953] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 1994.500362] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 1994.503294] Lustre: 47578:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 1dddbedb-f4ff-435a-a525-d12c8788ee2c@ [ 1994.528686] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 1995.098242] Lustre: lustre-MDT0000-osp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1995.108125] Lustre: Skipped 17 previous similar messages [ 1995.146625] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1550 to 0x280000401:1569) [ 1995.150872] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1551 to 0x2c0000401:1569) [ 2000.101788] Lustre: DEBUG MARKER: oleg650-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2001.633031] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2010.378315] Lustre: DEBUG MARKER: == replay-dual test 17: fail OST during recovery (3571) == 07:00:13 (1789124413) [ 2018.367683] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 2020.653116] Lustre: Failing over lustre-OST0000 [ 2020.859323] Lustre: server umount lustre-OST0000 complete [ 2044.052474] LDISKFS-fs (dm-2): 3 truncates cleaned up [ 2044.055274] LDISKFS-fs (dm-2): recovery complete [ 2044.061124] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2051.197556] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 2075.524537] Lustre: Failing over lustre-OST0000 [ 2075.531342] LustreError: 50105:0:(ldlm_lib.c:3067:target_stop_recovery_thread()) lustre-OST0000: Aborting recovery [ 2075.537987] Lustre: 49528:0:(ldlm_lib.c:2467:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 2075.543762] Lustre: 49528:0:(ldlm_lib.c:2467:target_recovery_overseer()) Skipped 2 previous similar messages [ 2075.549827] LustreError: 49528:0:(ofd_obd.c:1328:ofd_iocontrol()) lustre-OST0000: iocontrol from 'tgt_recover_0' cmd=c00866c1 _IOWR('f', 193, 8) unrecognized: rc = -25 [ 2075.796857] Lustre: server umount lustre-OST0000 complete [ 2094.057312] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2100.893743] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 2165.500245] Lustre: lustre-OST0000: recovery is timed out, evict stale exports [ 2165.506247] Lustre: 50548:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-OST0000: disconnect stale client ea82d09f-e274-4e54-b3d2-ff27289a1f26@ [ 2165.517995] Lustre: lustre-OST0000: disconnecting 1 stale clients [ 2165.548151] Lustre: lustre-OST0000: Recovery over after 1:10, of 4 clients 3 recovered and 1 was evicted. [ 2165.560935] Lustre: Skipped 4 previous similar messages [ 2171.222228] Lustre: DEBUG MARKER: oleg650-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 2172.804596] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 2181.579936] Lustre: DEBUG MARKER: == replay-dual test 18: ldlm_handle_enqueue succeeds on evicted export (3822) ========================================================== 07:03:04 (1789124584) [ 2185.445855] LustreError: 6515:0:(ldlm_lockd.c:1361:ldlm_handle_enqueue()) cfs_fail_timeout id 30b sleeping for 40000ms [ 2225.512286] LustreError: 6515:0:(ldlm_lockd.c:1361:ldlm_handle_enqueue()) cfs_fail_timeout id 30b awake [ 2239.248690] Lustre: DEBUG MARKER: == replay-dual test 19: resend of open request =========== 07:04:02 (1789124642) [ 2246.571198] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2248.033659] Lustre: *** cfs_fail_loc=157, val=2147483648*** [ 2248.040451] LustreError: 51613:0:(ldlm_lib.c:3411:target_send_reply_msg()) @@@ dropping reply req@ffff9db448b783c0 x1876030860842752/t0(0) o101->0962e95a-44c1-40b9-9d50-31fc44a9fb3e@192.168.206.50@tcp:478/0 lens 576/688 e 0 to 0 dl 1789124733 ref 1 fl Interpret:/600/0 rc 0/0 job:'createmany.0' uid:0 gid:0 projid:0 [ 2333.594846] Lustre: lustre-MDT0000: Client 0962e95a-44c1-40b9-9d50-31fc44a9fb3e (at 192.168.206.50@tcp) reconnecting [ 2337.214282] Lustre: Failing over lustre-MDT0000 [ 2337.638426] Lustre: server umount lustre-MDT0000 complete [ 2338.277731] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 2338.291349] LustreError: Skipped 1 previous similar message [ 2338.295750] 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 [ 2338.308025] Lustre: Skipped 9 previous similar messages [ 2338.317799] LustreError: 6521:0:(ldlm_lib.c:1228: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. [ 2338.341645] LustreError: 6521:0:(ldlm_lib.c:1228:target_handle_connect()) Skipped 103 previous similar messages [ 2357.664380] Lustre: 3645:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789124745/real 1789124745] req@ffff9db448b70000 x1876030877970304/t0(0) o400->MGC192.168.206.150@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789124761 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2357.684672] Lustre: 3645:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 4 previous similar messages [ 2357.692324] LustreError: MGC192.168.206.150@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2357.703944] LustreError: Skipped 3 previous similar messages [ 2359.110447] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2359.115084] LDISKFS-fs (dm-0): recovery complete [ 2359.123274] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2366.950036] LustreError: 3641:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9db47ccf2940 x1876030877978368/t0(0) o250->MGC192.168.206.150@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 [ 2367.416448] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 2367.430706] Lustre: Skipped 4 previous similar messages [ 2368.233736] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 2368.249108] Lustre: Skipped 4 previous similar messages [ 2371.958924] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 2372.632651] Lustre: 53198:0:(ldlm_lib.c:2148:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 2372.848477] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1584 to 0x2c0000401:1601) [ 2372.849303] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1584 to 0x280000401:1601) [ 2380.668775] Lustre: DEBUG MARKER: oleg650-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2382.214186] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2389.505326] Lustre: DEBUG MARKER: == replay-dual test 20: recovery time is not increasing == 07:06:33 (1789124793) [ 2396.179547] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2398.121283] Lustre: Failing over lustre-MDT0000 [ 2398.184327] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2398.194995] Lustre: Skipped 3 previous similar messages [ 2398.363269] Lustre: server umount lustre-MDT0000 complete [ 2418.551875] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2418.554527] LDISKFS-fs (dm-0): recovery complete [ 2418.560659] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2423.128708] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 2560.500211] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 2560.510955] Lustre: 55146:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 7c049cf0-024f-4b69-9061-d9a9e2926496@ [ 2560.521890] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 2560.565721] Lustre: 55146:0:(ldlm_lib.c:2148:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 2560.595710] Lustre: 55146:0:(ldlm_lib.c:2148:extend_recovery_timer()) Skipped 6 previous similar messages [ 2560.712547] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1603 to 0x280000401:1633) [ 2560.713231] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1584 to 0x2c0000401:1633) [ 2567.504752] Lustre: DEBUG MARKER: oleg650-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2568.920559] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2577.791455] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2579.748367] Lustre: Failing over lustre-MDT0000 [ 2580.165332] Lustre: server umount lustre-MDT0000 complete [ 2601.273474] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2601.277233] LDISKFS-fs (dm-0): recovery complete [ 2601.295222] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2609.644612] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xa43d17e00a07c2ef [ 2609.655141] Lustre: MGC192.168.206.150@tcp: Connection restored to 0@lo (at 0@lo) [ 2609.658073] Lustre: Skipped 10 previous similar messages [ 2609.969181] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 2609.983094] Lustre: Skipped 4 previous similar messages [ 2615.289422] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 2750.500335] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 2750.508847] Lustre: 56933:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 6375d809-91bc-4cd0-818b-338089b9cbe1@ [ 2750.529474] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 2750.556826] Lustre: 56933:0:(ldlm_lib.c:2148:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 2750.571815] Lustre: 56933:0:(ldlm_lib.c:2148:extend_recovery_timer()) Skipped 4 previous similar messages [ 2750.735142] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1584 to 0x2c0000401:1665) [ 2750.735455] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1635 to 0x280000401:1665) [ 2757.818638] Lustre: DEBUG MARKER: oleg650-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2759.447278] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2769.347172] Lustre: DEBUG MARKER: == replay-dual test 21a: commit on sharing =============== 07:12:52 (1789125172) [ 2778.065198] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2780.264116] Lustre: Failing over lustre-MDT0000 [ 2780.898249] Lustre: server umount lustre-MDT0000 complete [ 2803.943787] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2803.949199] LDISKFS-fs (dm-0): recovery complete [ 2803.965107] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2815.960749] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 2952.500222] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 2952.507624] Lustre: 58962:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 43c79665-b60c-431f-865a-ef58d2c1f99d@ [ 2952.523754] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 2952.570861] Lustre: 58962:0:(ldlm_lib.c:2148:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 2952.578969] Lustre: 58962:0:(ldlm_lib.c:2148:extend_recovery_timer()) Skipped 4 previous similar messages [ 2952.592838] Lustre: lustre-MDT0000: Recovery over after 2:20, of 3 clients 2 recovered and 1 was evicted. [ 2952.602160] Lustre: Skipped 3 previous similar messages [ 2952.637788] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1667 to 0x2c0000401:1697) [ 2952.640819] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1635 to 0x280000401:1697) [ 2960.197550] Lustre: DEBUG MARKER: SKIP: replay-dual test_21b skipping SLOW test 21b [ 2961.576698] Lustre: DEBUG MARKER: == replay-dual test 22a: c1 lfs mkdir -i 1 dir1, M1 drop reply [ 2962.706314] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 2962.712060] LustreError: 13915:0:(ldlm_lib.c:3411:target_send_reply_msg()) @@@ dropping reply req@ffff9db44aeb0000 x1876030860964480/t4294967333(0) o36->0962e95a-44c1-40b9-9d50-31fc44a9fb3e@192.168.206.50@tcp:436/0 lens 560/448 e 0 to 0 dl 1789125446 ref 1 fl Interpret:/200/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 2965.113830] Lustre: Failing over lustre-MDT0001 [ 2965.345833] Lustre: server umount lustre-MDT0001 complete [ 2968.419405] LustreError: 13915:0:(ldlm_lib.c:1228:target_handle_connect()) lustre-MDT0001: not available for connect from 192.168.206.50@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 2968.437064] LustreError: 13915:0:(ldlm_lib.c:1228:target_handle_connect()) Skipped 137 previous similar messages [ 2970.082611] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 2970.092102] Lustre: lustre-MDT0001-lwp-OST0000: Connection to lustre-MDT0001 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 2970.095032] LustreError: Skipped 2 previous similar messages [ 2970.117806] Lustre: Skipped 17 previous similar messages [ 2983.870610] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2984.309487] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 2984.319103] Lustre: Skipped 3 previous similar messages [ 2986.078118] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 2986.085110] Lustre: Skipped 3 previous similar messages [ 2988.227410] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 2989.628263] Lustre: 8170:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9db350ad12c0 x1876030860964480/t4294967333(0) o36->0962e95a-44c1-40b9-9d50-31fc44a9fb3e@192.168.206.50@tcp:463/0 lens 560/2880 e 0 to 0 dl 1789125473 ref 1 fl Interpret:/202/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 2997.443096] Lustre: DEBUG MARKER: oleg650-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 2999.190312] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3010.405496] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3012.848570] Lustre: Failing over lustre-MDT0000 [ 3013.188805] Lustre: server umount lustre-MDT0000 complete [ 3031.520270] Lustre: 3645:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789125419/real 1789125419] req@ffff9db4487ecf00 x1876030878276224/t0(0) o400->MGC192.168.206.150@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789125435 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3031.548596] Lustre: 3645:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 3031.556814] LustreError: MGC192.168.206.150@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3031.567915] LustreError: Skipped 3 previous similar messages [ 3035.289156] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3035.291358] LDISKFS-fs (dm-0): recovery complete [ 3035.303075] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3041.762366] LustreError: 3641:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9db46e789680 x1876030878284544/t0(0) o250->MGC192.168.206.150@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 [ 3041.800977] LustreError: 3641:0:(client.c:1404:ptlrpc_import_delay_req()) Skipped 11 previous similar messages [ 3047.035343] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 3047.456878] Lustre: 62030:0:(ldlm_lib.c:2148:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3047.603423] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1667 to 0x2c0000401:1729) [ 3047.603654] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1635 to 0x280000401:1729) [ 3056.598989] Lustre: DEBUG MARKER: oleg650-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3057.781782] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3066.397268] Lustre: DEBUG MARKER: == replay-dual test 22b: c1 lfs mkdir -i 1 d1, M1 drop reply [ 3067.453821] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 3067.457377] LustreError: 6515:0:(ldlm_lib.c:3411:target_send_reply_msg()) @@@ dropping reply req@ffff9db477770780 x1876030861004544/t8589934617(0) o36->0962e95a-44c1-40b9-9d50-31fc44a9fb3e@192.168.206.50@tcp:541/0 lens 560/448 e 0 to 0 dl 1789125551 ref 1 fl Interpret:/200/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 3070.337445] Lustre: Failing over lustre-MDT0000 [ 3070.734134] Lustre: server umount lustre-MDT0000 complete [ 3074.792128] LustreError: 6500:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1789125478 with bad export cookie 11834641646807929225 [ 3074.800226] Lustre: Failing over lustre-MDT0001 [ 3074.812227] LustreError: 6500:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 3074.857418] LustreError: 63172:0:(client.c:1394:ptlrpc_import_delay_req()) @@@ IMP_CLOSED req@ffff9db44aeb2d00 x1876030878318720/t0(0) o1000->lustre-MDT0000-osp-MDT0001@0@lo:24/4 lens 304/4320 e 0 to 0 dl 0 ref 2 fl Rpc:QU/200/ffffffff rc 0/-1 job:'umount.0' uid:0 gid:0 projid:4294967295 [ 3074.885902] LustreError: 63172:0:(osp_object.c:618:osp_attr_get()) lustre-MDT0000-osp-MDT0001: osp_attr_get update error [0x200000401:0x1:0x0]: rc = -5 [ 3075.470850] Lustre: server umount lustre-MDT0001 complete [ 3095.298779] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3095.554164] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3095.561625] LustreError: 63854:0:(llog.c:1655:llog_backup()) MGC192.168.206.150@tcp: failed to open log lustre-sptlrpc: rc = -108 [ 3095.588593] Lustre: 63854:0:(mgc_request_server.c:770:mgc_llog_local_copy()) MGC192.168.206.150@tcp: failed to copy new config lustre-sptlrpc: rc = -108 [ 3104.946970] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 3105.854718] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 3106.361622] Lustre: 63910:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9db46e747840 x1876030861004544/t8589934617(0) o36->0962e95a-44c1-40b9-9d50-31fc44a9fb3e@192.168.206.50@tcp:580/0 lens 560/2880 e 0 to 0 dl 1789125590 ref 1 fl Interpret:/202/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 3106.372583] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:36 to 0x280000400:65) [ 3106.391691] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:36 to 0x2c0000400:65) [ 3113.899810] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1667 to 0x2c0000401:1761) [ 3113.900176] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1635 to 0x280000401:1761) [ 3119.569209] Lustre: DEBUG MARKER: oleg650-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 3121.137473] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3122.687618] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3132.368107] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3135.060374] Lustre: Failing over lustre-MDT0000 [ 3135.471529] Lustre: server umount lustre-MDT0000 complete [ 3158.051241] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3158.057494] LDISKFS-fs (dm-0): recovery complete [ 3158.066651] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3166.192505] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xa43d17e00a07e1b9 [ 3171.478951] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 3171.866342] Lustre: 66110:0:(ldlm_lib.c:2148:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3171.879497] Lustre: 66110:0:(ldlm_lib.c:2148:extend_recovery_timer()) Skipped 4 previous similar messages [ 3171.994586] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1635 to 0x280000401:1793) [ 3171.996963] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1667 to 0x2c0000401:1793) [ 3180.597295] Lustre: DEBUG MARKER: oleg650-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3182.241772] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3189.982865] Lustre: DEBUG MARKER: == replay-dual test 22c: c1 lfs mkdir -i 1 d1, M1 drop update [ 3190.809791] Lustre: *** cfs_fail_loc=1701, val=2147483648*** [ 3190.814730] LustreError: 8440:0:(ldlm_lib.c:3411:target_send_reply_msg()) @@@ dropping reply req@ffff9db47bcf7480 x1876030878394624/t107374182411(0) o1000->lustre-MDT0001-mdtlov_UUID@0@lo:595/0 lens 2520/4320 e 0 to 0 dl 1789125605 ref 1 fl Interpret:/200/0 rc 0/0 job:'osp_up0-1.0' uid:0 gid:0 projid:4294967295 [ 3193.848308] Lustre: Failing over lustre-MDT0000 [ 3194.165827] Lustre: server umount lustre-MDT0000 complete [ 3212.422254] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3212.786537] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3212.792833] Lustre: Skipped 6 previous similar messages [ 3217.031888] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 3217.900584] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 3217.925081] Lustre: Skipped 26 previous similar messages [ 3217.985203] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1667 to 0x2c0000401:1825) [ 3217.985305] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1635 to 0x280000401:1825) [ 3224.887353] Lustre: DEBUG MARKER: oleg650-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3226.095426] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3233.932767] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3235.659706] Lustre: Failing over lustre-MDT0000 [ 3235.972062] Lustre: server umount lustre-MDT0000 complete [ 3257.487152] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3257.489975] LDISKFS-fs (dm-0): recovery complete [ 3257.496310] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3268.787962] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 3269.677830] Lustre: 69300:0:(ldlm_lib.c:2148:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3269.694375] Lustre: 69300:0:(ldlm_lib.c:2148:extend_recovery_timer()) Skipped 4 previous similar messages [ 3269.791687] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1667 to 0x2c0000401:1857) [ 3269.793955] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1635 to 0x280000401:1857) [ 3277.520192] Lustre: DEBUG MARKER: oleg650-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3278.726814] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3285.656584] Lustre: DEBUG MARKER: == replay-dual test 22d: c1 lfs mkdir -i 1 d1, M1 drop update [ 3289.816035] Lustre: *** cfs_fail_loc=1701, val=2147483648*** [ 3289.818693] LustreError: 66719:0:(ldlm_lib.c:3411:target_send_reply_msg()) @@@ dropping reply req@ffff9db34cbaf480 x1876030878460800/t115964117001(0) o1000->lustre-MDT0001-mdtlov_UUID@0@lo:694/0 lens 2520/4320 e 0 to 0 dl 1789125704 ref 1 fl Interpret:/200/0 rc 0/0 job:'osp_up0-1.0' uid:0 gid:0 projid:4294967295 [ 3293.202859] Lustre: Failing over lustre-MDT0000 [ 3293.495530] Lustre: server umount lustre-MDT0000 complete [ 3296.751079] LustreError: 6501:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1789125700 with bad export cookie 11834641646807936890 [ 3296.753979] Lustre: Failing over lustre-MDT0001 [ 3296.769725] LustreError: 6501:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 3 previous similar messages [ 3296.799033] LustreError: 70538:0:(ldlm_resource.c:1207:ldlm_resource_complain()) lustre-MDT0000-osp-MDT0001: namespace resource [0x2000013a1:0x79:0x0].0xf7117594 (ffff9db44a4e9200) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 3296.842049] Lustre: lustre-MDT0001: Not available for connect from 192.168.206.50@tcp (stopping) [ 3300.325942] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 3300.332238] Lustre: Skipped 2 previous similar messages [ 3303.281859] Lustre: server umount lustre-MDT0001 complete [ 3322.281534] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3322.441795] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3326.997674] Lustre: 71260:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9db347c1b480 x1876030861088512/t12884901939(0) o36->0962e95a-44c1-40b9-9d50-31fc44a9fb3e@192.168.206.50@tcp:46/0 lens 560/2880 e 0 to 0 dl 1789125811 ref 1 fl Interpret:/202/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 3327.022725] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:70 to 0x280000400:97) [ 3327.022900] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:70 to 0x2c0000400:97) [ 3327.105296] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1635 to 0x280000401:1889) [ 3327.106567] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1667 to 0x2c0000401:1889) [ 3327.513523] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 3327.835513] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 3335.985270] Lustre: DEBUG MARKER: oleg650-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 3337.476073] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3338.701878] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3346.878585] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3348.842345] Lustre: Failing over lustre-MDT0000 [ 3349.165343] Lustre: server umount lustre-MDT0000 complete [ 3370.943588] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3370.947298] LDISKFS-fs (dm-0): recovery complete [ 3370.957602] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3378.151406] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xa43d17e00a07ff9c [ 3381.777891] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 3383.813527] Lustre: 73469:0:(ldlm_lib.c:2148:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3383.825797] Lustre: 73469:0:(ldlm_lib.c:2148:extend_recovery_timer()) Skipped 4 previous similar messages [ 3383.934197] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1635 to 0x280000401:1921) [ 3383.934710] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1667 to 0x2c0000401:1921) [ 3389.089649] Lustre: DEBUG MARKER: oleg650-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3390.284760] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3399.375610] Lustre: DEBUG MARKER: == replay-dual test 23a: c1 rmdir d1, M1 drop reply and fail, client2 mkdir d1 ========================================================== 07:23:22 (1789125802) [ 3401.281184] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 3401.287172] LustreError: 71694:0:(ldlm_lib.c:3411:target_send_reply_msg()) @@@ dropping reply req@ffff9db447bb0000 x1876030861129728/t17179869210(0) o36->0962e95a-44c1-40b9-9d50-31fc44a9fb3e@192.168.206.50@tcp:120/0 lens 496/456 e 0 to 0 dl 1789125885 ref 1 fl Interpret:/200/0 rc 0/0 job:'rmdir.0' uid:0 gid:0 projid:4294967295 [ 3405.591409] Lustre: Failing over lustre-MDT0001 [ 3406.044605] Lustre: server umount lustre-MDT0001 complete [ 3424.343541] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3429.088840] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 3429.956846] Lustre: 71694:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9db469da4f00 x1876030861129728/t17179869210(0) o36->0962e95a-44c1-40b9-9d50-31fc44a9fb3e@192.168.206.50@tcp:149/0 lens 496/2888 e 0 to 0 dl 1789125914 ref 1 fl Interpret:/202/0 rc 0/0 job:'rmdir.0' uid:0 gid:0 projid:4294967295 [ 3429.957698] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:100 to 0x280000400:129) [ 3429.960894] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:100 to 0x2c0000400:129) [ 3436.903855] Lustre: DEBUG MARKER: oleg650-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 3438.149775] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3445.832061] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3447.857678] Lustre: Failing over lustre-MDT0000 [ 3448.202154] Lustre: server umount lustre-MDT0000 complete [ 3468.317978] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3468.326284] LDISKFS-fs (dm-0): recovery complete [ 3468.336627] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3477.490215] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xa43d17e00a080bb2 [ 3482.218467] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 3483.171328] Lustre: 76643:0:(ldlm_lib.c:2148:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3483.191519] Lustre: 76643:0:(ldlm_lib.c:2148:extend_recovery_timer()) Skipped 4 previous similar messages [ 3483.414945] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1923 to 0x2c0000401:1953) [ 3483.415473] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1923 to 0x280000401:1953) [ 3490.637669] Lustre: DEBUG MARKER: oleg650-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3491.954689] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3499.364613] Lustre: DEBUG MARKER: == replay-dual test 23b: c1 rmdir d1, M1 drop reply and fail M0/M1, c2 mkdir d1 ========================================================== 07:25:02 (1789125902) [ 3500.645558] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 3500.650435] LustreError: 76103:0:(ldlm_lib.c:3411:target_send_reply_msg()) @@@ dropping reply req@ffff9db46ab4b840 x1876030861163392/t21474836483(0) o36->0962e95a-44c1-40b9-9d50-31fc44a9fb3e@192.168.206.50@tcp:219/0 lens 496/456 e 0 to 0 dl 1789125984 ref 1 fl Interpret:/200/0 rc 0/0 job:'rmdir.0' uid:0 gid:0 projid:4294967295 [ 3503.911565] Lustre: Failing over lustre-MDT0000 [ 3504.110617] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3504.124732] Lustre: Skipped 4 previous similar messages [ 3504.249278] Lustre: server umount lustre-MDT0000 complete [ 3507.232856] LustreError: 6502:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1789125911 with bad export cookie 11834641646807944114 [ 3507.235466] Lustre: Failing over lustre-MDT0001 [ 3507.246080] LustreError: 6502:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 3507.506976] Lustre: server umount lustre-MDT0001 complete [ 3528.449081] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3528.743919] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3532.811049] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xa43d17e00a081330 [ 3538.850495] Lustre: 78575:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9db47bc43c00 x1876030861163392/t21474836483(0) o36->0962e95a-44c1-40b9-9d50-31fc44a9fb3e@192.168.206.50@tcp:257/0 lens 496/2888 e 0 to 0 dl 1789126022 ref 1 fl Interpret:/202/0 rc 0/0 job:'rmdir.0' uid:0 gid:0 projid:4294967295 [ 3538.908839] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:100 to 0x280000400:161) [ 3538.909387] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:100 to 0x2c0000400:161) [ 3539.502612] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 3539.675493] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 3546.338271] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1923 to 0x2c0000401:1985) [ 3546.348231] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1923 to 0x280000401:1985) [ 3551.388282] Lustre: DEBUG MARKER: oleg650-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 3552.863171] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3554.444868] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3562.749696] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3564.420528] Lustre: Failing over lustre-MDT0000 [ 3564.618351] Lustre: server umount lustre-MDT0000 complete [ 3572.050443] LustreError: 78575:0:(ldlm_lib.c:1228:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.206.50@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3572.063323] LustreError: 78575:0:(ldlm_lib.c:1228:target_handle_connect()) Skipped 294 previous similar messages [ 3583.655959] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3583.662570] LDISKFS-fs (dm-0): recovery complete [ 3583.670775] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3594.075936] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 3594.079808] Lustre: Skipped 13 previous similar messages [ 3594.281761] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 3594.294505] Lustre: Skipped 13 previous similar messages [ 3598.106550] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 3599.490347] Lustre: lustre-MDT0000: Recovery over after 0:05, of 3 clients 3 recovered and 0 were evicted. [ 3599.507283] Lustre: Skipped 14 previous similar messages [ 3599.561683] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1987 to 0x280000401:2017) [ 3599.563600] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1987 to 0x2c0000401:2017) [ 3607.278503] Lustre: DEBUG MARKER: oleg650-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3608.558329] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3616.364471] Lustre: DEBUG MARKER: == replay-dual test 23c: c1 rmdir d1, M0 drop update reply and fail M0, c2 mkdir d1 ========================================================== 07:26:59 (1789126019) [ 3617.772689] Lustre: *** cfs_fail_loc=1701, val=2147483648*** [ 3617.775579] LustreError: 8440:0:(ldlm_lib.c:3411:target_send_reply_msg()) @@@ dropping reply req@ffff9db350ad3c00 x1876030878678144/t137438953491(0) o1000->lustre-MDT0001-mdtlov_UUID@0@lo:267/0 lens 1984/4320 e 0 to 0 dl 1789126032 ref 1 fl Interpret:/200/0 rc 0/0 job:'osp_up0-1.0' uid:0 gid:0 projid:4294967295 [ 3621.453409] Lustre: Failing over lustre-MDT0000 [ 3621.776986] Lustre: server umount lustre-MDT0000 complete [ 3624.932886] Lustre: lustre-MDT0000-lwp-MDT0001: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 3624.952880] Lustre: Skipped 51 previous similar messages [ 3633.120311] Lustre: 78573:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789126021/real 1789126021] req@ffff9db350ad21c0 x1876030878678144/t0(0) o1000->lustre-MDT0000-osp-MDT0001@0@lo:24/4 lens 1984/4320 e 0 to 1 dl 1789126037 ref 2 fl Rpc:XQr/200/ffffffff rc 0/-1 job:'osp_up0-1.0' uid:0 gid:0 projid:4294967295 [ 3633.155460] Lustre: 78573:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 42 previous similar messages [ 3640.102480] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3640.262458] LustreError: MGC192.168.206.150@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3640.269455] LustreError: Skipped 9 previous similar messages [ 3645.110085] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 3646.023766] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1987 to 0x2c0000401:2049) [ 3646.023829] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1987 to 0x280000401:2049) [ 3654.388164] Lustre: DEBUG MARKER: oleg650-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3655.780833] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3664.440242] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3666.351332] Lustre: Failing over lustre-MDT0000 [ 3666.403947] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3666.410403] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3666.415755] LustreError: Skipped 6 previous similar messages [ 3666.429902] Lustre: Skipped 2 previous similar messages [ 3666.540771] Lustre: server umount lustre-MDT0000 complete [ 3687.656081] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3687.658732] LDISKFS-fs (dm-0): recovery complete [ 3687.664960] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3692.300817] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 3693.586685] Lustre: 83951:0:(ldlm_lib.c:2148:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3693.598633] Lustre: 83951:0:(ldlm_lib.c:2148:extend_recovery_timer()) Skipped 17 previous similar messages [ 3693.800101] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2051 to 0x2c0000401:2081) [ 3693.812537] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2051 to 0x280000401:2081) [ 3701.058894] Lustre: DEBUG MARKER: oleg650-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3702.590621] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3711.057721] Lustre: DEBUG MARKER: == replay-dual test 23d: c1 rmdir d1, M0 drop update reply and fail M0/M1, c2 mkdir d1 ========================================================== 07:28:34 (1789126114) [ 3715.836970] Lustre: *** cfs_fail_loc=1701, val=2147483648*** [ 3715.841140] LustreError: 8440:0:(ldlm_lib.c:3411:target_send_reply_msg()) @@@ dropping reply req@ffff9db47bff8000 x1876030878744320/t146028888081(0) o1000->lustre-MDT0001-mdtlov_UUID@0@lo:365/0 lens 1984/4320 e 0 to 0 dl 1789126130 ref 1 fl Interpret:/200/0 rc 0/0 job:'osp_up0-1.0' uid:0 gid:0 projid:4294967295 [ 3719.354043] Lustre: Failing over lustre-MDT0000 [ 3719.653704] Lustre: server umount lustre-MDT0000 complete [ 3723.183871] LustreError: 8445:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1789126127 with bad export cookie 11834641646807951408 [ 3723.188072] Lustre: Failing over lustre-MDT0001 [ 3723.202124] LustreError: 8445:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 3 previous similar messages [ 3723.222347] LustreError: 85186:0:(ldlm_resource.c:1207:ldlm_resource_complain()) lustre-MDT0000-osp-MDT0001: namespace resource [0x2000013a1:0x81:0x0].0x0 (ffff9db46ee48500) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 3723.272286] Lustre: lustre-MDT0001: Not available for connect from 192.168.206.50@tcp (stopping) [ 3729.221052] Lustre: server umount lustre-MDT0001 complete [ 3747.970755] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3747.981816] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3748.276199] LustreError: 85895:0:(llog.c:1655:llog_backup()) MGC192.168.206.150@tcp: failed to open log lustre-sptlrpc: rc = -108 [ 3748.285717] Lustre: 85895:0:(mgc_request_server.c:770:mgc_llog_local_copy()) MGC192.168.206.150@tcp: failed to copy new config lustre-sptlrpc: rc = -108 [ 3748.836164] LustreError: 3641:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9db477438f00 x1876030878751616/t0(0) o250->MGC192.168.206.150@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 [ 3748.863662] LustreError: 3641:0:(client.c:1404:ptlrpc_import_delay_req()) Skipped 9 previous similar messages [ 3753.946134] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2051 to 0x280000401:2113) [ 3753.969163] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2051 to 0x2c0000401:2113) [ 3754.431288] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 3754.656122] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 3765.648669] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:100 to 0x280000400:193) [ 3765.649601] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:100 to 0x2c0000400:193) [ 3765.699776] Lustre: 86690:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9db470b67c00 x1876030861238400/t25769803783(0) o36->0962e95a-44c1-40b9-9d50-31fc44a9fb3e@192.168.206.50@tcp:484/0 lens 496/2888 e 0 to 0 dl 1789126249 ref 1 fl Interpret:/202/0 rc 0/0 job:'rmdir.0' uid:0 gid:0 projid:4294967295 [ 3770.435185] Lustre: DEBUG MARKER: oleg650-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 3771.873923] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3773.375339] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3782.312700] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3784.089776] Lustre: Failing over lustre-MDT0000 [ 3784.373505] Lustre: server umount lustre-MDT0000 complete [ 3805.920342] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3805.922881] LDISKFS-fs (dm-0): recovery complete [ 3805.928832] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3816.512668] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 3817.152468] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2115 to 0x2c0000401:2145) [ 3817.154300] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2115 to 0x280000401:2145) [ 3825.190915] Lustre: DEBUG MARKER: oleg650-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3826.626732] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3834.419766] Lustre: DEBUG MARKER: == replay-dual test 24: reconstruct on non-existing object ========================================================== 07:30:37 (1789126237) [ 3835.666447] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 3835.672841] LustreError: 85904:0:(ldlm_lib.c:3411:target_send_reply_msg()) @@@ dropping reply req@ffff9db3481de1c0 x1876030861275392/t154618822673(0) o36->0962e95a-44c1-40b9-9d50-31fc44a9fb3e@192.168.206.50@tcp:554/0 lens 488/456 e 0 to 0 dl 1789126319 ref 1 fl Interpret:/200/0 rc 0/0 job:'truncate.0' uid:0 gid:0 projid:4294967295 [ 3920.723634] Lustre: lustre-MDT0000: Client 0962e95a-44c1-40b9-9d50-31fc44a9fb3e (at 192.168.206.50@tcp) reconnecting [ 3920.737109] Lustre: 86624:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9db45f1c0f00 x1876030861275392/t154618822673(0) o36->0962e95a-44c1-40b9-9d50-31fc44a9fb3e@192.168.206.50@tcp:639/0 lens 488/3152 e 0 to 0 dl 1789126404 ref 1 fl Interpret:/202/0 rc 0/0 job:'truncate.0' uid:0 gid:0 projid:4294967295 [ 3927.109979] Lustre: DEBUG MARKER: == replay-dual test 25: replay|resend ==================== 07:32:10 (1789126330) [ 3928.666697] Lustre: *** cfs_fail_loc=304, val=0*** [ 3931.114584] Lustre: Failing over lustre-OST0000 [ 3931.251699] Lustre: server umount lustre-OST0000 complete [ 3949.270033] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3949.526988] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 3949.529744] Lustre: Skipped 14 previous similar messages [ 3951.059411] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 3951.079756] Lustre: Skipped 55 previous similar messages [ 3954.897742] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 3963.813583] Lustre: DEBUG MARKER: oleg650-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 3965.362143] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 3973.922698] Lustre: DEBUG MARKER: == replay-dual test 26: dbench and tar with mds failover ========================================================== 07:32:57 (1789126377) [ 3984.555799] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3988.631689] Lustre: DEBUG MARKER: test_26 fail mds1 1 times [ 3990.568103] Lustre: Failing over lustre-MDT0000 [ 3990.622215] Lustre: lustre-MDT0000: Not available for connect from 192.168.206.50@tcp (stopping) [ 3990.633024] Lustre: Skipped 6 previous similar messages [ 3991.017641] Lustre: server umount lustre-MDT0000 complete [ 4010.945455] LDISKFS-fs (dm-0): 4 truncates cleaned up [ 4010.947862] LDISKFS-fs (dm-0): recovery complete [ 4010.959893] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4015.081930] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 4016.628054] Lustre: 92055:0:(ldlm_lib.c:2148:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 4016.637818] Lustre: 92055:0:(ldlm_lib.c:2148:extend_recovery_timer()) Skipped 17 previous similar messages [ 4018.760325] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2175 to 0x2c0000401:2209) [ 4018.761040] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2177 to 0x280000401:2209) [ 4025.674772] Lustre: DEBUG MARKER: oleg650-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4027.464085] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4040.348417] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 4043.967530] Lustre: DEBUG MARKER: test_26 fail mds2 2 times [ 4045.799413] Lustre: Failing over lustre-MDT0001 [ 4046.250713] Lustre: server umount lustre-MDT0001 complete [ 4046.366530] LustreError: 92670:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1789126450 with bad export cookie 11834641646807974354 [ 4069.160891] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 4069.163983] LDISKFS-fs (dm-1): recovery complete [ 4069.174244] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4074.809204] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 4077.488894] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:270 to 0x2c0000400:289) [ 4077.489750] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:269 to 0x280000400:289) [ 4085.370194] Lustre: DEBUG MARKER: oleg650-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 4086.755077] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4099.251386] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4103.159991] Lustre: DEBUG MARKER: test_26 fail mds1 3 times [ 4105.474273] Lustre: Failing over lustre-MDT0000 [ 4105.546255] Lustre: lustre-MDT0000: Not available for connect from 192.168.206.50@tcp (stopping) [ 4105.553906] Lustre: Skipped 2 previous similar messages [ 4111.224568] Lustre: server umount lustre-MDT0000 complete [ 4133.861841] LDISKFS-fs (dm-0): 3 truncates cleaned up [ 4133.866419] LDISKFS-fs (dm-0): recovery complete [ 4133.882349] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4148.558582] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 4149.785049] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2280 to 0x2c0000401:2305) [ 4149.800743] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2280 to 0x280000401:2305) [ 4159.621641] Lustre: DEBUG MARKER: oleg650-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4161.642789] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4173.748529] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 4177.295818] Lustre: DEBUG MARKER: test_26 fail mds2 4 times [ 4179.833307] Lustre: Failing over lustre-MDT0001 [ 4186.423824] Lustre: server umount lustre-MDT0001 complete [ 4189.168236] LustreError: 85905:0:(ldlm_lib.c:1228:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4189.177911] LustreError: 85905:0:(ldlm_lib.c:1228:target_handle_connect()) Skipped 235 previous similar messages [ 4207.885136] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 4207.887335] LDISKFS-fs (dm-1): recovery complete [ 4207.910559] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4208.575897] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 4208.588294] Lustre: Skipped 9 previous similar messages [ 4209.908949] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 4209.920920] Lustre: Skipped 9 previous similar messages [ 4213.292793] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 4215.092492] Lustre: lustre-MDT0001: Recovery over after 0:06, of 3 clients 3 recovered and 0 were evicted. [ 4215.110733] Lustre: Skipped 9 previous similar messages [ 4215.169643] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:372 to 0x280000400:417) [ 4215.171992] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:372 to 0x2c0000400:417) [ 4222.422846] Lustre: DEBUG MARKER: oleg650-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 4224.124901] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4276.520766] Lustre: DEBUG MARKER: == replay-dual test 28: lock replay should be ordered: waiting after granted ========================================================== 07:37:59 (1789126679) [ 4288.438209] Lustre: Failing over lustre-OST0000 [ 4288.450565] Lustre: *** cfs_fail_loc=32a, val=0*** [ 4288.454445] LustreError: 93196:0:(client.c:1394:ptlrpc_import_delay_req()) @@@ IMP_CLOSED req@ffff9db452112d00 x1876030880168064/t0(0) o105->lustre-OST0000@192.168.206.50@tcp:15/16 lens 392/224 e 0 to 0 dl 0 ref 1 fl Rpc:QU/0/ffffffff rc 0/-1 job:'' uid:4294967295 gid:4294967295 projid:4294967295 [ 4288.456221] LustreError: 98768:0:(ldlm_resource.c:1207:ldlm_resource_complain()) filter-lustre-OST0000_UUID: namespace resource [0x280000401:0x94d:0x0].0x0 (ffff9db3470c8c00) refcount nonzero (2) after lock cleanup; forcing cleanup. [ 4288.482778] LustreError: 98768:0:(ldlm_resource.c:1207:ldlm_resource_complain()) Skipped 1 previous similar message [ 4288.486865] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 4288.492296] LustreError: Skipped 5 previous similar messages [ 4288.495717] Lustre: lustre-OST0000-osc-MDT0000: Connection to lustre-OST0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 4288.505461] Lustre: Skipped 29 previous similar messages [ 4288.512457] Lustre: lustre-OST0000: Not available for connect from 0@lo (stopping) [ 4288.516378] Lustre: Skipped 16 previous similar messages [ 4288.625344] Lustre: server umount lustre-OST0000 complete [ 4305.630036] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4307.867962] Lustre: *** cfs_fail_loc=32a, val=0*** [ 4311.549397] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 4320.335994] Lustre: DEBUG MARKER: oleg650-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 4321.662869] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4331.061280] Lustre: DEBUG MARKER: == replay-dual test 29: replay vs update with the same xid ========================================================== 07:38:54 (1789126734) [ 4332.437789] Lustre: DEBUG MARKER: SKIP: replay-dual test_29 needs >= 2 clients [ 4333.852229] Lustre: DEBUG MARKER: == replay-dual test 30: layout lock replay is not blocked on IO ========================================================== 07:38:57 (1789126737) [ 4336.590180] Lustre: Failing over lustre-MDT0000 [ 4336.861576] Lustre: server umount lustre-MDT0000 complete [ 4353.313897] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4353.415824] LustreError: MGC192.168.206.150@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4353.422918] LustreError: Skipped 5 previous similar messages [ 4356.574266] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 4359.208264] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2381 to 0x2c0000401:2401) [ 4359.208383] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2382 to 0x280000401:2401) [ 4363.673535] Lustre: DEBUG MARKER: oleg650-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4364.861932] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4371.419820] Lustre: DEBUG MARKER: == replay-dual test 31: deadlock on file_remove_privs and occupied mod rpc slots ========================================================== 07:39:35 (1789126775) [ 4374.244605] Lustre: Failing over lustre-OST0000 [ 4374.349271] Lustre: server umount lustre-OST0000 complete [ 4391.163522] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4398.764655] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 4407.305252] Lustre: DEBUG MARKER: oleg650-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 4408.889596] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in IDLE [ 4417.324237] Lustre: DEBUG MARKER: == replay-dual test 32: gap in update llog shouldn't break recovery ========================================================== 07:40:20 (1789126820) [ 4418.246603] Lustre: *** cfs_fail_loc=131d, val=10*** [ 4418.749276] Lustre: *** cfs_fail_loc=131d, val=4294967294*** [ 4418.752600] Lustre: Skipped 11 previous similar messages [ 4421.300774] Lustre: Failing over lustre-MDT0001 [ 4421.746407] Lustre: server umount lustre-MDT0001 complete [ 4425.315669] Lustre: Failing over lustre-MDT0000 [ 4425.820443] Lustre: server umount lustre-MDT0000 complete [ 4433.255737] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4433.752949] Lustre: *** cfs_fail_loc=131d, val=4294967266*** [ 4433.763506] Lustre: Skipped 27 previous similar messages [ 4438.561614] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 4445.516869] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4445.626122] Lustre: *** cfs_fail_loc=131d, val=4294967262*** [ 4445.629762] Lustre: Skipped 3 previous similar messages [ 4450.161453] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 4451.367530] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:431 to 0x280000400:449) [ 4451.371305] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:431 to 0x2c0000400:449) [ 4451.455163] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2381 to 0x2c0000401:2433) [ 4451.457766] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2441 to 0x280000401:2497) [ 4460.190328] Lustre: DEBUG MARKER: == replay-dual test 33: Check for OBD_INCOMPAT_MULTI_RPCS in last_rcvd after abort_recovery ========================================================== 07:41:03 (1789126863) [ 4466.069894] Lustre: Failing over lustre-MDT0001 [ 4466.310519] Lustre: server umount lustre-MDT0001 complete [ 4485.966929] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4490.572889] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 4497.498857] Lustre: DEBUG MARKER: oleg650-client.virtnet: executing wait_import_state_mount REPLAY_WAIT mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 4498.841681] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in REPLAY_WAIT state after 0 sec [ 4499.522067] Lustre: lustre-MDT0001: Aborting client recovery [ 4499.526508] LustreError: 106566:0:(ldlm_lib.c:3067:target_stop_recovery_thread()) lustre-MDT0001: Aborting recovery [ 4499.537626] Lustre: 105932:0:(ldlm_lib.c:2467:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 4499.546048] Lustre: 105932:0:(ldlm_lib.c:2467:target_recovery_overseer()) Skipped 2 previous similar messages [ 4499.553563] Lustre: 105932:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0001: disconnect stale client 3ab858dd-fbc1-43a7-8fca-0b440041dd68@ [ 4499.560758] Lustre: lustre-MDT0001: disconnecting 1 stale clients [ 4499.580864] Lustre: lustre-MDT0001-osd: cancel update llog [0x240000400:0x1:0x0] [ 4499.590931] Lustre: lustre-MDT0000-osp-MDT0001: cancel update llog [0x200000401:0x1:0x0] [ 4499.642939] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:431 to 0x280000400:481) [ 4499.647657] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:431 to 0x2c0000400:481) [ 4504.407382] Lustre: DEBUG MARKER: oleg650-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 4505.904797] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4510.024490] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0001.recovery_status 1475 [ 4512.224227] Lustre: 3642:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789126831/real 1789126831] req@ffff9db45f426580 x1876030880296448/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1789126916 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4512.268978] Lustre: 3642:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 4516.496733] Lustre: Failing over lustre-MDT0001 [ 4516.803402] Lustre: server umount lustre-MDT0001 complete [ 4523.122966] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4526.283804] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug -1 all [ 4528.216281] Lustre: lustre-MDT0001: Denying connection for new client 36aa8561-edf1-4a98-bc93-d1ea06836555 (at 192.168.206.50@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 2:15 [ 4528.653233] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:431 to 0x280000400:513) [ 4528.654104] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:431 to 0x2c0000400:513) [ 4533.389784] Lustre: DEBUG MARKER: oleg650-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 4534.991382] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4538.348706] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0001.recovery_status 1475 [ 4545.797083] Lustre: DEBUG MARKER: == replay-dual test complete, duration 4314 sec ========== 07:42:29 (1789126949) [ 4548.587825] Lustre: DEBUG MARKER: === replay-dual: start cleanup 07:42:31 (1789126951) === [ 4557.505526] Lustre: DEBUG MARKER: === replay-dual: finish cleanup 07:42:40 (1789126960) === [ 4559.771193] Lustre: Failing over lustre-MDT0000 [ 4560.015126] Lustre: server umount lustre-MDT0000 complete [ 4584.687903] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4584.932660] Lustre: lustre-MDT0000: Not available for connect from 0@lo (not set up) [ 4584.940978] Lustre: Skipped 7 previous similar messages [ 4585.226678] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4585.238543] Lustre: Skipped 11 previous similar messages [ 4590.569664] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4590.608768] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 4590.615466] Lustre: Skipped 35 previous similar messages [ 4725.500216] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 4725.513481] Lustre: 109764:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 3ab858dd-fbc1-43a7-8fca-0b440041dd68@ [ 4725.524034] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 4725.582917] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2441 to 0x280000401:2529) [ 4725.584082] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2381 to 0x2c0000401:2465) [ 4731.295355] Lustre: DEBUG MARKER: oleg650-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4732.542592] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4744.315910] Lustre: server umount lustre-MDT0000 complete [ 4751.517207] LustreError: 92670:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1789127155 with bad export cookie 11834641646808201147 [ 4751.532041] LustreError: 92670:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 3 previous similar messages [ 4751.877242] Lustre: server umount lustre-MDT0001 complete [ 4769.176874] Lustre: server umount lustre-OST0000 complete [ 4786.410518] Lustre: server umount lustre-OST0001 complete [ 4804.356556] Lustre: DEBUG MARKER: oleg650-server.virtnet: executing unload_modules_local [ 4807.144995] Key type lgssc unregistered [ 4807.400564] LNet: 112706:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 4807.415745] LNetError: 112706:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 4807.435961] LNet: Removed LNI 192.168.206.150@tcp [ 4808.459175] Key type .llcrypt unregistered [ 4808.460992] Key type ._llcrypt unregistered