[ 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 484133675 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2399.998 MHz processor [ 0.000000] last_pfn = 0x146e00 max_arch_pfn = 0x400000000 [ 0.000000] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT [ 0.000000] last_pfn = 0xbffce max_arch_pfn = 0x400000000 [ 0.000000] found SMP MP-table at [mem 0x000f54b0-0x000f54bf] [ 0.000000] RAMDISK: [mem 0xbcc54000-0xbffbffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F52D0 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE247C 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE2318 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 0022D8 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE238C 000090 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE241C 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE2454 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe2318-0xbffe238b] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe2317] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe238c-0xbffe241b] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe241c-0xbffe2453] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe2454-0xbffe247b] [ 0.000000] No NUMA configuration found [ 0.000000] Faking a node at [mem 0x0000000000000000-0x0000000146dfffff] [ 0.000000] NODE_DATA(0) allocated [mem 0x1465a3000-0x1465cdfff] [ 0.000000] Reserving 256MB of memory at 2752MB for crashkernel (System RAM: 4205MB) [ 0.000000] Zone ranges: [ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.000000] DMA32 [mem 0x0000000001000000-0x00000000ffffffff] [ 0.000000] Normal [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Device empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff] [ 0.000000] node 0: [mem 0x0000000000100000-0x00000000bffcdfff] [ 0.000000] node 0: [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Zeroed struct page in unavailable ranges: 4756 pages [ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x0000000146dfffff] [ 0.000000] ACPI: PM-Timer IO Port: 0x608 [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) [ 0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) [ 0.000000] Using ACPI (MADT) for SMP configuration information [ 0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000] TSC deadline timer available [ 0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs [ 0.000000] kvm-guest: KVM setup pv remote TLB flush [ 0.000000] kvm-guest: setup PV sched yield [ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff] [ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff] [ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff] [ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff] [ 0.000000] PM: Registered nosave memory: [mem 0xbffce000-0xbfffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xc0000000-0xfeffbfff] [ 0.000000] PM: Registered nosave memory: [mem 0xfeffc000-0xfeffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xff000000-0xfffbffff] [ 0.000000] PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff] [ 0.000000] [mem 0xc0000000-0xfeffbfff] available for PCI devices [ 0.000000] Booting paravirtualized kernel on KVM [ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns [ 0.000000] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1 [ 0.000000] percpu: Embedded 63 pages/cpu s221184 r8192 d28672 u524288 [ 0.000000] kvm-guest: PV spinlocks enabled [ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1059606 [ 0.000000] Policy zone: Normal [ 0.000000] Kernel command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] Specific versions of hardware are certified with Red Hat Enterprise Linux 8. Please see the list of hardware certified with Red Hat Enterprise Linux 8 at https://catalog.redhat.com. [ 0.000000] audit: disabled (until reboot) [ 0.000000] software IO TLB: area num 4. [ 0.000000] Memory: 2829652K/4306352K available (18435K kernel code, 11221K rwdata, 7248K rodata, 2908K init, 18040K bss, 524584K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] ftrace: allocating 41240 entries in 162 pages [ 0.000000] ftrace: allocated 162 pages with 3 groups [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] rcu: RCU event tracing is enabled. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ 0.000000] rcu: RCU callback double-/use-after-free debug enabled. [ 0.000000] Rude variant of Tasks RCU enabled. [ 0.000000] Tracing variant of Tasks RCU enabled. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 0.000000] NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16 [ 0.000000] random: get_random_bytes called from start_kernel+0x622/0x9a8 with crng_init=0 [ 0.001000] Console: colour *CGA 80x25 [ 0.001000] printk: console [ttyS1] enabled [ 0.001000] ACPI: Core revision 20220331 [ 0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.001010] APIC: Switch to symmetric I/O mode setup [ 0.002352] x2apic enabled [ 0.003007] Switched APIC routing to physical x2apic. [ 0.004011] kvm-guest: setup PV IPIs [ 0.007295] ..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.008019] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.009011] pid_max: default: 32768 minimum: 301 [ 0.010129] LSM: Security Framework initializing [ 0.011045] Yama: becoming mindful. [ 0.012032] SELinux: Initializing. [ 0.013056] *** VALIDATE selinux *** [ 0.021418] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.026305] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.027140] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.028100] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.030104] *** VALIDATE tmpfs *** [ 0.031390] *** VALIDATE proc *** [ 0.032189] *** VALIDATE cgroup *** [ 0.033007] *** VALIDATE cgroup2 *** [ 0.034250] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.035139] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.036006] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.037028] Spectre V2 : User space: Vulnerable [ 0.038007] Speculative Store Bypass: Vulnerable [ 0.040585] debug: unmapping init [mem 0xffffffffbc459000-0xffffffffbc460fff] [ 0.042828] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.043666] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.044022] ... version: 2 [ 0.045012] ... bit width: 48 [ 0.046012] ... generic registers: 4 [ 0.047011] ... value mask: 0000ffffffffffff [ 0.048011] ... max period: 00007fffffffffff [ 0.049010] ... fixed-purpose events: 3 [ 0.050009] ... event mask: 000000070000000f [ 0.051330] rcu: Hierarchical SRCU implementation. [ 0.053303] smp: Bringing up secondary CPUs ... [ 0.054534] x86: Booting SMP configuration: [ 0.055029] .... node #0, CPUs: #1 #2 #3 [ 0.058429] smp: Brought up 1 node, 4 CPUs [ 0.060012] smpboot: Max logical packages: 1 [ 0.061016] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.146019] node 0 deferred pages initialised in 81ms [ 0.150031] devtmpfs: initialized [ 0.151131] x86/mm: Memory block size: 128MB [ 0.154686] gcov: version magic: 0x41383552 [ 0.157274] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.160068] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.162285] pinctrl core: initialized pinctrl subsystem [ 0.164158] [ 0.164716] ************************************************************* [ 0.167015] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.170017] ** ** [ 0.173013] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.176014] ** ** [ 0.178015] ** This means that this kernel is built to expose internal ** [ 0.181015] ** IOMMU data structures, which may compromise security on ** [ 0.183013] ** your system. ** [ 0.186014] ** ** [ 0.189021] ** If you see this message and you are not debugging the ** [ 0.192020] ** kernel, report this immediately to your vendor! ** [ 0.196023] ** ** [ 0.198019] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.201023] ************************************************************* [ 0.204820] NET: Registered protocol family 16 [ 0.206654] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.210096] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.212071] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.216512] cpuidle: using governor menu [ 0.217631] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.219600] PCI: Using configuration type 1 for base access [ 0.221146] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.230091] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.232041] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.236077] cryptd: max_cpu_qlen set to 1000 [ 0.240276] ACPI: Added _OSI(Module Device) [ 0.242025] ACPI: Added _OSI(Processor Device) [ 0.244022] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.246022] ACPI: Added _OSI(Processor Aggregator Device) [ 0.253043] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.260365] ACPI: Interpreter enabled [ 0.261176] ACPI: PM: (supports S0 S3 S4 S5) [ 0.263019] ACPI: Using IOAPIC for interrupt routing [ 0.265170] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.269724] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.280607] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.283061] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.286034] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.290123] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.295461] acpiphp: Slot [2] registered [ 0.298236] acpiphp: Slot [5] registered [ 0.299209] acpiphp: Slot [6] registered [ 0.301157] acpiphp: Slot [7] registered [ 0.303186] acpiphp: Slot [8] registered [ 0.305177] acpiphp: Slot [9] registered [ 0.306189] acpiphp: Slot [10] registered [ 0.309219] acpiphp: Slot [3] registered [ 0.310149] acpiphp: Slot [4] registered [ 0.312159] acpiphp: Slot [11] registered [ 0.314154] acpiphp: Slot [12] registered [ 0.315151] acpiphp: Slot [13] registered [ 0.317168] acpiphp: Slot [14] registered [ 0.318165] acpiphp: Slot [15] registered [ 0.320171] acpiphp: Slot [16] registered [ 0.321110] acpiphp: Slot [17] registered [ 0.323159] acpiphp: Slot [18] registered [ 0.324104] acpiphp: Slot [19] registered [ 0.326154] acpiphp: Slot [20] registered [ 0.327092] acpiphp: Slot [21] registered [ 0.329176] acpiphp: Slot [22] registered [ 0.330167] acpiphp: Slot [23] registered [ 0.332156] acpiphp: Slot [24] registered [ 0.334116] acpiphp: Slot [25] registered [ 0.335107] acpiphp: Slot [26] registered [ 0.337151] acpiphp: Slot [27] registered [ 0.339104] acpiphp: Slot [28] registered [ 0.341108] acpiphp: Slot [29] registered [ 0.342148] acpiphp: Slot [30] registered [ 0.344122] acpiphp: Slot [31] registered [ 0.345073] PCI host bridge to bus 0000:00 [ 0.347032] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.349035] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.352041] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.354035] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.356035] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.359044] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.361227] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.364180] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.368530] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.380815] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.386014] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.388018] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.391018] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.395021] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.397584] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.401093] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.404138] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.409026] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.415013] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.427015] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.433950] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.440000] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.450024] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.458025] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.475023] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.484000] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.491013] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.499013] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.514021] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.526420] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.534014] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.543026] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.561032] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.576280] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.586014] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.595016] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.616024] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.625647] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.632016] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.640017] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.665025] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 0.677176] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.684015] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.691016] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.707014] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 0.722559] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.724329] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.725412] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.728387] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.730215] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.736038] iommu: Default domain type: Passthrough [ 0.738442] SCSI subsystem initialized [ 0.740148] ACPI: bus type USB registered [ 0.742124] usbcore: registered new interface driver usbfs [ 0.744096] usbcore: registered new interface driver hub [ 0.746100] usbcore: registered new device driver usb [ 0.749327] pps_core: LinuxPPS API ver. 1 registered [ 0.751015] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.754072] PTP clock support registered [ 0.756237] EDAC MC: Ver: 3.0.0 [ 0.758210] PCI: Using ACPI for IRQ routing [ 0.759557] NetLabel: Initializing [ 0.761014] NetLabel: domain hash size = 128 [ 0.763012] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.766083] NetLabel: unlabeled traffic allowed by default [ 0.769041] vgaarb: loaded [ 0.770481] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.773025] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.781013] clocksource: Switched to clocksource kvm-clock [ 0.890626] VFS: Disk quotas dquot_6.6.0 [ 0.892156] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.895127] *** VALIDATE ramfs *** [ 0.896489] *** VALIDATE hugetlbfs *** [ 0.898064] pnp: PnP ACPI init [ 0.900526] pnp: PnP ACPI: found 6 devices [ 0.921232] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.924173] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.926971] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.929643] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.932526] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.935760] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.938736] NET: Registered protocol family 2 [ 0.941432] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.946954] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.950934] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.956646] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.960528] TCP: Hash tables configured (established 65536 bind 65536) [ 0.963233] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.966470] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.968933] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.972040] NET: Registered protocol family 1 [ 0.974802] RPC: Registered named UNIX socket transport module. [ 0.977212] RPC: Registered udp transport module. [ 0.979200] RPC: Registered tcp transport module. [ 0.980912] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.983863] NET: Registered protocol family 44 [ 0.985918] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.988603] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.991071] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.993336] PCI: CLS 0 bytes, default 64 [ 0.994937] Unpacking initramfs... [ 2.401411] debug: unmapping init [mem 0xffff8ac23cc54000-0xffff8ac23ffbffff] [ 2.407206] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.409817] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.414063] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 2.909556] Initialise system trusted keyrings [ 2.911607] Key type blacklist registered [ 2.913689] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.926198] zbud: loaded [ 2.929615] *** VALIDATE nfs *** [ 2.931064] *** VALIDATE nfs4 *** [ 2.932695] pstore: using deflate compression [ 2.936161] Platform Keyring initialized [ 3.043041] NET: Registered protocol family 38 [ 3.044453] Key type asymmetric registered [ 3.045395] Asymmetric key parser 'x509' registered [ 3.047070] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 3.048909] io scheduler mq-deadline registered [ 3.050034] io scheduler kyber registered [ 3.051296] io scheduler bfq registered [ 3.053171] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 3.055461] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 3.057371] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 3.059633] ACPI: Power Button [PWRF] [ 3.065514] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 3.071582] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 3.086779] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 3.096598] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 3.114183] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 3.141650] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.170891] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.176761] Non-volatile memory driver v1.3 [ 3.179125] Linux agpgart interface v0.103 [ 3.214119] virtio_blk virtio1: [vda] 149784 512-byte logical blocks (76.7 MB/73.1 MiB) [ 3.216920] vda: detected capacity change from 0 to 76689408 [ 3.232748] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.236174] vdb: detected capacity change from 0 to 1073741824 [ 3.253704] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.256520] vdc: detected capacity change from 0 to 2621440000 [ 3.272299] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.275217] vdd: detected capacity change from 0 to 2621440000 [ 3.291714] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.295073] vde: detected capacity change from 0 to 4294967296 [ 3.311498] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.314773] vdf: detected capacity change from 0 to 4294967296 [ 3.323573] libphy: Fixed MDIO Bus: probed [ 3.328805] usbcore: registered new interface driver usbserial_generic [ 3.331245] usbserial: USB Serial support registered for generic [ 3.333632] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.338603] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.340304] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.342519] mousedev: PS/2 mouse device common for all mice [ 3.345467] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.345502] rtc_cmos 00:05: RTC can wake from S4 [ 3.352236] rtc_cmos 00:05: registered as rtc0 [ 3.353047] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.354562] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.360897] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.361935] intel_pstate: CPU model not supported [ 3.369269] hid: raw HID events driver (C) Jiri Kosina [ 3.371559] usbcore: registered new interface driver usbhid [ 3.373802] usbhid: USB HID core driver [ 3.375590] drop_monitor: Initializing network drop monitor service [ 3.378513] Initializing XFRM netlink socket [ 3.381215] NET: Registered protocol family 10 [ 3.384699] Segment Routing with IPv6 [ 3.386303] NET: Registered protocol family 17 [ 3.388664] mpls_gso: MPLS GSO support [ 3.395898] RAS: Correctable Errors collector initialized. [ 3.398373] AVX version of gcm_enc/dec engaged. [ 3.400276] AES CTR mode by8 optimization enabled [ 3.488129] sched_clock: Marking stable (3488087705, 0)->(4324831467, -836743762) [ 3.491278] registered taskstats version 1 [ 3.494153] Loading compiled-in X.509 certificates [ 3.495868] zswap: loaded using pool lzo/zbud [ 3.522549] Key type big_key registered [ 3.537158] Key type encrypted registered [ 3.539328] ima: No TPM chip found, activating TPM-bypass! [ 3.541060] ima: Allocated hash algorithm: sha1 [ 3.542401] ima: No architecture policies found [ 3.552497] evm: Initialising EVM extended attributes: [ 3.554232] evm: security.selinux [ 3.555396] evm: security.ima [ 3.556340] evm: security.capability [ 3.557500] evm: HMAC attrs: 0x1 [ 3.563720] rtc_cmos 00:05: setting system clock to 2026-09-05 05:59:35 UTC (1788587975) [ 3.575817] debug: unmapping init [mem 0xffffffffbd403000-0xffffffffbd5fffff] [ 3.578743] debug: unmapping init [mem 0xffffffffbc182000-0xffffffffbc458fff] [ 3.591088] Write protecting the kernel read-only data: 28672k [ 3.594632] debug: unmapping init [mem 0xffffffffba803000-0xffffffffba9fffff] [ 3.596756] debug: unmapping init [mem 0xffffffffbb114000-0xffffffffbb1fffff] [ 3.645700] 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.654744] systemd[1]: Detected virtualization kvm. [ 3.656448] systemd[1]: Detected architecture x86-64. [ 3.658186] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.692693] systemd[1]: No hostname configured. [ 3.694595] systemd[1]: Set hostname to . [ 3.696519] random: systemd: uninitialized urandom read (16 bytes read) [ 3.699251] systemd[1]: Initializing machine ID from random generator. [ 3.749790] random: ln: uninitialized urandom read (6 bytes read) [ 3.849154] random: systemd: uninitialized urandom read (16 bytes read) [ 3.852323] systemd[1]: Reached target Local File Systems. [ OK ] Reached target Local File Systems. [ 3.857771] systemd[1]: Listening on udev Control Socket. [ OK ] Listening on udev Control Socket. [ 3.862572] systemd[1]: Listening on Journal Socket. [ OK ] Listening on Journal Socket. Starting Create Volatile Files and Directories... Starting Setup Virtual Console... [ OK ] Started Memstrack Anylazing Service. [ OK ] Reached target Swap. Starting Apply Kernel Variables... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. [ OK ] Reached target Initrd Root Device. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Reached target Timers. [ OK ] Reached target Slices. [ OK ] Listening on udev Kernel Socket. [ OK ] Listening on Journal Socket (/dev/log). Starting Journal Service... [ OK ] Reached target Sockets. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Setup Virtual Console. [ OK ] Started Apply Kernel Variables. [ OK ] Started Create list of required sta…vice nodes for the current kernel. Starting Create Static Device Nodes in /dev... Starting dracut cmdline hook... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started Journal Service. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 4.530207] device-mapper: uevent: version 1.0.3 [ 4.532651] device-mapper: ioctl: 4.46.0-ioctl (2022-02-22) initialised: dm-devel@redhat.com [ OK ] Started dracut pre-udev hook. Starting udev Kernel Device Manager... [ OK ] Started udev Kernel Device Manager. Starting dracut pre-trigger hook... [ OK ] Started dracut pre-trigger hook. Starting udev Coldplug all Devices... Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. Starting dracut initqueue hook... [ OK [ 5.280466] random: fast init done ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ 5.362757] virtio_net virtio0 ens2: renamed from eth0 [ 5.399168] scsi host0: ata_piix [ 5.418567] scsi host1: ata_piix [ 5.455442] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 5.458521] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 9.803318] dracut-initqueue[592]: RTNETLINK answers: File exists [ 10.066574] random: crng init done [ 10.068402] 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.598897] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped target Timers. [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Sockets. [ OK ] Stopped target Slices. [ OK ] Stopped target Paths. [ OK ] Stopped target System Initialization. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. [ OK ] Stopped target Swap. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. Stopping udev Kernel Device Manager... [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Closed udev 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.845751] printk: systemd: 26 output lines suppressed due to ratelimiting [ 12.156723] SELinux: Disabled at runtime. [ 12.222500] 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) [ 12.233318] systemd[1]: Detected virtualization kvm. [ 12.235849] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 12.770979] systemd[1]: initrd-switch-root.service: Succeeded. [ 12.774290] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 12.779625] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 12.784317] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 12.787193] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 12.793793] systemd[1]: Starting Journal Service... Starting Journal Service... [ 12.800893] systemd[1]: Mounting Huge Pages File System... Mounting Huge Pages File System... [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Listening on Process Core Dump Socket. [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Stopped target Switch Root. Mounting POSIX Message Queue File System... [ OK ] Created slice system-sshd\x2dkeygen.slice. [ 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 udev Control Socket. Starting Create list of required st…ce nodes for the current kernel... Mounting Kernel Debug File System... [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Listening on udev Kernel Socket. [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Reached target RPC Port Mapper. [ OK ] Created slice system-getty.slice. [ OK ] Stopped target Initrd Root File System. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Local Encrypted Volumes. Activating swap /dev/disk/by-label/SWAP... Starting Apply Kernel Variables... [ OK ] Created slice User and Session Slice. [ OK ] Reached target Slices. [ OK ] Stopped target Initrd File Systems. [ OK ] Reached target Paths. [ 12.949571] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS Starting udev Coldplug all Devices... Starting Remount Root and Kernel File Systems... [ OK ] Started Journal Service. [ OK ] Mounted Huge Pages File System. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Mounted Kernel Debug File System. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Started Apply Kernel Variables. [ OK ] Reached target Swap. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. Starting Configure read-only root support... Starting Flush Journal to Persistent Storage... Starting Create Static Device Nodes in /dev... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. Starting udev Kernel Device Manager... [ OK ] Reached target Local File Systems (Pre). Mounting /mnt... Mounting /home/green/git/lustre-release... [ OK ] Mounted /mnt. [ OK ] Started udev Coldplug all Devices. [ 13.270667] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 13.656549] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 13.690909] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 13.846248] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 13.872463] EDAC sbridge: Ver: 1.1.2 [ 15.284977] Key type dns_resolver registered [ 15.590950] NFS: Registering the id_resolver key type [ 15.592645] Key type id_resolver registered [ 15.594081] 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 RPC Bind... Starting Update UTMP about System Boot/Shutdown... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Started dnf makecache --timer. [ OK ] Reached target Timers. [ OK ] Reached target Basic System. [ OK ] Started irqbalance daemon. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting Restore /run/initramfs on shutdown... Starting Login Service... [ OK ] Started D-Bus System Message Bus. Starting Network Manager... [ OK ] Reached target sshd-keygen.target. [ 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... [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... Starting Hostname Service... [ OK ] Started OpenSSH server daemon. [ OK ] Started Permit User Sessions. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Serial Getty on ttyS1. [ OK ] Started Getty on tty1. [ OK ] Reached target Login Prompts. [ OK ] Started Command Scheduler. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting 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 oleg605-server login: [ 34.721225] spl: loading out-of-tree module taints kernel. [ 37.644716] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 42.800116] Key type ._llcrypt registered [ 42.802609] Key type .llcrypt registered [ 42.856935] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_hostid [ 55.810176] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing load_modules_local [ 57.496963] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 57.526455] alg: No test for adler32 (adler32-zlib) [ 59.037918] Lustre: Lustre: Build Version: 2.17.58_2_g97ad22e [ 60.039371] LNet: Added LNI 192.168.206.105@tcp [8/256/0/180] [ 61.849340] Key type lgssc registered [ 63.765382] Lustre: Echo OBD driver; http://www.lustre.org/ [ 73.273533] vdc: vdc1 vdc9 [ 82.118514] vde: vde1 vde9 [ 90.867860] vdf: vdf1 vdf9 [ 90.900691] vdf: vdf1 vdf9 [ 114.215699] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing load_modules_local [ 122.997401] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 124.278717] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 124.466519] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 124.534402] Lustre: lustre-MDT0000: new disk, initializing [ 124.845735] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 124.902285] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 128.922096] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 133.194301] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 139.374896] Lustre: lustre-OST0000: new disk, initializing [ 139.393727] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 139.407640] Lustre: Skipped 1 previous similar message [ 139.571972] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 142.463371] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:0:ost [ 142.470469] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:0:ost] [ 142.604546] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x240000400 [ 145.632884] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 149.221141] hrtimer: interrupt took 11210775 ns [ 155.444484] Lustre: lustre-OST0001: new disk, initializing [ 155.447315] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 155.557540] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 160.972073] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 162.552248] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:1:ost [ 162.569481] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:1:ost] [ 162.686850] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x280000400 [ 172.088778] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 181.518539] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 189.663735] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing check_logdir /tmp/testlogs/ [ 194.913962] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing yml_node [ 199.488939] Lustre: DEBUG MARKER: Client: 2.17.58.2 [ 202.101368] Lustre: DEBUG MARKER: MDS: 2.17.58.2 [ 204.674848] Lustre: DEBUG MARKER: OSS: 2.17.58.2 [ 206.219416] Lustre: DEBUG MARKER: -----============= acceptance-small: replay-single ============----- Sat Sep 5 02:02:56 EDT 2026 [ 222.532208] Lustre: DEBUG MARKER: excepting tests: 59 36 [ 224.328317] Lustre: DEBUG MARKER: === replay-single: start setup 02:03:15 (1788588195) === [ 229.420720] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing check_config_client /mnt/lustre [ 244.685599] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 248.033546] Lustre: 11314:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 251.988116] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 255.221045] Lustre: DEBUG MARKER: === replay-single: finish setup 02:03:46 (1788588226) === [ 257.188596] Lustre: DEBUG MARKER: == replay-single test 0a: empty replay =================== 02:03:47 (1788588227) [ 260.248970] LustreError: 11808:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 261.217432] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 263.103031] Lustre: Failing over lustre-MDT0000 [ 263.400784] Lustre: server umount lustre-MDT0000 complete [ 280.883397] LustreError: MGC192.168.206.105@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 281.225403] Lustre: lustre-MDT0000-lwp-OST0001: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 281.239937] Lustre: Skipped 1 previous similar message [ 281.379079] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 282.403114] Lustre: 3312:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788588237/real 1788588237] req@ffff8ac28ff2d500 x1875470483247232/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788588253 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 285.452736] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 286.368181] Lustre: 3310:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788588242/real 1788588242] req@ffff8ac182bd0700 x1875470483247616/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788588258 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 286.409845] Lustre: 3310:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 286.702106] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 287.712178] Lustre: 3311:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788588242/real 1788588242] req@ffff8ac182bd2300 x1875470483247744/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788588258 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 289.865958] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 289.965257] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 292.834878] Lustre: 3309:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788588247/real 1788588247] req@ffff8ac2bf967800 x1875470483248128/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788588263 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 295.820639] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 296.928295] Lustre: 3312:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788588252/real 1788588252] req@ffff8ac182bd1500 x1875470483248384/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788588268 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 296.956665] Lustre: 3312:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 297.352623] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 305.097745] Lustre: DEBUG MARKER: == replay-single test 0b: ensure object created after recover exists. (3284) ========================================================== 02:04:35 (1788588275) [ 307.089963] Lustre: Failing over lustre-OST0000 [ 307.169769] 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 [ 307.183840] Lustre: lustre-OST0000: Not available for connect from 0@lo (stopping) [ 307.252830] Lustre: server umount lustre-OST0000 complete [ 315.453726] LustreError: 6697:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.206.5@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 315.467676] LustreError: 6697:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 3 previous similar messages [ 317.410924] LustreError: 12073:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: 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. [ 320.573707] LustreError: 6697:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.206.5@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 324.879092] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 325.693954] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 326.742275] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 326.744031] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 326.759688] Lustre: Skipped 1 previous similar message [ 331.374288] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 340.060978] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 341.663265] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 349.318713] Lustre: DEBUG MARKER: == replay-single test 0c: check replay-barrier =========== 02:05:20 (1788588320) [ 351.916045] LustreError: 14845:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 352.607415] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 354.453356] Lustre: Failing over lustre-MDT0000 [ 354.817539] Lustre: server umount lustre-MDT0000 complete [ 371.168259] Lustre: 3311:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788588327/real 1788588327] req@ffff8ac2c1339500 x1875470483277440/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788588343 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 371.195427] 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 [ 371.937554] LustreError: MGC192.168.206.105@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 381.413473] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x14167a5a6af5ac9f [ 381.426466] Lustre: MGC192.168.206.105@tcp: Connection restored to 0@lo (at 0@lo) [ 381.801696] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 385.806671] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 387.673450] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 387.681753] Lustre: lustre-MDT0000: Denying connection for new client 3f6e2432-8cd9-4b16-9f65-1f2d9598354e (at 192.168.206.5@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:59 [ 388.065538] Lustre: 3312:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788588343/real 1788588343] req@ffff8ac2c133aa00 x1875470483278464/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788588359 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 388.096419] Lustre: 3312:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 7 previous similar messages [ 392.766987] Lustre: lustre-MDT0000: Denying connection for new client 3f6e2432-8cd9-4b16-9f65-1f2d9598354e (at 192.168.206.5@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:54 [ 396.264138] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 397.888503] Lustre: lustre-MDT0000: Denying connection for new client 3f6e2432-8cd9-4b16-9f65-1f2d9598354e (at 192.168.206.5@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:49 [ 403.005186] Lustre: lustre-MDT0000: Denying connection for new client 3f6e2432-8cd9-4b16-9f65-1f2d9598354e (at 192.168.206.5@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:44 [ 408.124251] Lustre: lustre-MDT0000: Denying connection for new client 3f6e2432-8cd9-4b16-9f65-1f2d9598354e (at 192.168.206.5@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:39 [ 418.371189] Lustre: lustre-MDT0000: Denying connection for new client 3f6e2432-8cd9-4b16-9f65-1f2d9598354e (at 192.168.206.5@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:29 [ 418.391783] Lustre: Skipped 1 previous similar message [ 438.846205] Lustre: lustre-MDT0000: Denying connection for new client 3f6e2432-8cd9-4b16-9f65-1f2d9598354e (at 192.168.206.5@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:08 [ 438.870955] Lustre: Skipped 3 previous similar messages [ 447.500447] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 447.503233] Lustre: 15491:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 640b7d70-0850-4a2a-b817-807816f8cd31@ [ 447.528157] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 447.610464] Lustre: lustre-MDT0000: Recovery over after 1:00, of 1 clients 0 recovered and 1 was evicted. [ 447.667591] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:44 to 0x240000400:65) [ 447.667615] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:44 to 0x280000400:65) [ 458.008975] Lustre: DEBUG MARKER: == replay-single test 0d: expired recovery with no clients ========================================================== 02:07:08 (1788588428) [ 460.700520] LustreError: 16234:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 461.587945] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 463.669880] Lustre: Failing over lustre-MDT0000 [ 464.004353] Lustre: server umount lustre-MDT0000 complete [ 481.746276] LustreError: MGC192.168.206.105@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 481.979732] 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 [ 481.998231] Lustre: Skipped 1 previous similar message [ 482.161594] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 483.808217] Lustre: 3309:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788588439/real 1788588439] req@ffff8ac28fc4c000 x1875470483303040/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788588455 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 486.811448] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 487.407633] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 487.423279] Lustre: Skipped 1 previous similar message [ 489.137941] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 489.146530] Lustre: lustre-MDT0000: Denying connection for new client f528b28b-848d-4379-b124-8eccca8717da (at 192.168.206.5@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 1:00 [ 489.161623] Lustre: Skipped 1 previous similar message [ 549.500171] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 549.511914] Lustre: 16886:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 3f6e2432-8cd9-4b16-9f65-1f2d9598354e@ [ 549.527610] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 549.601508] Lustre: lustre-MDT0000: Recovery over after 1:00, of 1 clients 0 recovered and 1 was evicted. [ 549.652138] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:44 to 0x280000400:97) [ 549.652968] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:44 to 0x240000400:97) [ 558.900770] Lustre: DEBUG MARKER: == replay-single test 1: simple create =================== 02:08:49 (1788588529) [ 561.680562] LustreError: 17624:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 562.443224] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 564.162205] Lustre: Failing over lustre-MDT0000 [ 564.194340] 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 [ 564.196497] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 564.207149] Lustre: Skipped 1 previous similar message [ 564.218100] Lustre: Skipped 1 previous similar message [ 564.422737] Lustre: server umount lustre-MDT0000 complete [ 582.344854] LustreError: MGC192.168.206.105@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 582.901307] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 584.877525] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 584.889764] Lustre: Skipped 1 previous similar message [ 587.013628] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 591.422271] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 591.576842] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 591.630702] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:44 to 0x240000400:129) [ 591.643045] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:44 to 0x280000400:129) [ 596.928643] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 598.375303] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 606.693818] Lustre: DEBUG MARKER: == replay-single test 2a: touch ========================== 02:09:37 (1788588577) [ 610.051520] LustreError: 19212:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 610.938619] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 612.935930] Lustre: Failing over lustre-MDT0000 [ 613.346321] Lustre: server umount lustre-MDT0000 complete [ 631.267367] Lustre: 3310:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788588587/real 1788588587] req@ffff8ac2bf3f9c00 x1875470483340928/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788588603 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 631.325111] Lustre: 3310:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 5 previous similar messages [ 631.338854] Lustre: lustre-MDT0000-lwp-OST0001: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 632.034537] LustreError: MGC192.168.206.105@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 641.504838] LustreError: 3308:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8ac2bf5a2300 x1875470483342720/t0(0) o250->MGC192.168.206.105@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 [ 642.291389] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 643.644781] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 643.873921] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 643.923676] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:44 to 0x240000400:161) [ 643.923939] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:131 to 0x280000400:161) [ 646.442672] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 654.716975] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 656.208927] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 656.295149] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 656.307764] Lustre: Skipped 1 previous similar message [ 664.387986] Lustre: DEBUG MARKER: == replay-single test 2b: touch ========================== 02:10:35 (1788588635) [ 667.103725] LustreError: 20802:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 667.856153] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 669.834811] Lustre: Failing over lustre-MDT0000 [ 670.261405] Lustre: server umount lustre-MDT0000 complete [ 687.073218] 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 [ 687.093909] Lustre: Skipped 1 previous similar message [ 687.905227] LustreError: MGC192.168.206.105@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 697.312740] LustreError: 3308:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8ac2bf967800 x1875470483358592/t0(0) o250->MGC192.168.206.105@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 [ 698.074498] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 698.076926] Lustre: Skipped 1 previous similar message [ 698.229732] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 699.967069] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 700.076768] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 700.111495] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:163 to 0x240000400:193) [ 700.116622] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:131 to 0x280000400:193) [ 702.829758] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 712.697593] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 712.707871] Lustre: Skipped 1 previous similar message [ 712.955516] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 714.575514] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 722.211633] Lustre: DEBUG MARKER: == replay-single test 2c: setstripe replay =============== 02:11:33 (1788588693) [ 725.046382] LustreError: 22397:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 725.924965] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 727.624109] Lustre: Failing over lustre-MDT0000 [ 728.033278] Lustre: lustre-MDT0000-lwp-OST0001: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 728.034716] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 728.049212] Lustre: Skipped 2 previous similar messages [ 728.059317] Lustre: Skipped 1 previous similar message [ 730.011504] Lustre: server umount lustre-MDT0000 complete [ 747.095950] LustreError: MGC192.168.206.105@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 747.627884] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 753.619466] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 756.292388] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 756.529279] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 756.593818] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:225) [ 756.600475] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:225) [ 765.993167] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 768.013791] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 777.003114] Lustre: DEBUG MARKER: == replay-single test 2d: setdirstripe replay ============ 02:12:27 (1788588747) [ 780.113223] LustreError: 23982:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 780.852757] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 782.696110] Lustre: Failing over lustre-MDT0000 [ 783.023093] Lustre: server umount lustre-MDT0000 complete [ 800.737442] Lustre: 3309:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788588756/real 1788588756] req@ffff8ac2a5725500 x1875470483389056/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788588772 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 800.740308] LustreError: MGC192.168.206.105@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 800.761184] Lustre: 3309:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 17 previous similar messages [ 800.761246] 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 [ 810.986062] LustreError: 3308:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8ac2c1339180 x1875470483390720/t0(0) o250->MGC192.168.206.105@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 [ 811.517600] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 813.846944] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:257) [ 813.847599] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:257) [ 816.156608] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 825.233313] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 825.830327] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 825.836975] Lustre: Skipped 3 previous similar messages [ 826.865074] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 834.636719] Lustre: DEBUG MARKER: == replay-single test 2e: O_CREAT|O_EXCL create replay === 02:13:25 (1788588805) [ 835.554235] Lustre: *** cfs_fail_loc=13b, val=315*** [ 835.560724] Lustre: *** cfs_fail_loc=13b, val=2147483648*** [ 835.564901] LustreError: 24595:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff8ac2c16eea00 x1875470468634752/t38654705666(0) o35->f528b28b-848d-4379-b124-8eccca8717da@192.168.206.5@tcp:619/0 lens 392/456 e 0 to 0 dl 1788588824 ref 1 fl Interpret:/600/0 rc 0/0 job:'openfile.0' uid:0 gid:0 projid:0 [ 839.989971] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 841.550753] Lustre: Failing over lustre-MDT0000 [ 841.883662] Lustre: server umount lustre-MDT0000 complete [ 859.059123] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 859.063988] Lustre: Skipped 2 previous similar messages [ 859.136177] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 863.131990] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 867.390371] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 867.407731] Lustre: Skipped 1 previous similar message [ 867.471823] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 867.479793] Lustre: Skipped 1 previous similar message [ 867.527022] Lustre: 26227:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff8ac2bf965c00 x1875470468634752/t38654705666(0) o35->f528b28b-848d-4379-b124-8eccca8717da@192.168.206.5@tcp:651/0 lens 392/456 e 0 to 0 dl 1788588856 ref 1 fl Interpret:/602/0 rc 0/0 job:'openfile.0' uid:0 gid:0 projid:0 [ 867.540275] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:289) [ 867.541821] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:289) [ 872.792538] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 874.098714] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 881.533553] Lustre: DEBUG MARKER: == replay-single test 3a: replay failed open(O_DIRECTORY) ========================================================== 02:14:12 (1788588852) [ 884.168644] LustreError: 27211:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 884.176412] LustreError: 27211:0:(osd_handler.c:720:osd_ro()) Skipped 1 previous similar message [ 884.997386] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 886.759515] Lustre: Failing over lustre-MDT0000 [ 887.138098] Lustre: server umount lustre-MDT0000 complete [ 904.503179] LustreError: MGC192.168.206.105@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 904.510140] LustreError: Skipped 1 previous similar message [ 905.017687] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 908.953208] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 914.669880] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:321) [ 914.671802] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:321) [ 920.178957] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 921.534295] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 928.583515] Lustre: DEBUG MARKER: == replay-single test 3b: replay failed open -ENOMEM ===== 02:14:59 (1788588899) [ 932.456546] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 933.270658] Lustre: *** cfs_fail_loc=114, val=0*** [ 936.093852] Lustre: Failing over lustre-MDT0000 [ 936.359445] Lustre: server umount lustre-MDT0000 complete [ 955.141991] 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 [ 955.156918] Lustre: Skipped 6 previous similar messages [ 955.333676] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 955.657141] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:353) [ 955.664235] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:353) [ 959.802267] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 960.487599] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 960.494557] Lustre: Skipped 5 previous similar messages [ 969.829619] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 971.193427] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 978.498709] Lustre: DEBUG MARKER: == replay-single test 3c: replay failed open -ENOMEM ===== 02:15:49 (1788588949) [ 981.939891] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 982.756379] Lustre: *** cfs_fail_loc=128, val=0*** [ 984.894263] Lustre: Failing over lustre-MDT0000 [ 985.213742] Lustre: server umount lustre-MDT0000 complete [ 1002.193563] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1002.583925] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1002.591842] Lustre: Skipped 2 previous similar messages [ 1002.644958] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1002.649553] Lustre: Skipped 2 previous similar messages [ 1002.672731] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:385) [ 1002.673683] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:385) [ 1005.242350] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1013.849181] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1015.162067] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1022.697532] Lustre: DEBUG MARKER: == replay-single test 4a: |x| 10 open(O_CREAT)s ========== 02:16:33 (1788588993) [ 1025.442869] LustreError: 32152:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 1025.453251] LustreError: 32152:0:(osd_handler.c:720:osd_ro()) Skipped 2 previous similar messages [ 1026.180644] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1028.251526] Lustre: Failing over lustre-MDT0000 [ 1028.585348] Lustre: server umount lustre-MDT0000 complete [ 1046.588635] LustreError: MGC192.168.206.105@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1046.598638] LustreError: Skipped 2 previous similar messages [ 1048.951406] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:391 to 0x280000400:417) [ 1048.956016] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:391 to 0x240000400:417) [ 1051.682725] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1058.272202] Lustre: 3311:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788589014/real 1788589014] req@ffff8ac2c133b480 x1875470483465472/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788589030 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1058.298218] Lustre: 3311:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 37 previous similar messages [ 1060.122916] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1061.550369] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1070.183033] Lustre: DEBUG MARKER: == replay-single test 4b: |x| rm 10 files ================ 02:17:21 (1788589041) [ 1073.683085] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1075.656767] Lustre: Failing over lustre-MDT0000 [ 1075.861940] Lustre: server umount lustre-MDT0000 complete [ 1093.758260] LustreError: 34343:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.206.5@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1093.774864] LustreError: 34343:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 1 previous similar message [ 1094.145439] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1094.158539] Lustre: Skipped 1 previous similar message [ 1094.939718] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:423 to 0x280000400:449) [ 1094.942015] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:423 to 0x240000400:449) [ 1097.964725] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1106.143204] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1107.582803] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1115.620693] Lustre: DEBUG MARKER: == replay-single test 5: |x| 220 open(O_CREAT) =========== 02:18:06 (1788589086) [ 1119.457071] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1127.073021] Lustre: Failing over lustre-MDT0000 [ 1127.486138] Lustre: server umount lustre-MDT0000 complete [ 1154.533807] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x14167a5a6af61e5f [ 1155.044732] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1155.048224] Lustre: Skipped 5 previous similar messages [ 1159.847795] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1161.152085] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:577) [ 1161.154718] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:577) [ 1170.430971] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1171.938930] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1195.827181] Lustre: DEBUG MARKER: == replay-single test 6a: mkdir + contained create ======= 02:19:26 (1788589166) [ 1199.364706] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1201.319661] Lustre: Failing over lustre-MDT0000 [ 1201.548051] Lustre: server umount lustre-MDT0000 complete [ 1220.578888] 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 [ 1220.594949] Lustre: Skipped 9 previous similar messages [ 1226.082471] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1226.216188] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 1226.236368] Lustre: Skipped 10 previous similar messages [ 1229.054636] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:609) [ 1229.063623] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:609) [ 1235.865552] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1237.464239] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1247.628555] Lustre: DEBUG MARKER: == replay-single test 6b: |X| rmdir ====================== 02:20:18 (1788589218) [ 1250.998534] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1252.766242] Lustre: Failing over lustre-MDT0000 [ 1252.977441] Lustre: server umount lustre-MDT0000 complete [ 1270.745902] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1270.752308] Lustre: Skipped 2 previous similar messages [ 1271.896337] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1271.904777] Lustre: Skipped 4 previous similar messages [ 1271.993217] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1272.001331] Lustre: Skipped 4 previous similar messages [ 1272.032721] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:641) [ 1272.032890] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:641) [ 1273.913849] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1283.327103] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1285.216335] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1294.555627] Lustre: DEBUG MARKER: == replay-single test 7: mkdir |X| contained create ====== 02:21:05 (1788589265) [ 1298.317523] LustreError: 40153:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 1298.323278] LustreError: 40153:0:(osd_handler.c:720:osd_ro()) Skipped 4 previous similar messages [ 1299.274566] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1300.821665] Lustre: Failing over lustre-MDT0000 [ 1301.206144] Lustre: server umount lustre-MDT0000 complete [ 1317.860352] LustreError: MGC192.168.206.105@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1317.870407] LustreError: Skipped 4 previous similar messages [ 1327.172944] LustreError: 40768:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.206.5@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1329.306606] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:673) [ 1329.308685] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:673) [ 1332.094855] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1340.814753] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1342.218421] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1349.196366] Lustre: DEBUG MARKER: == replay-single test 8: creat open |X| close ============ 02:22:00 (1788589320) [ 1352.228833] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1353.785631] Lustre: Failing over lustre-MDT0000 [ 1354.106791] Lustre: server umount lustre-MDT0000 complete [ 1373.442127] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:705) [ 1373.443732] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:705) [ 1374.443455] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1381.704700] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1383.260899] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1391.347630] Lustre: DEBUG MARKER: == replay-single test 9: |X| create (same inum/gen) ====== 02:22:42 (1788589362) [ 1394.773560] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1396.384841] Lustre: Failing over lustre-MDT0000 [ 1396.671649] Lustre: server umount lustre-MDT0000 complete [ 1415.497708] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:737) [ 1415.511145] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:737) [ 1419.529413] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1428.549866] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1429.856577] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1437.591742] Lustre: DEBUG MARKER: == replay-single test 10: create |X| rename unlink ======= 02:23:28 (1788589408) [ 1441.497616] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1443.238172] Lustre: Failing over lustre-MDT0000 [ 1443.503074] Lustre: server umount lustre-MDT0000 complete [ 1462.309606] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:769) [ 1462.313232] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:769) [ 1465.959631] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1475.010512] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1477.529309] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1488.691311] Lustre: DEBUG MARKER: == replay-single test 11: create open write rename |X| create-old-name read ========================================================== 02:24:18 (1788589458) [ 1494.076664] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1495.965824] Lustre: Failing over lustre-MDT0000 [ 1496.245533] Lustre: server umount lustre-MDT0000 complete [ 1522.146277] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x14167a5a6af6a06b [ 1525.133089] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:771 to 0x240000400:801) [ 1525.133651] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:771 to 0x280000400:801) [ 1528.071388] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1536.876501] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1538.419795] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1544.794705] Lustre: DEBUG MARKER: == replay-single test 12: open, unlink |X| close ========= 02:25:15 (1788589515) [ 1547.800827] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1549.234305] Lustre: Failing over lustre-MDT0000 [ 1549.604681] Lustre: server umount lustre-MDT0000 complete [ 1566.781224] LustreError: 48680:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.206.5@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1567.236569] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1567.241403] Lustre: Skipped 5 previous similar messages [ 1568.621300] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:771 to 0x280000400:833) [ 1568.622241] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:771 to 0x240000400:833) [ 1571.093236] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1574.368169] Lustre: 3312:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788589530/real 1788589530] req@ffff8ac2927a7b80 x1875470483679744/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788589546 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1574.383890] Lustre: 3312:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 68 previous similar messages [ 1579.586668] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1580.655689] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1588.140779] Lustre: DEBUG MARKER: == replay-single test 13: open chmod 0 |x| write close === 02:25:58 (1788589558) [ 1591.618935] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1593.495753] Lustre: Failing over lustre-MDT0000 [ 1593.820575] Lustre: server umount lustre-MDT0000 complete [ 1613.012442] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:771 to 0x280000400:865) [ 1613.013762] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:835 to 0x240000400:865) [ 1616.836553] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1625.048812] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1626.396738] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1633.699735] Lustre: DEBUG MARKER: == replay-single test 14: open(O_CREAT), unlink |X| close ========================================================== 02:26:44 (1788589604) [ 1637.302733] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1639.157972] Lustre: Failing over lustre-MDT0000 [ 1641.602622] Lustre: server umount lustre-MDT0000 complete [ 1658.849876] Lustre: lustre-MDT0000: Not available for connect from 0@lo (not set up) [ 1658.859887] Lustre: Skipped 1 previous similar message [ 1660.977871] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:835 to 0x240000400:897) [ 1660.981021] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:867 to 0x280000400:897) [ 1663.166657] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1671.234649] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1672.662165] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1680.240965] Lustre: DEBUG MARKER: == replay-single test 15: open(O_CREAT), unlink |X| touch new, close ========================================================== 02:27:31 (1788589651) [ 1683.393718] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1685.015362] Lustre: Failing over lustre-MDT0000 [ 1685.274733] Lustre: server umount lustre-MDT0000 complete [ 1703.093835] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1703.100211] Lustre: Skipped 10 previous similar messages [ 1705.226445] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:899 to 0x240000400:929) [ 1705.227595] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:899 to 0x280000400:929) [ 1707.268575] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1715.983821] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1717.172607] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1725.202094] Lustre: DEBUG MARKER: == replay-single test 16: |X| open(O_CREAT), unlink, touch new, unlink new ========================================================== 02:28:15 (1788589695) [ 1728.935978] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1730.835235] Lustre: Failing over lustre-MDT0000 [ 1731.134148] Lustre: server umount lustre-MDT0000 complete [ 1749.361795] Lustre: lustre-MDT0000-lwp-OST0001: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 1749.385725] Lustre: Skipped 20 previous similar messages [ 1751.398087] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:899 to 0x240000400:961) [ 1751.398658] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:931 to 0x280000400:961) [ 1754.603829] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 1754.611254] Lustre: Skipped 22 previous similar messages [ 1754.710575] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1764.889420] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1766.706711] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1773.959556] Lustre: DEBUG MARKER: == replay-single test 17: |X| open(O_CREAT), |replay| close ========================================================== 02:29:04 (1788589744) [ 1777.428720] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1779.421243] Lustre: Failing over lustre-MDT0000 [ 1779.857538] Lustre: server umount lustre-MDT0000 complete [ 1797.123752] LustreError: 56625:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.206.5@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1798.810152] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1798.825478] Lustre: Skipped 10 previous similar messages [ 1799.053886] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1799.057853] Lustre: Skipped 10 previous similar messages [ 1799.079983] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:963 to 0x240000400:993) [ 1799.082459] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:931 to 0x280000400:993) [ 1801.292871] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1809.589952] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1811.069149] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1819.204572] Lustre: DEBUG MARKER: == replay-single test 18: open(O_CREAT), unlink, touch new, close, touch, unlink ========================================================== 02:29:50 (1788589790) [ 1822.160031] LustreError: 57615:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 1822.169632] LustreError: 57615:0:(osd_handler.c:720:osd_ro()) Skipped 10 previous similar messages [ 1823.122276] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1825.116717] Lustre: Failing over lustre-MDT0000 [ 1825.463625] Lustre: server umount lustre-MDT0000 complete [ 1843.652357] LustreError: MGC192.168.206.105@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1843.666548] LustreError: Skipped 10 previous similar messages [ 1843.671663] LustreError: 3308:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8ac2c1f4ca80 x1875470483771904/t0(0) o250->MGC192.168.206.105@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 [ 1844.510982] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:995 to 0x240000400:1025) [ 1844.511193] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:995 to 0x280000400:1025) [ 1848.157312] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1856.980560] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1858.235696] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1864.640822] Lustre: DEBUG MARKER: == replay-single test 19: mcreate, open, write, rename === 02:30:35 (1788589835) [ 1868.188079] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1870.424467] Lustre: Failing over lustre-MDT0000 [ 1870.960060] Lustre: server umount lustre-MDT0000 complete [ 1889.241588] LustreError: 59803:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1890.627124] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1027 to 0x280000400:1057) [ 1890.631833] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1027 to 0x240000400:1057) [ 1893.535573] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1901.208651] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1902.519438] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1910.856454] Lustre: DEBUG MARKER: == replay-single test 20a: |X| open(O_CREAT), unlink, replay, close (test mds_cleanup_orphans) ========================================================== 02:31:21 (1788589881) [ 1914.278633] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1916.012251] Lustre: Failing over lustre-MDT0000 [ 1916.360148] Lustre: server umount lustre-MDT0000 complete [ 1936.672496] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1027 to 0x240000400:1089) [ 1936.673188] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1059 to 0x280000400:1089) [ 1939.337206] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1946.926555] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1948.207211] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1956.423867] Lustre: DEBUG MARKER: == replay-single test 20b: write, unlink, eviction, replay (test mds_cleanup_orphans) ========================================================== 02:32:07 (1788589927) [ 1962.458470] Lustre: 62407:0:(genops.c:1774:obd_export_evict_by_uuid()) lustre-MDT0000: evicting f528b28b-848d-4379-b124-8eccca8717da at adminstrative request [ 1969.202663] Lustre: Failing over lustre-MDT0000 [ 1969.548283] Lustre: server umount lustre-MDT0000 complete [ 1987.785737] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1059 to 0x280000400:1121) [ 1987.786423] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1091 to 0x240000400:1121) [ 1990.662124] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1999.156758] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2000.603785] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2006.237950] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 2021.162867] Lustre: DEBUG MARKER: before 4096, after 4096 [ 2027.368439] Lustre: DEBUG MARKER: == replay-single test 20c: check that client eviction does not affect file content ========================================================== 02:33:18 (1788589998) [ 2028.346401] Lustre: 64474:0:(genops.c:1774:obd_export_evict_by_uuid()) lustre-MDT0000: evicting f528b28b-848d-4379-b124-8eccca8717da at adminstrative request [ 2036.185133] Lustre: DEBUG MARKER: == replay-single test 21: |X| open(O_CREAT), unlink touch new, replay, close (test mds_cleanup_orphans) ========================================================== 02:33:27 (1788590007) [ 2039.867758] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2041.360794] Lustre: Failing over lustre-MDT0000 [ 2041.670068] Lustre: server umount lustre-MDT0000 complete [ 2069.984924] LustreError: 3308:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8ac2aef67800 x1875470483837952/t0(0) o250->MGC192.168.206.105@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 [ 2072.237212] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1123 to 0x240000400:1153) [ 2072.237993] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1124 to 0x280000400:1153) [ 2075.400273] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2086.188446] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2088.062743] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2096.497176] Lustre: DEBUG MARKER: == replay-single test 22: open(O_CREAT), |X| unlink, replay, close (test mds_cleanup_orphans) ========================================================== 02:34:27 (1788590067) [ 2100.902777] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2102.895559] Lustre: Failing over lustre-MDT0000 [ 2103.252745] Lustre: server umount lustre-MDT0000 complete [ 2131.937113] LustreError: 3308:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8ac2b5cac000 x1875470483854720/t0(0) o250->MGC192.168.206.105@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 [ 2132.664733] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 2132.682038] Lustre: Skipped 10 previous similar messages [ 2133.192755] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1155 to 0x280000400:1185) [ 2133.195470] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1155 to 0x240000400:1185) [ 2137.698447] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2148.516881] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2150.523425] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2161.055740] Lustre: DEBUG MARKER: == replay-single test 23: open(O_CREAT), |X| unlink touch new, replay, close (test mds_cleanup_orphans) ========================================================== 02:35:31 (1788590131) [ 2166.078880] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2168.431211] Lustre: Failing over lustre-MDT0000 [ 2168.917245] Lustre: server umount lustre-MDT0000 complete [ 2189.859048] Lustre: 3310:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788590144/real 1788590144] req@ffff8ac2b5cb7800 x1875470483870720/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788590160 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2189.890427] Lustre: 3310:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 84 previous similar messages [ 2193.858246] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2195.792906] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1187 to 0x280000400:1217) [ 2195.793288] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1187 to 0x240000400:1217) [ 2203.996927] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2205.286351] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2213.404725] Lustre: DEBUG MARKER: == replay-single test 24: open(O_CREAT), replay, unlink, close (test mds_cleanup_orphans) ========================================================== 02:36:24 (1788590184) [ 2217.258132] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2219.058553] Lustre: Failing over lustre-MDT0000 [ 2219.411670] Lustre: server umount lustre-MDT0000 complete [ 2243.826163] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2247.982531] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1219 to 0x280000400:1249) [ 2247.983185] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1219 to 0x240000400:1249) [ 2253.657188] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2255.138833] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2263.248857] Lustre: DEBUG MARKER: == replay-single test 25: open(O_CREAT), unlink, replay, close (test mds_cleanup_orphans) ========================================================== 02:37:13 (1788590233) [ 2267.136915] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2269.259949] Lustre: Failing over lustre-MDT0000 [ 2269.540812] Lustre: server umount lustre-MDT0000 complete [ 2297.826713] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x14167a5a6af6eb18 [ 2299.188597] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1219 to 0x280000400:1281) [ 2299.190427] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1251 to 0x240000400:1281) [ 2302.967651] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2311.820429] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2313.382326] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2321.334764] Lustre: DEBUG MARKER: == replay-single test 26: |X| open(O_CREAT), unlink two, close one, replay, close one (test mds_cleanup_orphans) ========================================================== 02:38:12 (1788590292) [ 2324.854145] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2326.730954] Lustre: Failing over lustre-MDT0000 [ 2326.989401] Lustre: server umount lustre-MDT0000 complete [ 2353.634106] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x14167a5a6af6f035 [ 2354.002526] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 2354.006038] Lustre: Skipped 11 previous similar messages [ 2355.445365] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1283 to 0x280000400:1313) [ 2355.446497] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1283 to 0x240000400:1313) [ 2357.591399] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2365.388897] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2366.711755] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2368.484974] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 2368.492261] Lustre: Skipped 23 previous similar messages [ 2373.964543] Lustre: DEBUG MARKER: == replay-single test 27: |X| open(O_CREAT), unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 02:39:04 (1788590344) [ 2377.490909] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2379.560195] Lustre: Failing over lustre-MDT0000 [ 2379.829350] Lustre: server umount lustre-MDT0000 complete [ 2397.817213] 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 [ 2397.831674] Lustre: Skipped 24 previous similar messages [ 2402.401146] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2407.486303] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 2407.509374] Lustre: Skipped 10 previous similar messages [ 2407.702351] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 2407.719934] Lustre: Skipped 10 previous similar messages [ 2407.791346] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1315 to 0x280000400:1345) [ 2407.794099] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1315 to 0x240000400:1345) [ 2413.319468] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2414.714808] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2423.111425] Lustre: DEBUG MARKER: == replay-single test 28: open(O_CREAT), |X| unlink two, close one, replay, close one (test mds_cleanup_orphans) ========================================================== 02:39:53 (1788590393) [ 2426.323311] LustreError: 75947:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 2426.331045] LustreError: 75947:0:(osd_handler.c:720:osd_ro()) Skipped 9 previous similar messages [ 2427.265689] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2429.531095] Lustre: Failing over lustre-MDT0000 [ 2429.876092] Lustre: server umount lustre-MDT0000 complete [ 2449.262472] LustreError: MGC192.168.206.105@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2449.278208] LustreError: Skipped 10 previous similar messages [ 2449.365958] LustreError: 76544:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 2449.394466] LustreError: 76544:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 2 previous similar messages [ 2451.823784] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1347 to 0x240000400:1377) [ 2451.835254] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1347 to 0x280000400:1377) [ 2455.338579] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2465.029819] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2466.371336] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2474.714665] Lustre: DEBUG MARKER: == replay-single test 29: open(O_CREAT), |X| unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 02:40:45 (1788590445) [ 2478.269867] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2480.251823] Lustre: Failing over lustre-MDT0000 [ 2480.577982] Lustre: server umount lustre-MDT0000 complete [ 2500.926568] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1379 to 0x240000400:1409) [ 2500.928960] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1379 to 0x280000400:1409) [ 2503.630101] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2513.367735] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2514.877035] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2522.920074] Lustre: DEBUG MARKER: == replay-single test 30: open(O_CREAT) two, unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 02:41:33 (1788590493) [ 2526.938293] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2528.678381] Lustre: Failing over lustre-MDT0000 [ 2529.049659] Lustre: server umount lustre-MDT0000 complete [ 2547.824043] Lustre: lustre-MDT0000: Not available for connect from 192.168.206.5@tcp (not set up) [ 2550.176512] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1411 to 0x240000400:1441) [ 2550.183802] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1411 to 0x280000400:1441) [ 2553.455609] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2563.223805] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2565.012895] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2573.245344] Lustre: DEBUG MARKER: == replay-single test 31: open(O_CREAT) two, unlink one, |X| unlink one, close two (test mds_cleanup_orphans) ========================================================== 02:42:24 (1788590544) [ 2577.287145] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2579.175118] Lustre: Failing over lustre-MDT0000 [ 2579.525802] Lustre: server umount lustre-MDT0000 complete [ 2599.229492] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1443 to 0x240000400:1473) [ 2599.229815] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1443 to 0x280000400:1473) [ 2602.616728] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2612.741386] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2614.307305] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2623.727185] Lustre: DEBUG MARKER: == replay-single test 32: close() notices client eviction; close() after client eviction ========================================================== 02:43:14 (1788590594) [ 2624.925694] Lustre: 82208:0:(genops.c:1774:obd_export_evict_by_uuid()) lustre-MDT0000: evicting f528b28b-848d-4379-b124-8eccca8717da at adminstrative request [ 2635.893473] Lustre: DEBUG MARKER: == replay-single test 33a: fid seq shouldn't be reused after abort recovery ========================================================== 02:43:26 (1788590606) [ 2639.110302] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2641.179927] Lustre: Failing over lustre-MDT0000 [ 2641.459922] Lustre: server umount lustre-MDT0000 complete [ 2651.445736] Lustre: lustre-MDT0000: Aborting client recovery [ 2651.449787] LustreError: 83126:0:(ldlm_lib.c:3029:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 2651.457225] Lustre: 83173:0:(ldlm_lib.c:2429:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 2651.463454] Lustre: 83173:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client f528b28b-848d-4379-b124-8eccca8717da@ [ 2651.471366] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 2651.571162] Lustre: lustre-MDT0000-osd: cancel update llog [0x200000400:0x1:0x0] [ 2651.689093] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1479 to 0x280000400:1505) [ 2651.694637] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1480 to 0x240000400:1505) [ 2657.075531] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2669.941241] Lustre: DEBUG MARKER: == replay-single test 33b: test fid seq allocation ======= 02:44:00 (1788590640) [ 2673.778371] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2675.424204] Lustre: Failing over lustre-MDT0000 [ 2675.799333] Lustre: server umount lustre-MDT0000 complete [ 2684.232078] Lustre: *** cfs_fail_loc=1311, val=0*** [ 2684.265621] Lustre: lustre-MDT0000: Aborting client recovery [ 2684.268871] LustreError: 84486:0:(ldlm_lib.c:3029:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 2684.274971] Lustre: 84532:0:(ldlm_lib.c:2429:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 2684.282402] Lustre: 84532:0:(ldlm_lib.c:2429:target_recovery_overseer()) Skipped 2 previous similar messages [ 2684.296860] Lustre: 84532:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client f528b28b-848d-4379-b124-8eccca8717da@ [ 2684.316803] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 2684.434171] Lustre: lustre-MDT0000-osd: cancel update llog [0x200015bc0:0x1:0x0] [ 2684.642206] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1516 to 0x280000400:1537) [ 2684.647326] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1516 to 0x240000400:1537) [ 2688.164392] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2694.405000] Lustre: *** cfs_fail_loc=1311, val=0*** [ 2702.852721] Lustre: DEBUG MARKER: == replay-single test 34: abort recovery before client does replay (test mds_cleanup_orphans) ========================================================== 02:44:33 (1788590673) [ 2707.516939] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2709.275958] Lustre: Failing over lustre-MDT0000 [ 2709.458261] Lustre: server umount lustre-MDT0000 complete [ 2718.666626] Lustre: lustre-MDT0000: Aborting client recovery [ 2718.669614] LustreError: 85862:0:(ldlm_lib.c:3029:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 2718.676861] Lustre: 85909:0:(ldlm_lib.c:2429:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 2718.682542] Lustre: 85909:0:(ldlm_lib.c:2429:target_recovery_overseer()) Skipped 2 previous similar messages [ 2718.686294] Lustre: 85909:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client f528b28b-848d-4379-b124-8eccca8717da@ [ 2718.691932] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 2718.745996] Lustre: lustre-MDT0000-osd: cancel update llog [0x200016778:0x1:0x0] [ 2718.868794] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1544 to 0x280000400:1569) [ 2718.870351] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1543 to 0x240000400:1569) [ 2723.822574] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2737.374734] Lustre: DEBUG MARKER: == replay-single test 35: test recovery from llog for unlink op ========================================================== 02:45:07 (1788590707) [ 2738.466716] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 2738.472399] LustreError: 85872:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff8ac2b5cb4380 x1875470469616512/t201863462916(0) o36->f528b28b-848d-4379-b124-8eccca8717da@192.168.206.5@tcp:251/0 lens 512/456 e 0 to 0 dl 1788590721 ref 1 fl Interpret:/200/0 rc 0/0 job:'rm.0' uid:0 gid:0 projid:4294967295 [ 2742.218523] Lustre: Failing over lustre-MDT0000 [ 2742.346323] Lustre: lustre-MDT0000: Not available for connect from 192.168.206.5@tcp (stopping) [ 2742.664629] Lustre: server umount lustre-MDT0000 complete [ 2752.873834] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 2752.876621] Lustre: lustre-MDT0000: Aborting client recovery [ 2752.886253] LustreError: 87085:0:(ldlm_lib.c:3029:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 2752.889438] Lustre: Skipped 18 previous similar messages [ 2752.904297] Lustre: 87132:0:(ldlm_lib.c:2429:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 2752.914111] Lustre: 87132:0:(ldlm_lib.c:2429:target_recovery_overseer()) Skipped 2 previous similar messages [ 2752.922836] Lustre: 87132:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client f528b28b-848d-4379-b124-8eccca8717da@ [ 2752.930496] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 2752.998643] Lustre: lustre-MDT0000-osd: cancel update llog [0x200017330:0x1:0x0] [ 2753.128446] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1571 to 0x280000400:1601) [ 2753.131349] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1543 to 0x240000400:1601) [ 2757.966536] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2770.557481] Lustre: DEBUG MARKER: SKIP: replay-single test_36 skipping ALWAYS excluded test 36 [ 2772.293107] Lustre: DEBUG MARKER: == replay-single test 37: abort recovery before client does replay (test mds_cleanup_orphans for directories) ========================================================== 02:45:42 (1788590742) [ 2776.784575] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2779.744275] Lustre: Failing over lustre-MDT0000 [ 2780.154680] Lustre: server umount lustre-MDT0000 complete [ 2788.901567] Lustre: lustre-MDT0000: Aborting client recovery [ 2788.905638] LustreError: 88545:0:(ldlm_lib.c:3029:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 2788.914492] Lustre: 88592:0:(ldlm_lib.c:2429:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 2788.920366] Lustre: 88592:0:(ldlm_lib.c:2429:target_recovery_overseer()) Skipped 2 previous similar messages [ 2788.928043] Lustre: 88592:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client f528b28b-848d-4379-b124-8eccca8717da@ [ 2788.936140] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 2788.988940] Lustre: lustre-MDT0000-osd: cancel update llog [0x200017b00:0x1:0x0] [ 2789.156963] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1571 to 0x280000400:1633) [ 2789.157139] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1543 to 0x240000400:1633) [ 2793.867854] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2799.072324] Lustre: 3309:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788590755/real 1788590755] req@ffff8ac2aec78a80 x1875470484083712/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788590771 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2799.119746] Lustre: 3309:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 79 previous similar messages [ 2806.019203] Lustre: DEBUG MARKER: == replay-single test 38: test recovery from unlink llog (test llog_gen_rec) ========================================================== 02:46:16 (1788590776) [ 2834.682651] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2836.643030] Lustre: Failing over lustre-MDT0000 [ 2836.935728] Lustre: server umount lustre-MDT0000 complete [ 2858.961497] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2864.376989] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2034 to 0x280000400:2049) [ 2864.379986] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2034 to 0x240000400:2049) [ 2871.079258] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2872.678380] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2893.193480] Lustre: DEBUG MARKER: == replay-single test 39: test recovery from unlink llog (test llog_gen_rec) ========================================================== 02:47:43 (1788590863) [ 2915.561944] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2927.252231] Lustre: Failing over lustre-MDT0000 [ 2927.655256] Lustre: server umount lustre-MDT0000 complete [ 2950.620435] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2952.442430] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2450 to 0x240000400:2465) [ 2952.453492] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2450 to 0x280000400:2465) [ 2961.176909] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2963.014697] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2983.123500] Lustre: DEBUG MARKER: == replay-single test 41: read from a valid osc while other oscs are invalid ========================================================== 02:49:14 (1788590954) [ 2985.382387] Lustre: setting import lustre-OST0001_UUID INACTIVE by administrator request [ 2986.312795] Lustre: lustre-OST0001: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnecting [ 2986.325938] LustreError: lustre-OST0001-osc-MDT0000: This client was evicted by lustre-OST0001; in progress operations using this service will fail. [ 2986.344898] Lustre: lustre-OST0001-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 2986.351951] Lustre: Skipped 25 previous similar messages [ 2992.915433] Lustre: DEBUG MARKER: == replay-single test 42: recovery after ost failure ===== 02:49:23 (1788590963) [ 3013.091767] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 3025.002588] Lustre: Failing over lustre-OST0000 [ 3025.143090] Lustre: server umount lustre-OST0000 complete [ 3028.058663] LustreError: 6696:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.206.5@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3028.086584] LustreError: 6696:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 1 previous similar message [ 3028.451931] 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 [ 3028.462142] Lustre: Skipped 23 previous similar messages [ 3044.119912] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 3044.123936] Lustre: Skipped 12 previous similar messages [ 3045.540910] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 3045.550215] Lustre: Skipped 6 previous similar messages [ 3047.069355] Lustre: lustre-OST0000: Recovery over after 0:02, of 2 clients 2 recovered and 0 were evicted. [ 3047.079175] Lustre: Skipped 6 previous similar messages [ 3050.767978] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3109.921687] Lustre: DEBUG MARKER: == replay-single test 43: mds osc import failure during recovery; don't LBUG ========================================================== 02:51:20 (1788591080) [ 3113.296993] LustreError: 95829:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 3113.310331] LustreError: 95829:0:(osd_handler.c:720:osd_ro()) Skipped 10 previous similar messages [ 3114.285108] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3117.371969] Lustre: Failing over lustre-MDT0000 [ 3117.653571] Lustre: server umount lustre-MDT0000 complete [ 3136.295445] LustreError: MGC192.168.206.105@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3136.310847] LustreError: Skipped 10 previous similar messages [ 3136.487053] LustreError: 96482:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3136.503793] LustreError: 96482:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 8 previous similar messages [ 3136.599610] Lustre: lustre-MDT0000: Not available for connect from 192.168.206.5@tcp (not set up) [ 3138.774534] Lustre: *** cfs_fail_loc=204, val=2147483648*** [ 3138.778423] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2866 to 0x280000400:2881) [ 3141.848734] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3151.261646] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3152.956600] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3154.912222] LustreError: 96507:0:(osp_precreate.c:974:osp_precreate_cleanup_orphans()) lustre-OST0000-osc-MDT0000: cannot cleanup orphans: rc = -11 [ 3154.920582] Lustre: lustre-OST0000: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnecting [ 3155.936857] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2867 to 0x240000400:2913) [ 3171.233058] Lustre: DEBUG MARKER: == replay-single test 44a: race in target handle connect ========================================================== 02:52:21 (1788591141) [ 3176.395183] LustreError: 96484:0:(ldlm_lib.c:1176:target_handle_connect()) cfs_race id 701 sleeping [ 3181.536693] LustreError: 96484:0:(ldlm_lib.c:1176:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 3181.547800] Lustre: lustre-MDT0000: Client f528b28b-848d-4379-b124-8eccca8717da (at 192.168.206.5@tcp) reconnecting [ 3181.584204] LustreError: 36626:0:(ldlm_lib.c:1176:target_handle_connect()) cfs_fail_race id 701 waking [ 3183.242520] LustreError: 96482:0:(ldlm_lib.c:1176:target_handle_connect()) cfs_race id 701 sleeping [ 3188.704098] LustreError: 96482:0:(ldlm_lib.c:1176:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 3188.719069] Lustre: lustre-MDT0000: Client f528b28b-848d-4379-b124-8eccca8717da (at 192.168.206.5@tcp) reconnecting [ 3190.716656] LustreError: 96501:0:(ldlm_lib.c:1176:target_handle_connect()) cfs_race id 701 sleeping [ 3195.873815] LustreError: 96501:0:(ldlm_lib.c:1176:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 3195.892548] Lustre: lustre-MDT0000: Client f528b28b-848d-4379-b124-8eccca8717da (at 192.168.206.5@tcp) reconnecting [ 3197.824195] LustreError: 96484:0:(ldlm_lib.c:1176:target_handle_connect()) cfs_race id 701 sleeping [ 3203.042394] LustreError: 96484:0:(ldlm_lib.c:1176:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 3204.894987] LustreError: 96501:0:(ldlm_lib.c:1176:target_handle_connect()) cfs_race id 701 sleeping [ 3210.208628] LustreError: 96501:0:(ldlm_lib.c:1176:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 3210.221525] Lustre: lustre-MDT0000: Client f528b28b-848d-4379-b124-8eccca8717da (at 192.168.206.5@tcp) reconnecting [ 3210.235746] Lustre: Skipped 1 previous similar message [ 3219.115513] LustreError: 96482:0:(ldlm_lib.c:1176:target_handle_connect()) cfs_race id 701 sleeping [ 3219.130754] LustreError: 96482:0:(ldlm_lib.c:1176:target_handle_connect()) Skipped 1 previous similar message [ 3224.544108] LustreError: 96482:0:(ldlm_lib.c:1176:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 3224.551903] LustreError: 96482:0:(ldlm_lib.c:1176:target_handle_connect()) Skipped 1 previous similar message [ 3231.719920] Lustre: lustre-MDT0000: Client f528b28b-848d-4379-b124-8eccca8717da (at 192.168.206.5@tcp) reconnecting [ 3231.738631] Lustre: Skipped 2 previous similar messages [ 3241.470783] LustreError: 96501:0:(ldlm_lib.c:1176:target_handle_connect()) cfs_race id 701 sleeping [ 3241.482156] LustreError: 96501:0:(ldlm_lib.c:1176:target_handle_connect()) Skipped 2 previous similar messages [ 3246.561264] LustreError: 96501:0:(ldlm_lib.c:1176:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 3246.576525] LustreError: 96501:0:(ldlm_lib.c:1176:target_handle_connect()) Skipped 2 previous similar messages [ 3256.620363] Lustre: DEBUG MARKER: == replay-single test 44b: race in target handle connect ========================================================== 02:53:47 (1788591227) [ 3258.924590] LustreError: 96484:0:(ldlm_lib.c:1434:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 3269.182651] Lustre: lustre-MDT0000: Export ffff8ac2b015c800 already connecting from 192.168.206.5@tcp [ 3274.309348] Lustre: lustre-MDT0000: Export ffff8ac2b015c800 already connecting from 192.168.206.5@tcp [ 3279.420810] Lustre: lustre-MDT0000: Export ffff8ac2b015c800 already connecting from 192.168.206.5@tcp [ 3282.519970] Lustre: lustre-MDT0000: Export ffff8ac2b015c800 already connecting from 192.168.206.5@tcp [ 3289.661376] Lustre: lustre-MDT0000: Export ffff8ac2b015c800 already connecting from 192.168.206.5@tcp [ 3289.672676] Lustre: Skipped 1 previous similar message [ 3298.928113] LustreError: 96484:0:(ldlm_lib.c:1434:target_handle_connect()) cfs_fail_timeout id 704 awake [ 3298.935412] Lustre: 96484:0:(service.c:2582:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/20s); client may timeout req@ffff8ac2bf966300 x1875470472254336/t0(0) o38->f528b28b-848d-4379-b124-8eccca8717da@192.168.206.5@tcp:0/0 lens 520/416 e 0 to 0 dl 1788591250 ref 1 fl Complete:H/200/0 rc 0/0 job:'lctl.0' uid:0 gid:0 projid:4294967295 [ 3299.905641] Lustre: lustre-MDT0000: Client f528b28b-848d-4379-b124-8eccca8717da (at 192.168.206.5@tcp) reconnecting [ 3299.919474] Lustre: Skipped 3 previous similar messages [ 3299.923876] LustreError: 98301:0:(ldlm_lib.c:1434:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 3325.502854] Lustre: lustre-MDT0000: Export ffff8ac2b015c800 already connecting from 192.168.206.5@tcp [ 3325.519509] Lustre: Skipped 1 previous similar message [ 3339.984205] LustreError: 98301:0:(ldlm_lib.c:1434:target_handle_connect()) cfs_fail_timeout id 704 awake [ 3339.992623] Lustre: 98301:0:(service.c:2582:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/20s); client may timeout req@ffff8ac2b5cb6d80 x1875470472257408/t0(0) o38->f528b28b-848d-4379-b124-8eccca8717da@192.168.206.5@tcp:0/0 lens 520/416 e 0 to 0 dl 1788591291 ref 1 fl Complete:H/200/0 rc 0/0 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3340.863354] LustreError: 96484:0:(ldlm_lib.c:1434:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 3366.476408] Lustre: lustre-MDT0000: Export ffff8ac2b015c800 already connecting from 192.168.206.5@tcp [ 3366.483808] Lustre: Skipped 3 previous similar messages [ 3380.864097] LustreError: 96484:0:(ldlm_lib.c:1434:target_handle_connect()) cfs_fail_timeout id 704 awake [ 3380.878148] Lustre: 96484:0:(service.c:2582:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/20s); client may timeout req@ffff8ac18545f480 x1875470472259328/t0(0) o38->f528b28b-848d-4379-b124-8eccca8717da@192.168.206.5@tcp:0/0 lens 520/416 e 0 to 0 dl 1788591332 ref 1 fl Complete:H/200/0 rc 0/0 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3381.827077] Lustre: lustre-MDT0000: Client f528b28b-848d-4379-b124-8eccca8717da (at 192.168.206.5@tcp) reconnecting [ 3381.833515] Lustre: Skipped 1 previous similar message [ 3381.837544] LustreError: 96483:0:(ldlm_lib.c:1434:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 3406.417751] Lustre: lustre-MDT0000: Export ffff8ac2b015c800 already connecting from 192.168.206.5@tcp [ 3406.430777] Lustre: Skipped 3 previous similar messages [ 3421.880132] LustreError: 96483:0:(ldlm_lib.c:1434:target_handle_connect()) cfs_fail_timeout id 704 awake [ 3421.888037] Lustre: 96483:0:(service.c:2582:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/20s); client may timeout req@ffff8ac18945b800 x1875470472261248/t0(0) o38->f528b28b-848d-4379-b124-8eccca8717da@192.168.206.5@tcp:0/0 lens 520/416 e 0 to 0 dl 1788591373 ref 1 fl Complete:H/200/0 rc 0/0 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3426.881305] LustreError: 99145:0:(ldlm_lib.c:1434:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 3466.928135] LustreError: 99145:0:(ldlm_lib.c:1434:target_handle_connect()) cfs_fail_timeout id 704 awake [ 3466.936943] Lustre: 99145:0:(service.c:2582:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/20s); client may timeout req@ffff8ac2b5cb6300 x1875470472263424/t0(0) o38->f528b28b-848d-4379-b124-8eccca8717da@192.168.206.5@tcp:0/0 lens 520/416 e 0 to 0 dl 1788591418 ref 1 fl Complete:H/200/0 rc 0/0 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3467.849995] LustreError: 98301:0:(ldlm_lib.c:1434:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 3487.681130] LustreError: 98301:0:(ldlm_lib.c:1434:target_handle_connect()) cfs_fail_timeout interrupted [ 3493.012229] Lustre: DEBUG MARKER: == replay-single test 44c: race in target handle connect ========================================================== 02:57:43 (1788591463) [ 3496.897890] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3501.131741] Lustre: Failing over lustre-MDT0000 [ 3501.538939] Lustre: server umount lustre-MDT0000 complete [ 3511.573355] Lustre: *** cfs_fail_loc=712, val=0*** [ 3511.588494] LustreError: 36626:0:(service.c:1394:ptlrpc_check_req()) @@@ Invalid replay without recovery req@ffff8ac2bb477b80 x1875470484634624/t0(0) o400->lustre-MDT0000-mdtlov_UUID@0@lo:0/0 lens 224/0 e 0 to 0 dl 0 ref 1 fl New:/2c0/ffffffff rc 0/-1 job:'ptlrpcd_rcv.0' uid:0 gid:0 projid:4294967295 [ 3511.916866] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 3511.917061] Lustre: lustre-MDT0000: Aborting client recovery [ 3511.921617] Lustre: Skipped 9 previous similar messages [ 3511.929811] LustreError: 101020:0:(ldlm_lib.c:3029:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 3511.949483] Lustre: 101066:0:(ldlm_lib.c:2429:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 3511.964492] Lustre: 101066:0:(ldlm_lib.c:2429:target_recovery_overseer()) Skipped 2 previous similar messages [ 3511.970911] Lustre: 101066:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client f528b28b-848d-4379-b124-8eccca8717da@ [ 3511.988727] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 3512.121656] Lustre: lustre-MDT0000-osd: cancel update llog [0x2000182d0:0x1:0x0] [ 3512.268430] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2867 to 0x240000400:2945) [ 3512.276513] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2866 to 0x280000400:2913) [ 3517.062575] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3525.091602] Lustre: Failing over lustre-MDT0000 [ 3525.480549] Lustre: server umount lustre-MDT0000 complete [ 3543.506506] Lustre: 3309:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788591499/real 1788591499] req@ffff8ac2ae73a680 x1875470484643712/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788591515 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3543.539995] Lustre: 3309:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 20 previous similar messages [ 3544.828270] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2866 to 0x280000400:2945) [ 3544.831334] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2867 to 0x240000400:2977) [ 3548.153554] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3558.768381] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3560.259632] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3569.150947] Lustre: DEBUG MARKER: == replay-single test 45: Handle failed close ============ 02:58:59 (1788591539) [ 3569.394894] Lustre: lustre-MDT0000: Client f528b28b-848d-4379-b124-8eccca8717da (at 192.168.206.5@tcp) reconnecting [ 3569.409140] Lustre: Skipped 2 previous similar messages [ 3576.829505] Lustre: DEBUG MARKER: == replay-single test 46: Don't leak file handle after open resend (3325) ========================================================== 02:59:07 (1788591547) [ 3577.913711] Lustre: *** cfs_fail_loc=122, val=2147483648*** [ 3577.923106] LustreError: 101996:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff8ac290e68e00 x1875470472320768/t0(0) o700->f528b28b-848d-4379-b124-8eccca8717da@192.168.206.5@tcp:335/0 lens 264/248 e 0 to 0 dl 1788591560 ref 1 fl Interpret:/200/0 rc 0/0 job:'touch.0' uid:0 gid:0 projid:4294967295 [ 3597.878992] Lustre: Failing over lustre-MDT0000 [ 3598.239631] Lustre: server umount lustre-MDT0000 complete [ 3625.442091] LustreError: 3308:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8ac181f2f100 x1875470484664192/t0(0) o250->MGC192.168.206.105@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 [ 3629.687384] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3640.298305] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 3640.310422] Lustre: Skipped 8 previous similar messages [ 3640.653263] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2947 to 0x280000400:2977) [ 3640.660344] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2979 to 0x240000400:3009) [ 3647.670399] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3649.171582] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3659.925901] Lustre: DEBUG MARKER: == replay-single test 47: MDS->OSC failure during precreate cleanup (2824) ========================================================== 03:00:30 (1788591630) [ 3662.774323] Lustre: Failing over lustre-OST0000 [ 3664.894162] Lustre: server umount lustre-OST0000 complete [ 3665.896590] 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 [ 3665.922977] Lustre: Skipped 9 previous similar messages [ 3665.936698] LustreError: 6695:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: 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. [ 3684.009740] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 3684.019336] Lustre: Skipped 4 previous similar messages [ 3685.161385] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 3685.170498] Lustre: Skipped 3 previous similar messages [ 3685.611167] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 3685.624117] Lustre: Skipped 3 previous similar messages [ 3691.276367] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3701.101870] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 3702.505201] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 3775.089544] Lustre: DEBUG MARKER: == replay-single test 48: MDS->OSC failure during precreate cleanup (2824) ========================================================== 03:02:25 (1788591745) [ 3778.641599] LustreError: 106250:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 3778.646377] LustreError: 106250:0:(osd_handler.c:720:osd_ro()) Skipped 1 previous similar message [ 3779.552911] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3782.117858] Lustre: Failing over lustre-MDT0000 [ 3782.448970] Lustre: server umount lustre-MDT0000 complete [ 3799.967923] LustreError: MGC192.168.206.105@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3799.978149] LustreError: Skipped 3 previous similar messages [ 3805.306684] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3810.076087] Lustre: *** cfs_fail_loc=216, val=0*** [ 3810.076669] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3030 to 0x240000400:3073) [ 3810.080905] LustreError: 106889:0:(osp_precreate.c:974:osp_precreate_cleanup_orphans()) lustre-OST0001-osc-MDT0000: cannot cleanup orphans: rc = -30 [ 3811.169498] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2998 to 0x280000400:3041) [ 3877.558598] Lustre: DEBUG MARKER: == replay-single test 50: Double OSC recovery, don't LASSERT (3812) ========================================================== 03:04:08 (1788591848) [ 3879.258842] Lustre: lustre-OST0000: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnecting [ 3879.269371] Lustre: Skipped 2 previous similar messages [ 3890.938122] Lustre: DEBUG MARKER: == replay-single test 52: time out lock replay (3764) ==== 03:04:21 (1788591861) [ 3893.417064] Lustre: Failing over lustre-MDT0000 [ 3893.650706] Lustre: server umount lustre-MDT0000 complete [ 3912.653735] Lustre: *** cfs_fail_loc=157, val=2147483648*** [ 3912.657195] LustreError: 108532:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff8ac287411c00 x1875470472437120/t0(0) o101->f528b28b-848d-4379-b124-8eccca8717da@192.168.206.5@tcp:670/0 lens 328/344 e 0 to 0 dl 1788591895 ref 1 fl Complete:/240/0 rc 0/0 job:'ldlm_lock_repla.0' uid:0 gid:0 projid:4294967295 [ 3917.316350] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3928.125108] Lustre: lustre-MDT0000: Client f528b28b-848d-4379-b124-8eccca8717da (at 192.168.206.5@tcp) reconnected, waiting for 1 clients in recovery for 1:25 [ 3928.280117] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3052 to 0x280000400:3073) [ 3928.280189] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3085 to 0x240000400:3105) [ 3934.651835] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3936.164952] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3946.355287] Lustre: DEBUG MARKER: == replay-single test 53a: |X| close request while two MDC requests in flight ========================================================== 03:05:17 (1788591917) [ 3948.621990] Lustre: *** cfs_fail_loc=115, val=2147483648*** [ 3953.245249] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3955.255554] Lustre: Failing over lustre-MDT0000 [ 3955.574434] Lustre: server umount lustre-MDT0000 complete [ 3984.864717] LustreError: 3308:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8ac2ae734e00 x1875470484763392/t0(0) o250->MGC192.168.206.105@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 [ 3989.647303] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3075 to 0x280000400:3105) [ 3989.648698] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3085 to 0x240000400:3137) [ 3990.009197] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3999.265963] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4001.101333] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4010.164030] Lustre: DEBUG MARKER: == replay-single test 53b: |X| open request while two MDC requests in flight ========================================================== 03:06:21 (1788591981) [ 4011.074482] Lustre: *** cfs_fail_loc=107, val=2147483648*** [ 4016.346831] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4017.920123] Lustre: Failing over lustre-MDT0000 [ 4018.139850] Lustre: server umount lustre-MDT0000 complete [ 4051.391647] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4052.087679] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3139 to 0x240000400:3169) [ 4052.091254] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3075 to 0x280000400:3137) [ 4059.779656] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4061.155283] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4070.852466] Lustre: DEBUG MARKER: == replay-single test 53c: |X| open request and close request while two MDC requests in flight ========================================================== 03:07:21 (1788592041) [ 4071.692236] Lustre: *** cfs_fail_loc=107, val=2147483648*** [ 4077.206683] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4079.402960] Lustre: Failing over lustre-MDT0000 [ 4079.672824] Lustre: server umount lustre-MDT0000 complete [ 4097.174740] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3171 to 0x240000400:3201) [ 4097.174759] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3075 to 0x280000400:3169) [ 4100.282695] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4111.107147] Lustre: DEBUG MARKER: == replay-single test 53d: close reply while two MDC requests in flight ========================================================== 03:08:01 (1788592081) [ 4113.338470] Lustre: *** cfs_fail_loc=13b, val=315*** [ 4113.342153] Lustre: *** cfs_fail_loc=13b, val=2147483648*** [ 4113.347150] LustreError: 113631:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff8ac2913b3480 x1875470472486016/t257698037777(0) o35->f528b28b-848d-4379-b124-8eccca8717da@192.168.206.5@tcp:116/0 lens 392/456 e 0 to 0 dl 1788592096 ref 1 fl Interpret:/600/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 4116.073455] Lustre: Failing over lustre-MDT0000 [ 4116.478306] Lustre: server umount lustre-MDT0000 complete [ 4133.919988] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4133.930785] Lustre: Skipped 10 previous similar messages [ 4137.591703] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4140.178053] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3203 to 0x240000400:3233) [ 4140.178618] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3075 to 0x280000400:3201) [ 4140.191546] Lustre: 114928:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff8ac287412680 x1875470472486016/t257698037777(0) o35->f528b28b-848d-4379-b124-8eccca8717da@192.168.206.5@tcp:143/0 lens 392/456 e 0 to 0 dl 1788592123 ref 1 fl Interpret:/602/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 4146.159250] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4147.710984] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4148.192258] Lustre: 3311:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788592104/real 1788592104] req@ffff8ac2ba5ddc00 x1875470484808960/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788592120 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4148.219103] Lustre: 3311:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 61 previous similar messages [ 4156.089810] Lustre: DEBUG MARKER: == replay-single test 53e: |X| open reply while two MDC requests in flight ========================================================== 03:08:46 (1788592126) [ 4157.429992] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 4157.438869] LustreError: 114927:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff8ac29d9b0700 x1875470472499200/t261993005072(0) o36->f528b28b-848d-4379-b124-8eccca8717da@192.168.206.5@tcp:160/0 lens 504/448 e 0 to 0 dl 1788592140 ref 1 fl Interpret:/200/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 4163.507601] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4165.535539] Lustre: Failing over lustre-MDT0000 [ 4165.886335] Lustre: server umount lustre-MDT0000 complete [ 4189.529477] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4197.981890] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3075 to 0x280000400:3233) [ 4197.989303] Lustre: 116615:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff8ac2b6347b80 x1875470472499200/t261993005072(0) o36->f528b28b-848d-4379-b124-8eccca8717da@192.168.206.5@tcp:200/0 lens 504/2880 e 0 to 0 dl 1788592180 ref 1 fl Interpret:/202/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 4197.990744] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3235 to 0x240000400:3265) [ 4204.178736] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4206.260262] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4215.721250] Lustre: DEBUG MARKER: == replay-single test 53f: |X| open reply and close reply while two MDC requests in flight ========================================================== 03:09:46 (1788592186) [ 4217.383901] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 4217.385805] LustreError: 116615:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff8ac287410e00 x1875470472513280/t266287972368(0) o36->f528b28b-848d-4379-b124-8eccca8717da@192.168.206.5@tcp:220/0 lens 504/448 e 0 to 0 dl 1788592200 ref 1 fl Interpret:/200/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 4219.533140] Lustre: *** cfs_fail_loc=13b, val=315*** [ 4223.752059] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4225.775687] Lustre: Failing over lustre-MDT0000 [ 4225.980783] Lustre: server umount lustre-MDT0000 complete [ 4257.684232] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4258.478560] Lustre: 118308:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff8ac2aec73480 x1875470472514048/t266287972369(0) o35->f528b28b-848d-4379-b124-8eccca8717da@192.168.206.5@tcp:261/0 lens 392/456 e 0 to 0 dl 1788592241 ref 1 fl Interpret:/602/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 4258.512613] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3267 to 0x240000400:3297) [ 4258.520743] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3075 to 0x280000400:3265) [ 4258.525277] Lustre: 118308:0:(mdt_recovery.c:102:mdt_req_from_lrd()) Skipped 1 previous similar message [ 4266.407216] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 4266.418028] Lustre: Skipped 18 previous similar messages [ 4269.072318] Lustre: DEBUG MARKER: == replay-single test 53g: |X| drop open reply and close request while close and open are both in flight ========================================================== 03:10:39 (1788592239) [ 4270.086290] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 4270.093942] Lustre: Skipped 1 previous similar message [ 4270.098363] LustreError: 118307:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff8ac2b4b8d180 x1875470472525696/t270582939664(0) o36->f528b28b-848d-4379-b124-8eccca8717da@192.168.206.5@tcp:273/0 lens 504/448 e 0 to 0 dl 1788592253 ref 1 fl Interpret:/200/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 4270.129293] LustreError: 118307:0:(ldlm_lib.c:3373:target_send_reply_msg()) Skipped 1 previous similar message [ 4271.972296] Lustre: *** cfs_fail_loc=115, val=2147483648*** [ 4271.977826] Lustre: Skipped 1 previous similar message [ 4276.874301] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4278.702310] Lustre: Failing over lustre-MDT0000 [ 4278.860497] Lustre: lustre-MDT0000: Not available for connect from 192.168.206.5@tcp (stopping) [ 4279.004919] Lustre: server umount lustre-MDT0000 complete [ 4297.184204] Lustre: lustre-MDT0000-lwp-OST0001: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 4297.204045] Lustre: Skipped 18 previous similar messages [ 4308.256656] LustreError: 3308:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8ac2b5cb5f80 x1875470484858112/t0(0) o250->MGC192.168.206.105@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 [ 4308.799289] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4308.805486] Lustre: Skipped 8 previous similar messages [ 4314.108935] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4319.832151] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4319.848130] Lustre: Skipped 8 previous similar messages [ 4320.011342] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4320.029416] Lustre: Skipped 8 previous similar messages [ 4320.054506] Lustre: 119845:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff8ac2b5cb6300 x1875470472525696/t270582939664(0) o36->f528b28b-848d-4379-b124-8eccca8717da@192.168.206.5@tcp:322/0 lens 504/2880 e 0 to 0 dl 1788592302 ref 1 fl Interpret:/202/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 4320.066443] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3299 to 0x240000400:3329) [ 4320.111883] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3075 to 0x280000400:3297) [ 4329.104991] Lustre: DEBUG MARKER: == replay-single test 53h: open request and close reply while two MDC requests in flight ========================================================== 03:11:39 (1788592299) [ 4330.096972] Lustre: *** cfs_fail_loc=107, val=2147483648*** [ 4332.254778] Lustre: *** cfs_fail_loc=13b, val=315*** [ 4332.261839] Lustre: *** cfs_fail_loc=13b, val=2147483648*** [ 4332.267023] LustreError: 119847:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff8ac290e68e00 x1875470472538496/t274877906960(0) o35->f528b28b-848d-4379-b124-8eccca8717da@192.168.206.5@tcp:335/0 lens 392/456 e 0 to 0 dl 1788592315 ref 1 fl Interpret:/600/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 4336.338783] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4338.304569] Lustre: Failing over lustre-MDT0000 [ 4338.531712] Lustre: server umount lustre-MDT0000 complete [ 4357.651489] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3299 to 0x280000400:3329) [ 4357.651696] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3299 to 0x240000400:3361) [ 4357.689451] Lustre: 121286:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff8ac28fc4ed80 x1875470472538496/t274877906960(0) o35->f528b28b-848d-4379-b124-8eccca8717da@192.168.206.5@tcp:360/0 lens 392/456 e 0 to 0 dl 1788592340 ref 1 fl Interpret:/602/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 4361.335640] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4372.571696] Lustre: DEBUG MARKER: == replay-single test 55: let MDS_CHECK_RESENT return the original return code instead of 0 ========================================================== 03:12:23 (1788592343) [ 4373.567580] Lustre: *** cfs_fail_loc=12b, val=2147483991*** [ 4373.574994] LustreError: 121283:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff8ac287410000 x1875470472548608/t279172874255(0) o101->f528b28b-848d-4379-b124-8eccca8717da@192.168.206.5@tcp:376/0 lens 664/608 e 0 to 0 dl 1788592356 ref 1 fl Interpret:/600/0 rc 301/0 job:'touch.0' uid:0 gid:0 projid:0 [ 4388.935063] Lustre: 121283:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff8ac2aec72d80 x1875470472548608/t279172874255(0) o101->f528b28b-848d-4379-b124-8eccca8717da@192.168.206.5@tcp:391/0 lens 664/3488 e 0 to 0 dl 1788592371 ref 1 fl Interpret:/602/0 rc 0/0 job:'touch.0' uid:0 gid:0 projid:0 [ 4396.398438] Lustre: DEBUG MARKER: == replay-single test 56: don't replay a symlink open request (3440) ========================================================== 03:12:46 (1788592366) [ 4399.420203] LustreError: 122399:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 4399.435929] LustreError: 122399:0:(osd_handler.c:720:osd_ro()) Skipped 7 previous similar messages [ 4400.404746] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4402.712281] Lustre: Failing over lustre-MDT0000 [ 4402.966395] Lustre: server umount lustre-MDT0000 complete [ 4422.214578] LustreError: MGC192.168.206.105@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4422.228248] LustreError: Skipped 9 previous similar messages [ 4427.430330] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4429.979268] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3331 to 0x280000400:3361) [ 4429.980158] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3299 to 0x240000400:3393) [ 4436.543437] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4437.957949] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4457.048988] Lustre: DEBUG MARKER: == replay-single test 57: test recovery from llog for setattr op ========================================================== 03:13:47 (1788592427) [ 4461.981517] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4464.148568] Lustre: Failing over lustre-MDT0000 [ 4464.456427] Lustre: server umount lustre-MDT0000 complete [ 4487.729636] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4491.430463] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3331 to 0x280000400:3393) [ 4491.432099] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3395 to 0x240000400:3425) [ 4497.100797] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4498.563686] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4505.049337] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 4516.570829] Lustre: DEBUG MARKER: == replay-single test 58a: test recovery from llog for setattr op (test llog_gen_rec) ========================================================== 03:14:47 (1788592487) [ 4556.320418] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4558.364698] Lustre: Failing over lustre-MDT0000 [ 4558.996854] Lustre: server umount lustre-MDT0000 complete [ 4578.802075] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:4644 to 0x280000400:4673) [ 4578.802528] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:4676 to 0x240000400:4705) [ 4582.868614] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4591.823923] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4593.456817] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4647.944901] Lustre: DEBUG MARKER: == replay-single test 58b: test replay of setxattr op ==== 03:16:58 (1788592618) [ 4652.695840] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4654.765605] Lustre: Failing over lustre-MDT0000 [ 4655.083603] Lustre: server umount lustre-MDT0000 complete [ 4681.697301] LustreError: 3308:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8ac183155180 x1875470485608960/t0(0) o250->MGC192.168.206.105@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 [ 4686.523891] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4693.314648] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:4707 to 0x240000400:4737) [ 4693.316540] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:4644 to 0x280000400:4705) [ 4699.642896] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4701.545783] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4711.566933] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount FULL mgc.*.mgs_server_uuid 1475 0 [ 4713.116889] Lustre: DEBUG MARKER: mgc.*.mgs_server_uuid in FULL state after 0 sec [ 4718.745221] Lustre: DEBUG MARKER: == replay-single test 58c: resend/reconstruct setxattr op ========================================================== 03:18:09 (1788592689) [ 4725.727240] Lustre: *** cfs_fail_loc=123, val=2147483648*** [ 4741.183376] Lustre: lustre-MDT0000: Client f528b28b-848d-4379-b124-8eccca8717da (at 192.168.206.5@tcp) reconnecting [ 4741.191664] Lustre: Skipped 2 previous similar messages [ 4743.682171] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 4743.687532] Lustre: Skipped 1 previous similar message [ 4743.690068] LustreError: 129800:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff8ac2bf75ac50 x1875470475329792/t296352743435(0) o36->f528b28b-848d-4379-b124-8eccca8717da@192.168.206.5@tcp:746/0 lens 66040/440 e 0 to 0 dl 1788592726 ref 1 fl Interpret:/600/0 rc 0/0 job:'setfattr.0' uid:0 gid:0 projid:0 [ 4759.118398] Lustre: 128707:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff8ac18455ca80 x1875470475329792/t296352743435(0) o36->f528b28b-848d-4379-b124-8eccca8717da@192.168.206.5@tcp:7/0 lens 66040/440 e 0 to 0 dl 1788592742 ref 1 fl Interpret:/602/0 rc 0/0 job:'setfattr.0' uid:0 gid:0 projid:0 [ 4768.902459] Lustre: DEBUG MARKER: SKIP: replay-single test_59 skipping ALWAYS excluded test 59 [ 4770.603407] Lustre: DEBUG MARKER: == replay-single test 60: test llog post recovery init vs llog unlink ========================================================== 03:19:01 (1788592741) [ 4780.869856] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4783.821937] Lustre: Failing over lustre-MDT0000 [ 4784.195371] Lustre: server umount lustre-MDT0000 complete [ 4802.657795] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4802.667472] Lustre: Skipped 8 previous similar messages [ 4804.454226] Lustre: 3309:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788592760/real 1788592760] req@ffff8ac2a9343b80 x1875470485640576/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788592776 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4804.487904] Lustre: 3309:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 58 previous similar messages [ 4807.049291] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4811.398319] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:4838 to 0x240000400:4865) [ 4811.400190] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:4807 to 0x280000400:4833) [ 4816.266597] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4817.715845] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4826.533745] Lustre: DEBUG MARKER: == replay-single test 61a: test race llog recovery vs llog cleanup ========================================================== 03:19:57 (1788592797) [ 4843.845288] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 4856.298157] Lustre: Failing over lustre-OST0000 [ 4856.346629] Lustre: server umount lustre-OST0000 complete [ 4856.414968] LustreError: 36619:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.206.5@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4856.435277] LustreError: 36619:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 7 previous similar messages [ 4857.364936] LustreError: lustre-OST0000-osc-MDT0000: operation ost_destroy to node 0@lo failed: rc = -107 [ 4857.371756] LustreError: Skipped 4 previous similar messages [ 4878.078836] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 4878.088965] Lustre: Skipped 15 previous similar messages [ 4880.987476] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4895.399627] Lustre: Failing over lustre-OST0000 [ 4895.504673] Lustre: server umount lustre-OST0000 complete [ 4898.785771] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 4898.798385] LustreError: Skipped 1 previous similar message [ 4898.804045] 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 [ 4898.819373] Lustre: Skipped 14 previous similar messages [ 4898.828693] LustreError: 12073:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: 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. [ 4898.840303] LustreError: 12073:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 7 previous similar messages [ 4913.983994] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 4913.989774] Lustre: Skipped 7 previous similar messages [ 4920.348611] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4924.254957] Lustre: lustre-OST0000: Recovery over after 0:09, of 2 clients 2 recovered and 0 were evicted. [ 4924.264528] Lustre: Skipped 7 previous similar messages [ 4930.098756] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 4931.756660] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4972.712360] Lustre: DEBUG MARKER: == replay-single test 61b: test race mds llog sync vs llog cleanup ========================================================== 03:22:23 (1788592943) [ 4975.608045] Lustre: Failing over lustre-MDT0000 [ 4975.952510] Lustre: server umount lustre-MDT0000 complete [ 5002.218563] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x14167a5a6b011272 [ 5003.844112] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 5003.846581] Lustre: Skipped 8 previous similar messages [ 5004.021822] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5234 to 0x280000400:5249) [ 5004.023771] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5266 to 0x240000400:5281) [ 5007.374612] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5021.727312] Lustre: Failing over lustre-MDT0000 [ 5022.238402] Lustre: server umount lustre-MDT0000 complete [ 5039.286861] LustreError: MGC192.168.206.105@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5039.305451] LustreError: Skipped 5 previous similar messages [ 5039.586821] LustreError: 136719:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 5039.595743] LustreError: 136719:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 3 previous similar messages [ 5041.949279] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5266 to 0x240000400:5313) [ 5041.950735] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5234 to 0x280000400:5281) [ 5044.349101] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5054.177762] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5055.650816] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5065.199347] Lustre: DEBUG MARKER: == replay-single test 61c: test race mds llog sync vs llog cleanup ========================================================== 03:23:55 (1788593035) [ 5079.134525] Lustre: Failing over lustre-OST0000 [ 5079.239182] Lustre: server umount lustre-OST0000 complete [ 5081.058373] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 5103.221134] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5111.350904] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 5112.761949] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 5120.898810] Lustre: DEBUG MARKER: == replay-single test 61d: error in llog_setup should cleanup the llog context correctly ========================================================== 03:24:51 (1788593091) [ 5122.547100] Lustre: Failing over lustre-MDT0000 [ 5122.936326] Lustre: server umount lustre-MDT0000 complete [ 5131.332906] Lustre: *** cfs_fail_loc=605, val=0*** [ 5131.334591] LustreError: 139728:0:(llog_obd.c:192:llog_setup()) MGS: ctxt 0 lop_setup=ffffffffc139bfc0 failed: rc = -95 [ 5131.351627] LustreError: 139728:0:(obd_config.c:845:class_setup()) setup MGS failed (-95) [ 5131.357865] LustreError: 139728:0:(obd_mount.c:259:lustre_start_simple()) MGS setup error -95 [ 5131.361985] LustreError: 139728:0:(tgt_mount.c:116:server_deregister_mount()) MGS not registered [ 5131.369414] LustreError: Failed to start MGS 'MGS' (-95). Is the 'mgs' module loaded? [ 5131.373431] LustreError: 139728:0:(tgt_mount.c:2132:server_put_super()) no obd lustre-MDT0000 [ 5131.495084] Lustre: server umount lustre-MDT0000 complete [ 5131.501101] LustreError: 139728:0:(super25.c:179:lustre_fill_super()) llite: Unable to mount : rc = -95 [ 5142.172747] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5283 to 0x280000400:5313) [ 5142.174093] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5315 to 0x240000400:5345) [ 5142.411140] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5150.338136] Lustre: DEBUG MARKER: == replay-single test 62: don't mis-drop resent replay === 03:25:21 (1788593121) [ 5153.912820] LustreError: 140774:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 5153.936086] LustreError: 140774:0:(osd_handler.c:720:osd_ro()) Skipped 5 previous similar messages [ 5154.837452] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5158.013469] Lustre: Failing over lustre-MDT0000 [ 5158.313413] Lustre: server umount lustre-MDT0000 complete [ 5177.941073] Lustre: *** cfs_fail_loc=707, val=0*** [ 5183.403545] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5194.324359] Lustre: lustre-MDT0000: Client f528b28b-848d-4379-b124-8eccca8717da (at 192.168.206.5@tcp) reconnected, waiting for 1 clients in recovery for 0:53 [ 5194.853974] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5359 to 0x240000400:5377) [ 5194.854467] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5326 to 0x280000400:5345) [ 5201.799278] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5203.846958] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5215.039127] Lustre: DEBUG MARKER: == replay-single test 65a: AT: verify early replies ====== 03:26:25 (1788593185) [ 5245.830587] LustreError: 142112:0:(service.c:2558:ptlrpc_server_handle_request()) @@@ HIT req@ffff8ac18a35b800 x1875470476203264/t0(0) o101->f528b28b-848d-4379-b124-8eccca8717da@192.168.206.5@tcp:493/0 lens 664/0 e 0 to 0 dl 1788593228 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 5245.861616] LustreError: 142112:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a sleeping for 11000ms [ 5256.920500] LustreError: 142112:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a awake [ 5256.938203] LustreError: 141425:0:(service.c:2558:ptlrpc_server_handle_request()) @@@ HIT req@ffff8ac182d10e00 x1875470476204288/t0(0) o35->f528b28b-848d-4379-b124-8eccca8717da@192.168.206.5@tcp:510/0 lens 392/0 e 0 to 0 dl 1788593245 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 5259.233652] LustreError: 141420:0:(service.c:2558:ptlrpc_server_handle_request()) @@@ HIT req@ffff8ac184573b80 x1875470476210176/t0(0) o101->f528b28b-848d-4379-b124-8eccca8717da@192.168.206.5@tcp:547/0 lens 576/0 e 0 to 0 dl 1788593282 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'unlinkmany.0' uid:0 gid:0 projid:0 [ 5259.271748] LustreError: 141420:0:(service.c:2558:ptlrpc_server_handle_request()) Skipped 27 previous similar messages [ 5261.425188] LustreError: 6695:0:(service.c:2558:ptlrpc_server_handle_request()) @@@ HIT req@ffff8ac28fc4c380 x1875470485901952/t0(0) o6->lustre-MDT0000-mdtlov_UUID@0@lo:509/0 lens 544/0 e 0 to 0 dl 1788593244 ref 1 fl Interpret:/200/ffffffff rc 0/-1 job:'osp-syn-1-0.0' uid:0 gid:0 projid:4294967295 [ 5261.448239] LustreError: 6695:0:(service.c:2558:ptlrpc_server_handle_request()) Skipped 20 previous similar messages [ 5266.419190] LustreError: 14772:0:(service.c:2558:ptlrpc_server_handle_request()) @@@ HIT req@ffff8ac2b5def480 x1875470485903360/t0(0) o6->lustre-MDT0000-mdtlov_UUID@0@lo:514/0 lens 544/0 e 0 to 0 dl 1788593249 ref 1 fl Interpret:/200/ffffffff rc 0/-1 job:'osp-syn-0-0.0' uid:0 gid:0 projid:4294967295 [ 5266.463985] LustreError: 14772:0:(service.c:2558:ptlrpc_server_handle_request()) Skipped 7 previous similar messages [ 5276.017827] Lustre: DEBUG MARKER: == replay-single test 65b: AT: verify early replies on packed reply / bulk ========================================================== 03:27:26 (1788593246) [ 5306.224432] LustreError: 35393:0:(tgt_handler.c:2827:tgt_brw_write()) cfs_fail_timeout id 224 sleeping for 11000ms [ 5317.288113] LustreError: 35393:0:(tgt_handler.c:2827:tgt_brw_write()) cfs_fail_timeout id 224 awake [ 5327.141307] Lustre: DEBUG MARKER: == replay-single test 66a: AT: verify MDT service time adjusts with no early replies ========================================================== 03:28:17 (1788593297) [ 5355.674400] LustreError: 141420:0:(service.c:2558:ptlrpc_server_handle_request()) @@@ HIT req@ffff8ac2bf5a2300 x1875470476228352/t0(0) o101->f528b28b-848d-4379-b124-8eccca8717da@192.168.206.5@tcp:603/0 lens 576/0 e 0 to 0 dl 1788593338 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 5355.689641] LustreError: 141420:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a sleeping for 5000ms [ 5360.792130] LustreError: 141420:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a awake [ 5373.657026] LustreError: 142859:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a awake [ 5373.678833] LustreError: 142860:0:(service.c:2558:ptlrpc_server_handle_request()) @@@ HIT req@ffff8ac2a90afb80 x1875470476251136/t0(0) o101->f528b28b-848d-4379-b124-8eccca8717da@192.168.206.5@tcp:660/0 lens 664/0 e 0 to 0 dl 1788593395 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 5373.710802] LustreError: 142860:0:(service.c:2558:ptlrpc_server_handle_request()) Skipped 120 previous similar messages [ 5390.557730] Lustre: DEBUG MARKER: == replay-single test 66b: AT: verify net latency adjusts ========================================================== 03:29:21 (1788593361) [ 5482.590912] Lustre: DEBUG MARKER: == replay-single test 67a: AT: verify slow request processing doesn't induce reconnects ========================================================== 03:30:53 (1788593453) [ 5510.138756] LustreError: 141422:0:(service.c:2558:ptlrpc_server_handle_request()) @@@ HIT req@ffff8ac2c1082680 x1875470476306304/t0(0) o101->f528b28b-848d-4379-b124-8eccca8717da@192.168.206.5@tcp:3/0 lens 576/0 e 0 to 0 dl 1788593493 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 5510.160288] LustreError: 141422:0:(service.c:2558:ptlrpc_server_handle_request()) Skipped 98 previous similar messages [ 5510.169864] LustreError: 141422:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a sleeping for 400ms [ 5510.176858] LustreError: 141422:0:(service.c:2559:ptlrpc_server_handle_request()) Skipped 1 previous similar message [ 5510.600179] LustreError: 141422:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a awake [ 5526.442948] LustreError: 141425:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a sleeping for 400ms [ 5526.449113] LustreError: 141425:0:(service.c:2559:ptlrpc_server_handle_request()) Skipped 37 previous similar messages [ 5526.872116] LustreError: 141425:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a awake [ 5526.878488] LustreError: 141425:0:(service.c:2559:ptlrpc_server_handle_request()) Skipped 37 previous similar messages [ 5560.041437] Lustre: DEBUG MARKER: == replay-single test 67b: AT: verify instant slowdown doesn't induce reconnects ========================================================== 03:32:10 (1788593530) [ 5594.467741] Lustre: DEBUG MARKER: phase 2 [ 5602.498357] Lustre: DEBUG MARKER: == replay-single test 68: AT: verify slowing locks ======= 03:32:53 (1788593573) [ 5682.722362] Lustre: DEBUG MARKER: == replay-single test 70a: check multi client t-f ======== 03:34:13 (1788593653) [ 5684.439282] Lustre: DEBUG MARKER: SKIP: replay-single test_70a Need two or more clients, have 1 [ 5686.336834] Lustre: DEBUG MARKER: == replay-single test 70b: dbench 1mdts recovery; 1 clients ========================================================== 03:34:16 (1788593656) [ 5690.783817] Lustre: DEBUG MARKER: Started rundbench load pid=128680 ... [ 5695.678226] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5698.407117] Lustre: DEBUG MARKER: test_70b fail mds1 1 times [ 5700.493035] Lustre: Failing over lustre-MDT0000 [ 5700.653262] Lustre: lustre-MDT0000: Not available for connect from 192.168.206.5@tcp (stopping) [ 5700.843859] Lustre: server umount lustre-MDT0000 complete [ 5719.008128] Lustre: 3310:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788593674/real 1788593674] req@ffff8ac2aec71180 x1875470486023296/t0(0) o400->MGC192.168.206.105@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1788593690 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5719.008468] 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 [ 5719.047638] Lustre: 3310:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 37 previous similar messages [ 5719.047696] LustreError: MGC192.168.206.105@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5719.047699] LustreError: Skipped 2 previous similar messages [ 5719.122526] Lustre: Skipped 10 previous similar messages [ 5728.289653] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x14167a5a6b0185a5 [ 5728.317279] Lustre: MGC192.168.206.105@tcp: Connection restored to 0@lo (at 0@lo) [ 5728.323800] Lustre: Skipped 11 previous similar messages [ 5728.781654] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 5728.785869] Lustre: Skipped 5 previous similar messages [ 5728.880210] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 5728.889958] Lustre: Skipped 7 previous similar messages [ 5734.091771] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5740.114645] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 5740.126805] Lustre: Skipped 4 previous similar messages [ 5740.697169] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 5740.714027] Lustre: Skipped 5 previous similar messages [ 5740.779651] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5426 to 0x280000400:5441) [ 5740.783141] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5480 to 0x240000400:5505) [ 5746.429591] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5748.271864] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5754.937754] LustreError: 149718:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 5754.943202] LustreError: 149718:0:(osd_handler.c:720:osd_ro()) Skipped 1 previous similar message [ 5755.987795] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5758.530902] Lustre: DEBUG MARKER: test_70b fail mds1 2 times [ 5760.136067] Lustre: Failing over lustre-MDT0000 [ 5760.459503] Lustre: server umount lustre-MDT0000 complete [ 5781.226039] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5465 to 0x280000400:5505) [ 5781.226480] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5530 to 0x240000400:5569) [ 5783.353569] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5793.545561] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5794.982938] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5801.985987] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5804.490555] Lustre: DEBUG MARKER: test_70b fail mds1 3 times [ 5806.376367] Lustre: Failing over lustre-MDT0000 [ 5806.601879] Lustre: server umount lustre-MDT0000 complete [ 5833.189852] LustreError: 3308:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8ac18a359f80 x1875470486199680/t0(0) o250->MGC192.168.206.105@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 [ 5838.012917] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5847.247700] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5619 to 0x240000400:5665) [ 5847.249320] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5555 to 0x280000400:5601) [ 5852.875679] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5854.098650] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5861.722497] Lustre: DEBUG MARKER: == replay-single test 70c: tar 1mdts recovery ============ 03:37:12 (1788593832) [ 5987.833662] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 6000.236211] Lustre: DEBUG MARKER: test_70c fail mds1 1 times [ 6002.402754] Lustre: Failing over lustre-MDT0000 [ 6002.506135] Lustre: lustre-MDT0000: Not available for connect from 192.168.206.5@tcp (stopping) [ 6002.866427] Lustre: server umount lustre-MDT0000 complete [ 6026.567455] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6046.605428] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6272 to 0x280000400:6305) [ 6046.628878] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6336 to 0x240000400:6369) [ 6052.262802] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6053.645905] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6135.109985] Lustre: DEBUG MARKER: == replay-single test 70d: mkdir/rmdir striped dir 1mdts recovery ========================================================== 03:41:46 (1788594106) [ 6136.684981] Lustre: DEBUG MARKER: SKIP: replay-single test_70d needs >= 2 MDTs [ 6138.285918] Lustre: DEBUG MARKER: == replay-single test 70e: rename cross-MDT with random fails ========================================================== 03:41:49 (1788594109) [ 6139.863307] Lustre: DEBUG MARKER: SKIP: replay-single test_70e needs >= 2 MDTs [ 6141.660109] Lustre: DEBUG MARKER: == replay-single test 70f: OSS O_DIRECT recovery with 1 clients ========================================================== 03:41:52 (1788594112) [ 6148.850837] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 6151.293577] Lustre: DEBUG MARKER: test_70f failing OST 1 times [ 6153.172597] Lustre: Failing over lustre-OST0000 [ 6153.259238] Lustre: server umount lustre-OST0000 complete [ 6153.329591] LustreError: 36621:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.206.5@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 6153.372211] LustreError: 36621:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 9 previous similar messages [ 6154.211182] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 6163.526411] LustreError: 36620:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.206.5@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 6163.559652] LustreError: 36620:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 3 previous similar messages [ 6176.560771] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6185.713469] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 6187.369118] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 6197.405912] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 6199.708573] Lustre: DEBUG MARKER: test_70f failing OST 2 times [ 6201.372087] Lustre: Failing over lustre-OST0000 [ 6201.454635] Lustre: server umount lustre-OST0000 complete [ 6203.360687] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 6203.368437] LustreError: 36625:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: 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. [ 6203.379804] LustreError: 36625:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 3 previous similar messages [ 6224.434728] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6233.671597] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 6235.454325] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 6245.695750] Lustre: DEBUG MARKER: == replay-single test 71a: mkdir/rmdir striped dir with 2 mdts recovery ========================================================== 03:43:36 (1788594216) [ 6246.984377] Lustre: DEBUG MARKER: SKIP: replay-single test_71a needs >= 2 MDTs [ 6248.583299] Lustre: DEBUG MARKER: == replay-single test 73a: open(O_CREAT), unlink, replay, reconnect before open replay, close ========================================================== 03:43:39 (1788594219) [ 6252.318731] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 6254.583274] Lustre: Failing over lustre-MDT0000 [ 6254.749668] Lustre: server umount lustre-MDT0000 complete [ 6278.802644] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6281.300717] Lustre: *** cfs_fail_loc=302, val=2147483648*** [ 6297.706607] Lustre: lustre-MDT0000: Client f528b28b-848d-4379-b124-8eccca8717da (at 192.168.206.5@tcp) reconnected, waiting for 1 clients in recovery for 0:53 [ 6297.904375] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6625 to 0x240000400:6657) [ 6297.907673] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6560 to 0x280000400:6593) [ 6304.269718] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6305.596956] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6313.958345] Lustre: DEBUG MARKER: == replay-single test 73b: open(O_CREAT), unlink, replay, reconnect at open_replay reply, close ========================================================== 03:44:44 (1788594284) [ 6317.852247] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 6320.362355] Lustre: Failing over lustre-MDT0000 [ 6320.606728] Lustre: server umount lustre-MDT0000 complete [ 6336.992413] Lustre: 3309:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788594292/real 1788594292] req@ffff8ac28448f100 x1875470487069824/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788594308 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6337.029070] Lustre: 3309:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 36 previous similar messages [ 6337.043149] 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 [ 6337.057027] Lustre: Skipped 10 previous similar messages [ 6338.522384] LustreError: MGC192.168.206.105@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 6338.527965] LustreError: Skipped 4 previous similar messages [ 6338.681866] Lustre: lustre-MDT0000: Not available for connect from 192.168.206.5@tcp (not set up) [ 6338.904325] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 6338.912728] Lustre: Skipped 6 previous similar messages [ 6339.002585] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 6339.011120] Lustre: Skipped 6 previous similar messages [ 6340.057812] Lustre: *** cfs_fail_loc=157, val=2147483648*** [ 6340.064451] LustreError: 160517:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff8ac18872d180 x1875470484593920/t339302416387(339302416387) o101->f528b28b-848d-4379-b124-8eccca8717da@192.168.206.5@tcp:77/0 lens 592/608 e 0 to 0 dl 1788594322 ref 1 fl Interpret:/604/0 rc 301/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 6342.888843] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6346.920604] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 6346.931065] Lustre: Skipped 12 previous similar messages [ 6356.567476] Lustre: lustre-MDT0000: Client f528b28b-848d-4379-b124-8eccca8717da (at 192.168.206.5@tcp) reconnected, waiting for 1 clients in recovery for 0:53 [ 6356.585221] Lustre: 160517:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff8ac18872dc00 x1875470484593920/t339302416387(339302416387) o101->f528b28b-848d-4379-b124-8eccca8717da@192.168.206.5@tcp:94/0 lens 592/3488 e 0 to 0 dl 1788594339 ref 1 fl Interpret:/606/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 6356.664250] Lustre: lustre-MDT0000: Recovery over after 0:16, of 1 clients 1 recovered and 0 were evicted. [ 6356.669868] Lustre: Skipped 6 previous similar messages [ 6356.714457] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6595 to 0x280000400:6625) [ 6356.719407] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6625 to 0x240000400:6689) [ 6362.579791] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6364.077438] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6372.096130] Lustre: DEBUG MARKER: == replay-single test 74: Ensure applications don't fail waiting for OST recovery ========================================================== 03:45:42 (1788594342) [ 6376.482310] Lustre: Failing over lustre-OST0000 [ 6376.741095] Lustre: server umount lustre-OST0000 complete [ 6377.444575] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 6377.459624] LustreError: 36622:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: 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. [ 6377.479643] LustreError: 36622:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 6 previous similar messages [ 6380.933833] Lustre: Failing over lustre-MDT0000 [ 6381.292333] Lustre: server umount lustre-MDT0000 complete [ 6399.730783] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6595 to 0x280000400:6657) [ 6404.543943] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6411.849319] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 6411.860977] Lustre: Skipped 7 previous similar messages [ 6411.866434] Lustre: lustre-OST0000: Denying connection for new client 5a4c1b9d-c91b-41ba-b606-a416d6459455 (at 192.168.206.5@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:59 [ 6411.874491] Lustre: Skipped 11 previous similar messages [ 6415.955528] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6625 to 0x240000400:6721) [ 6416.610753] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6427.074983] Lustre: DEBUG MARKER: == replay-single test 80a: DNE: create remote dir, drop update rep from MDT0, fail MDT0 ========================================================== 03:46:37 (1788594397) [ 6428.915467] Lustre: DEBUG MARKER: SKIP: replay-single test_80a needs >= 2 MDTs [ 6431.005755] Lustre: DEBUG MARKER: == replay-single test 80b: DNE: create remote dir, drop update rep from MDT0, fail MDT1 ========================================================== 03:46:41 (1788594401) [ 6432.635938] Lustre: DEBUG MARKER: SKIP: replay-single test_80b needs >= 2 MDTs [ 6434.075311] Lustre: DEBUG MARKER: == replay-single test 80c: DNE: create remote dir, drop update rep from MDT1, fail MDT[0,1] ========================================================== 03:46:45 (1788594405) [ 6435.241942] Lustre: DEBUG MARKER: SKIP: replay-single test_80c needs >= 2 MDTs [ 6436.333783] Lustre: DEBUG MARKER: == replay-single test 80d: DNE: create remote dir, drop update rep from MDT1, fail 2 MDTs ========================================================== 03:46:47 (1788594407) [ 6437.590593] Lustre: DEBUG MARKER: SKIP: replay-single test_80d needs >= 2 MDTs [ 6438.961408] Lustre: DEBUG MARKER: == replay-single test 80e: DNE: create remote dir, drop MDT1 rep, fail MDT0 ========================================================== 03:46:49 (1788594409) [ 6440.591591] Lustre: DEBUG MARKER: SKIP: replay-single test_80e needs >= 2 MDTs [ 6442.394581] Lustre: DEBUG MARKER: == replay-single test 80f: DNE: create remote dir, drop MDT1 rep, fail MDT1 ========================================================== 03:46:53 (1788594413) [ 6443.737592] Lustre: DEBUG MARKER: SKIP: replay-single test_80f needs >= 2 MDTs [ 6445.136930] Lustre: DEBUG MARKER: == replay-single test 80g: DNE: create remote dir, drop MDT1 rep, fail MDT0, then MDT1 ========================================================== 03:46:56 (1788594416) [ 6446.524896] Lustre: DEBUG MARKER: SKIP: replay-single test_80g needs >= 2 MDTs [ 6448.081631] Lustre: DEBUG MARKER: == replay-single test 80h: DNE: create remote dir, drop MDT1 rep, fail 2 MDTs ========================================================== 03:46:58 (1788594418) [ 6449.235498] Lustre: DEBUG MARKER: SKIP: replay-single test_80h needs >= 2 MDTs [ 6450.710082] Lustre: DEBUG MARKER: == replay-single test 81a: DNE: unlink remote dir, drop MDT0 update rep, fail MDT1 ========================================================== 03:47:01 (1788594421) [ 6452.026475] Lustre: DEBUG MARKER: SKIP: replay-single test_81a needs >= 2 MDTs [ 6453.561977] Lustre: DEBUG MARKER: == replay-single test 81b: DNE: unlink remote dir, drop MDT0 update reply, fail MDT0 ========================================================== 03:47:04 (1788594424) [ 6454.844852] Lustre: DEBUG MARKER: SKIP: replay-single test_81b needs >= 2 MDTs [ 6456.491652] Lustre: DEBUG MARKER: == replay-single test 81c: DNE: unlink remote dir, drop MDT0 update reply, fail MDT0,MDT1 ========================================================== 03:47:07 (1788594427) [ 6457.745456] Lustre: DEBUG MARKER: SKIP: replay-single test_81c needs >= 2 MDTs [ 6459.481352] Lustre: DEBUG MARKER: == replay-single test 81d: DNE: unlink remote dir, drop MDT0 update reply, fail 2 MDTs ========================================================== 03:47:10 (1788594430) [ 6460.955746] Lustre: DEBUG MARKER: SKIP: replay-single test_81d needs >= 2 MDTs [ 6462.408683] Lustre: DEBUG MARKER: == replay-single test 81e: DNE: unlink remote dir, drop MDT1 req reply, fail MDT0 ========================================================== 03:47:13 (1788594433) [ 6463.717855] Lustre: DEBUG MARKER: SKIP: replay-single test_81e needs >= 2 MDTs [ 6465.427466] Lustre: DEBUG MARKER: == replay-single test 81f: DNE: unlink remote dir, drop MDT1 req reply, fail MDT1 ========================================================== 03:47:16 (1788594436) [ 6466.891209] Lustre: DEBUG MARKER: SKIP: replay-single test_81f needs >= 2 MDTs [ 6468.510835] Lustre: DEBUG MARKER: == replay-single test 81g: DNE: unlink remote dir, drop req reply, fail M0, then M1 ========================================================== 03:47:19 (1788594439) [ 6470.048554] Lustre: DEBUG MARKER: SKIP: replay-single test_81g needs >= 2 MDTs [ 6471.842144] Lustre: DEBUG MARKER: == replay-single test 81h: DNE: unlink remote dir, drop request reply, fail 2 MDTs ========================================================== 03:47:22 (1788594442) [ 6473.853204] Lustre: DEBUG MARKER: SKIP: replay-single test_81h needs >= 2 MDTs [ 6475.968214] Lustre: DEBUG MARKER: == replay-single test 84a: stale open during export disconnect ========================================================== 03:47:26 (1788594446) [ 6477.973759] Lustre: 165134:0:(genops.c:1774:obd_export_evict_by_uuid()) lustre-MDT0000: evicting 5a4c1b9d-c91b-41ba-b606-a416d6459455 at adminstrative request [ 6487.189136] Lustre: DEBUG MARKER: == replay-single test 85a: check the cancellation of unused locks during recovery(IBITS) ========================================================== 03:47:37 (1788594457) [ 6494.884626] Lustre: Failing over lustre-MDT0000 [ 6495.332481] Lustre: server umount lustre-MDT0000 complete [ 6523.297898] LustreError: 3308:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8ac181a0c000 x1875470487118208/t0(0) o250->MGC192.168.206.105@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 [ 6526.517639] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6709 to 0x280000400:6753) [ 6526.525864] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6773 to 0x240000400:6817) [ 6528.313965] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6536.785238] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6538.185503] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6545.368268] Lustre: DEBUG MARKER: == replay-single test 85b: check the cancellation of unused locks during recovery(EXTENT) ========================================================== 03:48:36 (1788594516) [ 6558.682701] Lustre: Failing over lustre-OST0000 [ 6560.844097] Lustre: server umount lustre-OST0000 complete [ 6561.350187] LustreError: 36617:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.206.5@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 6561.368777] LustreError: 36617:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 4 previous similar messages [ 6584.665268] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6593.359980] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 6595.036455] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 6604.407379] Lustre: DEBUG MARKER: == replay-single test 86: umount server after clear nid_stats should not hit LBUG ========================================================== 03:49:35 (1788594575) [ 6609.485763] Lustre: Failing over lustre-MDT0000 [ 6609.781669] Lustre: server umount lustre-MDT0000 complete [ 6617.844767] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6709 to 0x280000400:6785) [ 6617.846811] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6918 to 0x240000400:6945) [ 6622.326215] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6631.473886] Lustre: DEBUG MARKER: == replay-single test 87a: write replay ================== 03:50:02 (1788594602) [ 6635.274930] LustreError: 169579:0:(osd_handler.c:720:osd_ro()) lustre-OST0000: *** setting device osd-zfs read-only *** [ 6635.280426] LustreError: 169579:0:(osd_handler.c:720:osd_ro()) Skipped 6 previous similar messages [ 6636.087710] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 6638.628987] Lustre: Failing over lustre-OST0000 [ 6638.667165] Lustre: server umount lustre-OST0000 complete [ 6643.169408] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 6662.689809] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6672.455586] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 6673.667122] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 6681.018601] Lustre: DEBUG MARKER: == replay-single test 87b: write replay with changed data (checksum resend) ========================================================== 03:50:52 (1788594652) [ 6684.533897] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 6687.465886] Lustre: Failing over lustre-OST0000 [ 6687.500325] Lustre: server umount lustre-OST0000 complete [ 6687.713275] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 6691.296911] LustreError: 152983:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: 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. [ 6691.315568] LustreError: 152983:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 13 previous similar messages [ 6706.640627] LustreError: lustre-OST0000: BAD WRITE CHECKSUM: from 12345-192.168.206.5@tcp inode [0x200028c71:0x5:0x0] object 0x240000400:6947 extent [0-1048575]: client csum c7868cd, server csum 19024e9b [ 6710.975196] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6719.316543] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 6720.998917] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 6729.107961] Lustre: DEBUG MARKER: == replay-single test 88: MDS should not assign same objid to different files ========================================================== 03:51:39 (1788594699) [ 6732.720729] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 6736.318990] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 6743.039817] Lustre: Failing over lustre-MDT0000 [ 6743.303167] Lustre: server umount lustre-MDT0000 complete [ 6747.510572] LustreError: 5829:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788594719 with bad export cookie 1447478859007664945 [ 6757.863093] Lustre: Failing over lustre-OST0000 [ 6757.955890] Lustre: server umount lustre-OST0000 complete [ 6792.160472] LustreError: 3308:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8ac186105500 x1875470487202176/t0(0) o250->MGC192.168.206.105@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 [ 6797.433675] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6808.218191] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6824 to 0x280000400:6849) [ 6821.005472] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6948 to 0x240000400:6977) [ 6821.587158] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6835.791886] Lustre: DEBUG MARKER: == replay-single test 89: no disk space leak on late ost connection ========================================================== 03:53:26 (1788594806) [ 6852.087372] Lustre: Failing over lustre-OST0000 [ 6852.187387] Lustre: server umount lustre-OST0000 complete [ 6856.108373] Lustre: Failing over lustre-MDT0000 [ 6856.450547] Lustre: server umount lustre-MDT0000 complete [ 6880.694834] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6884.162597] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6824 to 0x280000400:6881) [ 6894.705847] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6896.724553] Lustre: lustre-OST0000: Denying connection for new client 3695bd3d-f44c-40fa-aa64-1c578512d20f (at 192.168.206.5@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 1:07 [ 6896.743831] Lustre: Skipped 1 previous similar message [ 6917.185267] Lustre: lustre-OST0000: Denying connection for new client 3695bd3d-f44c-40fa-aa64-1c578512d20f (at 192.168.206.5@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 0:47 [ 6917.215294] Lustre: Skipped 3 previous similar messages [ 6953.022745] Lustre: lustre-OST0000: Denying connection for new client 3695bd3d-f44c-40fa-aa64-1c578512d20f (at 192.168.206.5@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 0:11 [ 6953.039852] Lustre: Skipped 6 previous similar messages [ 6964.500188] Lustre: lustre-OST0000: recovery is timed out, evict stale exports [ 6964.507800] Lustre: 177480:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-OST0000: disconnect stale client 888eefac-9178-4a0b-9bec-9ea9030fc457@ [ 6964.520372] Lustre: lustre-OST0000: disconnecting 1 stale clients [ 6964.570163] Lustre: lustre-OST0000: Recovery over after 1:10, of 2 clients 1 recovered and 1 was evicted. [ 6964.571580] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 6964.584091] Lustre: Skipped 8 previous similar messages [ 6964.589632] Lustre: Skipped 13 previous similar messages [ 6964.590384] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6988 to 0x240000400:7009) [ 6970.714304] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 65 sec [ 6984.500418] Lustre: DEBUG MARKER: free_before: 7520256 free_after: 7520256 [ 6990.678951] Lustre: DEBUG MARKER: == replay-single test 90: lfs find identifies the missing striped file segments ========================================================== 03:56:01 (1788594961) [ 6995.351331] Lustre: Failing over lustre-OST0001 [ 6995.538396] Lustre: server umount lustre-OST0001 complete [ 6996.961444] Lustre: lustre-OST0001-osc-MDT0000: Connection to lustre-OST0001 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 6996.968776] Lustre: Skipped 12 previous similar messages [ 6996.975181] LustreError: 36628:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0001: 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. [ 6996.993534] LustreError: 36628:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 35 previous similar messages [ 7014.958705] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 7014.962611] Lustre: Skipped 11 previous similar messages [ 7014.968399] Lustre: lustre-OST0001: in recovery but waiting for the first client to connect [ 7014.977610] Lustre: Skipped 9 previous similar messages [ 7016.415253] Lustre: lustre-OST0001: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 7016.424405] Lustre: Skipped 8 previous similar messages [ 7021.379319] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7031.260657] Lustre: DEBUG MARKER: == replay-single test 93a: replay + reconnect ============ 03:56:41 (1788595001) [ 7034.700688] Lustre: Failing over lustre-OST0000 [ 7034.797777] Lustre: server umount lustre-OST0000 complete [ 7053.943451] LustreError: 180574:0:(ldlm_lib.c:2930:target_recovery_thread()) cfs_fail_timeout id 715 sleeping for 40000ms [ 7053.952996] LustreError: 180574:0:(ldlm_lib.c:2930:target_recovery_thread()) Skipped 76 previous similar messages [ 7058.507131] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7059.940877] Lustre: *** cfs_fail_loc=715, val=40*** [ 7069.154107] Lustre: 3308:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788595025/real 1788595025] req@ffff8ac2baf67480 x1875470487273600/t0(0) o400->lustre-OST0000-osc-MDT0000@0@lo:28/4 lens 224/224 e 0 to 1 dl 1788595041 ref 1 fl Rpc:XQr/2c0/ffffffff rc 0/-1 job:'ldlm_lock_repla.0' uid:0 gid:0 projid:4294967295 [ 7069.186761] Lustre: 3308:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 31 previous similar messages [ 7069.193629] Lustre: lustre-OST0000: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnected, waiting for 2 clients in recovery for 1:25 [ 7070.271080] Lustre: lustre-OST0000: Client 3695bd3d-f44c-40fa-aa64-1c578512d20f (at 192.168.206.5@tcp) reconnected, waiting for 2 clients in recovery for 1:24 [ 7075.298432] Lustre: *** cfs_fail_loc=715, val=40*** [ 7075.305100] Lustre: Skipped 1 previous similar message [ 7076.320182] Lustre: *** cfs_fail_loc=715, val=40*** [ 7085.538862] Lustre: lustre-OST0000: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnected, waiting for 2 clients in recovery for 1:08 [ 7091.681114] Lustre: *** cfs_fail_loc=715, val=40*** [ 7094.033943] LustreError: 180574:0:(ldlm_lib.c:2930:target_recovery_thread()) cfs_fail_timeout id 715 awake [ 7094.047285] LustreError: 180574:0:(ldlm_lib.c:2930:target_recovery_thread()) Skipped 76 previous similar messages [ 7099.459932] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 7100.749669] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 7107.940562] Lustre: DEBUG MARKER: == replay-single test 93b: replay + reconnect on mds ===== 03:57:58 (1788595078) [ 7111.943439] Lustre: Failing over lustre-MDT0000 [ 7112.314237] Lustre: server umount lustre-MDT0000 complete [ 7129.666404] LustreError: MGC192.168.206.105@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 7129.670442] LustreError: Skipped 5 previous similar messages [ 7132.271071] LustreError: 182171:0:(ldlm_lib.c:2930:target_recovery_thread()) cfs_fail_timeout id 715 sleeping for 80000ms [ 7134.444381] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7138.273018] Lustre: *** cfs_fail_loc=715, val=80*** [ 7138.280347] Lustre: Skipped 1 previous similar message [ 7148.604182] Lustre: lustre-MDT0000: Client 3695bd3d-f44c-40fa-aa64-1c578512d20f (at 192.168.206.5@tcp) reconnected, waiting for 1 clients in recovery for 0:53 [ 7148.620832] Lustre: Skipped 1 previous similar message [ 7154.656218] Lustre: *** cfs_fail_loc=715, val=80*** [ 7163.965158] Lustre: lustre-MDT0000: Client 3695bd3d-f44c-40fa-aa64-1c578512d20f (at 192.168.206.5@tcp) reconnected, waiting for 1 clients in recovery for 0:38 [ 7180.353899] Lustre: lustre-MDT0000: Client 3695bd3d-f44c-40fa-aa64-1c578512d20f (at 192.168.206.5@tcp) reconnected, waiting for 1 clients in recovery for 0:22 [ 7186.401792] Lustre: *** cfs_fail_loc=715, val=80*** [ 7186.408115] Lustre: Skipped 1 previous similar message [ 7196.739727] Lustre: lustre-MDT0000: Client 3695bd3d-f44c-40fa-aa64-1c578512d20f (at 192.168.206.5@tcp) reconnected, waiting for 1 clients in recovery for 0:05 [ 7212.100146] Lustre: lustre-MDT0000: Recovery already passed deadline 0:09. If you do not want to wait more, you may force taget eviction via 'lctl --device lustre-MDT0000 abort_recovery. [ 7212.353282] LustreError: 182171:0:(ldlm_lib.c:2930:target_recovery_thread()) cfs_fail_timeout id 715 awake [ 7212.468549] Lustre: 182171:0:(ldlm_lib.c:2976:target_recovery_thread()) too long recovery - read logs [ 7212.488440] LustreError: dumping log to /tmp/lustre-log.1788595184.182171 [ 7212.734260] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6894 to 0x280000400:6913) [ 7212.735540] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:7023 to 0x240000400:7041) [ 7218.542183] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 7220.005671] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7228.611880] Lustre: DEBUG MARKER: == replay-single test complete, duration 7021 sec ======== 03:59:59 (1788595199) [ 7230.091934] Lustre: DEBUG MARKER: === replay-single: start cleanup 04:00:00 (1788595200) === [ 7239.333228] Lustre: DEBUG MARKER: === replay-single: finish cleanup 04:00:10 (1788595210) === [ 7241.184064] Lustre: Failing over lustre-MDT0000 [ 7241.595628] Lustre: server umount lustre-MDT0000 complete [ 7268.259911] LustreError: 3308:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8ac2a9133100 x1875470487363968/t0(0) o250->MGC192.168.206.105@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 [ 7273.696330] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:7023 to 0x240000400:7073) [ 7273.702917] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6894 to 0x280000400:6945) [ 7274.147318] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7284.019079] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 7285.358714] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7295.970677] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 7295.989108] Lustre: Skipped 1 previous similar message [ 7297.905345] Lustre: server umount lustre-MDT0000 complete [ 7301.309370] LustreError: 36618:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788595273 with bad export cookie 1447478859007696606 [ 7301.332774] LustreError: 36618:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 7301.423020] Lustre: server umount lustre-OST0000 complete [ 7304.652757] Lustre: server umount lustre-OST0001 complete [ 7314.991280] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing unload_modules_local [ 7317.376302] Key type lgssc unregistered [ 7317.659877] LNet: 185458:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 7317.667248] LNetError: 185458:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 7317.684986] LNet: Removed LNI 192.168.206.105@tcp [ 7318.428271] Key type .llcrypt unregistered [ 7318.431806] Key type ._llcrypt unregistered