[ 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 498361754 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.001011] APIC: Switch to symmetric I/O mode setup [ 0.003313] x2apic enabled [ 0.004010] Switched APIC routing to physical x2apic. [ 0.005016] kvm-guest: setup PV IPIs [ 0.008302] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.009000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.009020] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.010011] pid_max: default: 32768 minimum: 301 [ 0.011138] LSM: Security Framework initializing [ 0.012058] Yama: becoming mindful. [ 0.013049] SELinux: Initializing. [ 0.014078] *** VALIDATE selinux *** [ 0.023486] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.027844] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.028155] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.029111] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.030114] *** VALIDATE tmpfs *** [ 0.032051] *** VALIDATE proc *** [ 0.033223] *** VALIDATE cgroup *** [ 0.034008] *** VALIDATE cgroup2 *** [ 0.035254] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.037080] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.038009] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.039027] Spectre V2 : User space: Vulnerable [ 0.040009] Speculative Store Bypass: Vulnerable [ 0.043321] debug: unmapping init [mem 0xffffffff8b659000-0xffffffff8b660fff] [ 0.045186] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.046713] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.047021] ... version: 2 [ 0.048012] ... bit width: 48 [ 0.049011] ... generic registers: 4 [ 0.050015] ... value mask: 0000ffffffffffff [ 0.051016] ... max period: 00007fffffffffff [ 0.052015] ... fixed-purpose events: 3 [ 0.053010] ... event mask: 000000070000000f [ 0.054282] rcu: Hierarchical SRCU implementation. [ 0.056454] smp: Bringing up secondary CPUs ... [ 0.057539] x86: Booting SMP configuration: [ 0.058028] .... node #0, CPUs: #1 #2 #3 [ 0.061477] smp: Brought up 1 node, 4 CPUs [ 0.063014] smpboot: Max logical packages: 1 [ 0.064018] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.150990] node 0 deferred pages initialised in 84ms [ 0.155013] devtmpfs: initialized [ 0.156276] x86/mm: Memory block size: 128MB [ 0.158561] gcov: version magic: 0x41383552 [ 0.160143] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.161079] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.162239] pinctrl core: initialized pinctrl subsystem [ 0.163205] [ 0.163841] ************************************************************* [ 0.164015] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.165019] ** ** [ 0.166013] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.167012] ** ** [ 0.168014] ** This means that this kernel is built to expose internal ** [ 0.169013] ** IOMMU data structures, which may compromise security on ** [ 0.170012] ** your system. ** [ 0.171015] ** ** [ 0.172013] ** If you see this message and you are not debugging the ** [ 0.173012] ** kernel, report this immediately to your vendor! ** [ 0.174015] ** ** [ 0.175015] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.176012] ************************************************************* [ 0.177698] NET: Registered protocol family 16 [ 0.178448] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.179064] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.180061] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.181444] cpuidle: using governor menu [ 0.183687] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.186454] PCI: Using configuration type 1 for base access [ 0.188135] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.198078] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.199025] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.201137] cryptd: max_cpu_qlen set to 1000 [ 0.203298] ACPI: Added _OSI(Module Device) [ 0.204013] ACPI: Added _OSI(Processor Device) [ 0.205015] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.206013] ACPI: Added _OSI(Processor Aggregator Device) [ 0.210030] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.214544] ACPI: Interpreter enabled [ 0.216064] ACPI: PM: (supports S0 S3 S4 S5) [ 0.218012] ACPI: Using IOAPIC for interrupt routing [ 0.220117] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.225421] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.235739] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.238043] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.240017] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.244133] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.250709] acpiphp: Slot [2] registered [ 0.252388] acpiphp: Slot [5] registered [ 0.254176] acpiphp: Slot [6] registered [ 0.256230] acpiphp: Slot [7] registered [ 0.257121] acpiphp: Slot [8] registered [ 0.259128] acpiphp: Slot [9] registered [ 0.261189] acpiphp: Slot [10] registered [ 0.263202] acpiphp: Slot [3] registered [ 0.265112] acpiphp: Slot [4] registered [ 0.266120] acpiphp: Slot [11] registered [ 0.268120] acpiphp: Slot [12] registered [ 0.269108] acpiphp: Slot [13] registered [ 0.270101] acpiphp: Slot [14] registered [ 0.272101] acpiphp: Slot [15] registered [ 0.274127] acpiphp: Slot [16] registered [ 0.275074] acpiphp: Slot [17] registered [ 0.277108] acpiphp: Slot [18] registered [ 0.278103] acpiphp: Slot [19] registered [ 0.280101] acpiphp: Slot [20] registered [ 0.281120] acpiphp: Slot [21] registered [ 0.283137] acpiphp: Slot [22] registered [ 0.285113] acpiphp: Slot [23] registered [ 0.287214] acpiphp: Slot [24] registered [ 0.289103] acpiphp: Slot [25] registered [ 0.290117] acpiphp: Slot [26] registered [ 0.292127] acpiphp: Slot [27] registered [ 0.294106] acpiphp: Slot [28] registered [ 0.295121] acpiphp: Slot [29] registered [ 0.297132] acpiphp: Slot [30] registered [ 0.299109] acpiphp: Slot [31] registered [ 0.301066] PCI host bridge to bus 0000:00 [ 0.302034] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.305037] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.308024] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.310037] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.313030] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.315019] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.317272] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.320939] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.324247] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.333927] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.339548] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.342021] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.345020] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.347017] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.350567] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.353961] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.357047] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.362838] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.368015] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.383016] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.389015] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.395533] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.404014] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.413017] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.440015] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.455437] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.466018] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.476016] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.507019] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.521744] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.533015] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.543017] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.572019] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.586114] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.594013] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.607014] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.631015] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.640500] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.648013] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.655952] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.677023] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 0.688815] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.697016] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.704015] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.733019] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 0.743504] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.746525] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.750451] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.752465] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.755303] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.761105] iommu: Default domain type: Passthrough [ 0.763017] SCSI subsystem initialized [ 0.764269] ACPI: bus type USB registered [ 0.766150] usbcore: registered new interface driver usbfs [ 0.768122] usbcore: registered new interface driver hub [ 0.771171] usbcore: registered new device driver usb [ 0.773197] pps_core: LinuxPPS API ver. 1 registered [ 0.774016] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.778111] PTP clock support registered [ 0.780163] EDAC MC: Ver: 3.0.0 [ 0.783057] PCI: Using ACPI for IRQ routing [ 0.785114] NetLabel: Initializing [ 0.786011] NetLabel: domain hash size = 128 [ 0.788015] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.790077] NetLabel: unlabeled traffic allowed by default [ 0.793145] vgaarb: loaded [ 0.794257] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.796010] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.801359] clocksource: Switched to clocksource kvm-clock [ 0.914550] VFS: Disk quotas dquot_6.6.0 [ 0.916250] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.918439] *** VALIDATE ramfs *** [ 0.919874] *** VALIDATE hugetlbfs *** [ 0.921616] pnp: PnP ACPI init [ 0.924127] pnp: PnP ACPI: found 6 devices [ 0.944059] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.947530] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.949984] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.952385] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.955050] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.957735] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.960974] NET: Registered protocol family 2 [ 0.963525] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.968490] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.972361] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.978747] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.982603] TCP: Hash tables configured (established 65536 bind 65536) [ 0.986229] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.989683] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.992756] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.995840] NET: Registered protocol family 1 [ 0.998614] RPC: Registered named UNIX socket transport module. [ 1.000645] RPC: Registered udp transport module. [ 1.002504] RPC: Registered tcp transport module. [ 1.004384] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 1.006471] NET: Registered protocol family 44 [ 1.008449] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 1.010904] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 1.013460] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 1.015849] PCI: CLS 0 bytes, default 64 [ 1.018258] Unpacking initramfs... [ 4.525578] debug: unmapping init [mem 0xffff89debcc54000-0xffff89debffbffff] [ 4.535930] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 4.540161] software IO TLB: mapped [mem 0x00000000a2200000-0x00000000a6200000] (64MB) [ 4.547397] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 6.983969] Initialise system trusted keyrings [ 7.003101] Key type blacklist registered [ 7.007929] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 7.057054] zbud: loaded [ 7.072338] *** VALIDATE nfs *** [ 7.073774] *** VALIDATE nfs4 *** [ 7.077682] pstore: using deflate compression [ 7.136817] Platform Keyring initialized [ 7.547558] NET: Registered protocol family 38 [ 7.562337] Key type asymmetric registered [ 7.566931] Asymmetric key parser 'x509' registered [ 7.569892] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 7.578547] io scheduler mq-deadline registered [ 7.584626] io scheduler kyber registered [ 7.589592] io scheduler bfq registered [ 7.600424] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 7.606096] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 7.612340] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 7.623441] ACPI: Power Button [PWRF] [ 7.650675] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 7.672941] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 7.720878] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 7.741930] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 7.789046] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 7.841030] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 7.876458] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 7.888941] Non-volatile memory driver v1.3 [ 7.893183] Linux agpgart interface v0.103 [ 7.973136] virtio_blk virtio1: [vda] 145904 512-byte logical blocks (74.7 MB/71.2 MiB) [ 7.981908] vda: detected capacity change from 0 to 74702848 [ 8.021955] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 8.028166] vdb: detected capacity change from 0 to 1073741824 [ 8.069638] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 8.088277] vdc: detected capacity change from 0 to 2621440000 [ 8.138088] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 8.148119] vdd: detected capacity change from 0 to 2621440000 [ 8.190701] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 8.206265] vde: detected capacity change from 0 to 4294967296 [ 8.264447] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 8.273456] vdf: detected capacity change from 0 to 4294967296 [ 8.292412] libphy: Fixed MDIO Bus: probed [ 8.338268] usbcore: registered new interface driver usbserial_generic [ 8.347364] usbserial: USB Serial support registered for generic [ 8.354328] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 8.379497] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 8.382806] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 8.390991] mousedev: PS/2 mouse device common for all mice [ 8.405603] rtc_cmos 00:05: RTC can wake from S4 [ 8.411832] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 8.426266] rtc_cmos 00:05: registered as rtc0 [ 8.442243] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 8.442861] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 8.442901] intel_pstate: CPU model not supported [ 8.461329] hid: raw HID events driver (C) Jiri Kosina [ 8.469373] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 8.479434] usbcore: registered new interface driver usbhid [ 8.509277] usbhid: USB HID core driver [ 8.511226] drop_monitor: Initializing network drop monitor service [ 8.517823] Initializing XFRM netlink socket [ 8.527248] NET: Registered protocol family 10 [ 8.534074] Segment Routing with IPv6 [ 8.535385] NET: Registered protocol family 17 [ 8.538843] mpls_gso: MPLS GSO support [ 8.557886] RAS: Correctable Errors collector initialized. [ 8.563387] AVX version of gcm_enc/dec engaged. [ 8.570389] AES CTR mode by8 optimization enabled [ 8.797691] sched_clock: Marking stable (8797667183, 0)->(9766358011, -968690828) [ 8.803529] registered taskstats version 1 [ 8.807474] Loading compiled-in X.509 certificates [ 8.811355] zswap: loaded using pool lzo/zbud [ 8.852700] Key type big_key registered [ 8.872703] Key type encrypted registered [ 8.875753] ima: No TPM chip found, activating TPM-bypass! [ 8.878580] ima: Allocated hash algorithm: sha1 [ 8.881245] ima: No architecture policies found [ 8.884320] evm: Initialising EVM extended attributes: [ 8.894698] evm: security.selinux [ 8.896713] evm: security.ima [ 8.898755] evm: security.capability [ 8.900328] evm: HMAC attrs: 0x1 [ 8.903582] rtc_cmos 00:05: setting system clock to 2026-08-19 05:38:35 UTC (1787117915) [ 8.918158] debug: unmapping init [mem 0xffffffff8c603000-0xffffffff8c7fffff] [ 8.932091] debug: unmapping init [mem 0xffffffff8b382000-0xffffffff8b658fff] [ 8.961231] Write protecting the kernel read-only data: 28672k [ 8.970651] debug: unmapping init [mem 0xffffffff89a03000-0xffffffff89bfffff] [ 8.988241] debug: unmapping init [mem 0xffffffff8a314000-0xffffffff8a3fffff] [ 9.061812] 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) [ 9.083420] systemd[1]: Detected virtualization kvm. [ 9.085217] systemd[1]: Detected architecture x86-64. [ 9.088910] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 9.193760] systemd[1]: No hostname configured. [ 9.198768] systemd[1]: Set hostname to . [ 9.202848] random: systemd: uninitialized urandom read (16 bytes read) [ 9.207263] systemd[1]: Initializing machine ID from random generator. [ 9.408248] random: ln: uninitialized urandom read (6 bytes read) [ 9.651480] random: systemd: uninitialized urandom read (16 bytes read) [ 9.662895] systemd[1]: Reached target Swap. [ OK ] Reached target Swap. [ 9.672262] systemd[1]: Listening on Journal Socket. [ OK ] Listening on Journal Socket. [ 9.682532] systemd[1]: Listening on udev Control Socket. [ OK ] Listening on udev Control Socket. [ OK ] Reached target Initrd Root Device. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Timers. [ OK ] Reached target Local File Systems. Starting Create Volatile Files and Directories... Starting Setup Virtual Console... [ OK ] Reached target Slices. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Listening on Journal Socket (/dev/log). [ OK ] Listening on udev Kernel Socket. [ OK ] Reached target Sockets. Starting Apply Kernel Variables... [ OK ] Reached target Paths. [ OK ] Started Memstrack Anylazing Service. Starting Journal Service... [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Setup Virtual Console. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Apply Kernel Variables. 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... [ 11.441861] device-mapper: uevent: version 1.0.3 [ 11.445297] 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 ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ 13.259275] random: fast init done [ 13.284139] virtio_net virtio0 ens2: renamed from eth0 [ 13.445623] scsi host0: ata_piix [ 13.528488] scsi host1: ata_piix [ 13.543950] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 13.546154] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 18.417974] random: crng init done [ 18.426134] random: 7 urandom warning(s) missed due to ratelimiting [ 20.863378] dracut-initqueue[586]: RTNETLINK answers: File exists Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. Mounting /sysroot... [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. [ 22.643127] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Remote File Systems. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped target Timers. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target System Initialization. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped target Swap. Stopping udev Kernel Device Manager... [ OK ] Stopped target Sockets. [ OK ] Stopped target Paths. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped target Slices. [ OK ] Stopped udev Kernel Device Manager. [ 25.333105] hrtimer: interrupt took 3094838 ns [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Closed udev Kernel Socket. [ OK ] Closed udev Control Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 26.597335] printk: systemd: 26 output lines suppressed due to ratelimiting [ 27.608034] SELinux: Disabled at runtime. [ 27.735339] 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) [ 27.755161] systemd[1]: Detected virtualization kvm. [ 27.760066] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 29.762691] systemd[1]: initrd-switch-root.service: Succeeded. [ 29.768357] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 29.787530] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 29.801708] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 29.809344] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 29.838236] systemd[1]: Starting Journal Service... Starting Journal Service... [ 29.866931] systemd[1]: Reached target rpc_pipefs.target. [ 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. [ OK ] Created slice User and Session Slice. [ OK ] Listening on Process Core Dump Socket. Starting Apply Kernel Variables... [ OK ] Started Forward Password Requests to Wall Directory Watch. Mounting POSIX Message Queue File System... [ OK ] Listening on udev Kernel Socket. [ OK ] Created slice system-sshd\x2dkeygen.slice. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Reached target RPC Port Mapper. Starting Remount Root and Kernel File Systems... Starting udev Coldplug all Devices... [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd File Systems. [ OK ] Stopped target Initrd Root File System. [ OK ] Reached target Slices. [ OK ] Reached target Local Encrypted Volumes. Mounting Huge Pages File System... [ OK ] Reached target Paths. Mounting Kernel Debug File System... [ OK ] Created slice system-getty.slice. [ OK ] Created slice system-serial\x2dgetty.slice. Activating swap /dev/disk/by-label/SWAP... [ OK ] Started Journal Service. [ OK ] Started Apply Kernel Variables. [ OK ] Mounted POSIX Message Queue File System. [ 30.812419] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS [ OK ] Started Create list of required sta…vice nodes for the current kernel. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Mounted Huge Pages File System. [ OK ] Mounted Kernel Debug File System. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Reached target Swap. Starting Configure read-only root support... Starting Create Static Device Nodes in /dev... Starting Flush Journal to Persistent Storage... [ OK ] Started udev Coldplug all Devices. [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. Starting udev Kernel Device Manager... [ OK ] Reached target Local File Systems (Pre). Mounting /home/green/git/lustre-release... Mounting /mnt... [ OK ] Mounted /mnt. [ 32.093776] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 33.456526] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 33.487222] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 34.252629] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 34.348709] EDAC sbridge: Ver: 1.1.2 [* ] A start job is running for Configur…-only root support (8s / no limit) [** ] A start job is running for Configur…-only root support (8s / no limit) [*** ] A start job is running for Configur…-only root support (9s / no limit)[ 39.439814] Key type dns_resolver registered [ *** ] A start job is running for Configur…only root support (10s / no limit) [ *** ] A start job is running for Configur…only root support (10s / no limit)[ 40.561366] NFS: Registering the id_resolver key type [ 40.572162] Key type id_resolver registered [ 40.573858] Key type id_legacy registered [ ***] A start job is running for Configur…only root support (11s / no limit) [ **] A start job is running for Configur…only root support (11s / no limit) [ OK ] Started Configure read-only root support. Starting Load/Save Random Seed... [ OK ] Reached target Local File Systems. Starting Mark the need to relabel after reboot... Starting Rebuild Dynamic Linker Cache... Starting Create Volatile Files and Directories... [ OK ] Started Load/Save Random Seed. [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Create Volatile Files and Directories. Starting RPC Bind... Starting Update UTMP about System Boot/Shutdown... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Started dnf makecache --timer. [ OK ] Reached target Timers. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ 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 ] Reached target sshd-keygen.target. [ OK ] Started D-Bus System Message Bus. Starting Network Manager... [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Login Service. [ OK ] Started Network Manager. Starting Network Manager Wait Online... [ OK ] Reached target Network. Starting OpenSSH server daemon... Starting GSSAPI Proxy Daemon... Starting Dynamic System Tuning Daemon... Starting Hostname Service... [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... [ OK ] Started OpenSSH server daemon. [ OK ] Started Permit User Sessions. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Command Scheduler. [ OK ] Started Serial Getty on ttyS1. [ OK ] Started Getty on tty1. [ OK ] Reached target Login Prompts. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting Crash recovery kernel arming... Starting Notify NFS peers of a restart... Starting System Logging Service... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg312-server login: [ 81.331243] spl: loading out-of-tree module taints kernel. [ 89.373518] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 101.355886] Key type ._llcrypt registered [ 101.363969] Key type .llcrypt registered [ 101.493875] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_hostid [ 121.565630] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing load_modules_local [ 123.084729] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 123.114798] alg: No test for adler32 (adler32-zlib) [ 125.045537] Lustre: Lustre: Build Version: 2.17.57_1_g9da61ce [ 126.213234] LNet: Added LNI 192.168.203.112@tcp [8/256/0/180] [ 127.992226] Key type lgssc registered [ 129.945900] Lustre: Echo OBD driver; http://www.lustre.org/ [ 141.363934] vdc: vdc1 vdc9 [ 152.048504] vde: vde1 vde9 [ 164.019173] vdf: vdf1 vdf9 [ 190.441265] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing load_modules_local [ 202.365665] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 203.664660] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 204.128300] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 204.302386] Lustre: lustre-MDT0000: new disk, initializing [ 204.761456] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 204.854051] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 210.494768] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 215.891349] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 223.432375] Lustre: lustre-OST0000: new disk, initializing [ 223.438247] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 223.443662] Lustre: Skipped 1 previous similar message [ 223.684827] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 224.998463] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:0:ost [ 225.012265] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:0:ost] [ 225.211489] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x240000400 [ 231.162670] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 243.298573] Lustre: lustre-OST0001: new disk, initializing [ 243.302648] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 243.382199] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 251.134777] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 253.583176] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:1:ost [ 253.590095] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:1:ost] [ 253.681119] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x280000400 [ 264.267264] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 273.839615] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 281.503291] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing check_logdir /tmp/testlogs/ [ 288.358558] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing yml_node [ 293.936065] Lustre: DEBUG MARKER: Client: 2.17.57.1 [ 297.331434] Lustre: DEBUG MARKER: MDS: 2.17.57.1 [ 300.832505] Lustre: DEBUG MARKER: OSS: 2.17.57.1 [ 302.791375] Lustre: DEBUG MARKER: -----============= acceptance-small: replay-single ============----- Wed Aug 19 01:43:27 EDT 2026 [ 322.583883] Lustre: DEBUG MARKER: excepting tests: 59 36 [ 324.515246] Lustre: DEBUG MARKER: === replay-single: start setup 01:43:49 (1787118229) === [ 330.688730] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing check_config_client /mnt/lustre [ 348.667337] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 352.245359] Lustre: 11292:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 356.545835] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 360.907784] Lustre: DEBUG MARKER: === replay-single: finish setup 01:44:25 (1787118265) === [ 362.673563] Lustre: DEBUG MARKER: == replay-single test 0a: empty replay =================== 01:44:27 (1787118267) [ 365.694253] LustreError: 11791:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 366.514121] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 368.424164] Lustre: Failing over lustre-MDT0000 [ 368.698416] Lustre: server umount lustre-MDT0000 complete [ 387.555407] Lustre: 3309:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787118277/real 1787118277] req@ffff89df09037480 x1873929077579648/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787118293 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 387.558763] LustreError: MGC192.168.203.112@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 387.597795] Lustre: 3309:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 387.626671] 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 [ 391.712171] Lustre: 3311:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787118282/real 1787118282] req@ffff89df09034a80 x1873929077580032/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787118298 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 391.750182] Lustre: 3311:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 397.809597] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x9b881f90d52a836d [ 397.816491] Lustre: MGC192.168.203.112@tcp: Connection restored to 0@lo (at 0@lo) [ 398.316771] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 398.881480] Lustre: 3311:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787118288/real 1787118288] req@ffff89df09037b80 x1873929077580416/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787118304 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 402.639508] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 403.297727] Lustre: 3309:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787118293/real 1787118293] req@ffff89df414d2680 x1873929077580800/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787118309 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 403.324301] Lustre: 3309:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 411.621327] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 411.707589] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 412.522944] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 418.646726] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 420.419347] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 430.056746] Lustre: DEBUG MARKER: == replay-single test 0b: ensure object created after recover exists. (3284) ========================================================== 01:45:35 (1787118335) [ 432.110632] Lustre: Failing over lustre-OST0000 [ 432.216112] Lustre: server umount lustre-OST0000 complete [ 432.614925] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 432.624353] 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 [ 432.648433] Lustre: Skipped 1 previous similar message [ 438.241199] LustreError: 6684:0:(ldlm_lib.c:1192: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. [ 438.258775] LustreError: 6684:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 4 previous similar messages [ 442.357733] LustreError: 6683:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.203.12@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 443.362673] LustreError: 6685:0:(ldlm_lib.c:1192: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. [ 447.450713] LustreError: 12811:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.203.12@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 452.656851] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 454.014428] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 454.310526] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 454.317658] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 454.336073] Lustre: Skipped 1 previous similar message [ 461.176893] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 473.815980] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 476.644890] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 488.027446] Lustre: DEBUG MARKER: == replay-single test 0c: check replay-barrier =========== 01:46:32 (1787118392) [ 491.362651] LustreError: 14839:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 492.419977] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 495.124077] Lustre: Failing over lustre-MDT0000 [ 495.518299] Lustre: server umount lustre-MDT0000 complete [ 515.040176] Lustre: 3308:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787118405/real 1787118405] req@ffff89df3fa6dc00 x1873929077613824/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787118421 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 515.043035] 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 [ 515.075696] Lustre: 3308:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 515.106786] Lustre: Skipped 1 previous similar message [ 515.120725] LustreError: MGC192.168.203.112@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 525.216287] Lustre: 3311:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787118415/real 1787118415] req@ffff89df030d8e00 x1873929077614592/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787118431 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 525.250363] Lustre: 3311:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 525.976057] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 532.112320] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 534.764147] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 534.774425] Lustre: lustre-MDT0000: Denying connection for new client a56b322e-7318-4d27-aa67-d5480f6773fe (at 192.168.203.12@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:59 [ 540.120461] Lustre: lustre-MDT0000: Denying connection for new client a56b322e-7318-4d27-aa67-d5480f6773fe (at 192.168.203.12@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:54 [ 540.133546] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 545.241625] Lustre: lustre-MDT0000: Denying connection for new client a56b322e-7318-4d27-aa67-d5480f6773fe (at 192.168.203.12@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:49 [ 550.359442] Lustre: lustre-MDT0000: Denying connection for new client a56b322e-7318-4d27-aa67-d5480f6773fe (at 192.168.203.12@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:44 [ 555.482899] Lustre: lustre-MDT0000: Denying connection for new client a56b322e-7318-4d27-aa67-d5480f6773fe (at 192.168.203.12@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:39 [ 565.720424] Lustre: lustre-MDT0000: Denying connection for new client a56b322e-7318-4d27-aa67-d5480f6773fe (at 192.168.203.12@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:28 [ 565.746994] Lustre: Skipped 1 previous similar message [ 586.199430] Lustre: lustre-MDT0000: Denying connection for new client a56b322e-7318-4d27-aa67-d5480f6773fe (at 192.168.203.12@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:08 [ 586.218113] Lustre: Skipped 3 previous similar messages [ 594.501047] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 594.503976] Lustre: 15493:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 84cfd422-bc52-44fa-bebf-cc38f4b4988a@ [ 594.536345] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 594.592237] Lustre: lustre-MDT0000: Recovery over after 1:00, of 1 clients 0 recovered and 1 was evicted. [ 594.644630] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:44 to 0x280000400:65) [ 594.649538] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:44 to 0x240000400:65) [ 606.974562] Lustre: DEBUG MARKER: == replay-single test 0d: expired recovery with no clients ========================================================== 01:48:31 (1787118511) [ 610.368793] LustreError: 16236:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 611.335685] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 614.141218] Lustre: Failing over lustre-MDT0000 [ 614.553896] Lustre: server umount lustre-MDT0000 complete [ 633.312156] Lustre: 3308:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787118523/real 1787118523] req@ffff89df3f933800 x1873929077640320/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787118539 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 633.315724] 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 [ 633.342774] Lustre: 3308:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 4 previous similar messages [ 633.369379] Lustre: Skipped 1 previous similar message [ 633.373513] LustreError: MGC192.168.203.112@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 643.211760] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 643.316579] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 648.244210] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 651.283712] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 651.292722] Lustre: lustre-MDT0000: Denying connection for new client 51083077-1bb3-4059-b062-e6ad68ec3b36 (at 192.168.203.12@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 1:00 [ 651.322177] Lustre: Skipped 1 previous similar message [ 658.345899] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 658.353107] Lustre: Skipped 1 previous similar message [ 711.500458] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 711.509584] Lustre: 16870:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client a56b322e-7318-4d27-aa67-d5480f6773fe@ [ 711.525398] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 711.597263] Lustre: lustre-MDT0000: Recovery over after 1:00, of 1 clients 0 recovered and 1 was evicted. [ 711.698546] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:44 to 0x280000400:97) [ 711.702532] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:44 to 0x240000400:97) [ 725.591571] Lustre: DEBUG MARKER: == replay-single test 1: simple create =================== 01:50:30 (1787118630) [ 729.377412] LustreError: 17611:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 730.438154] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 732.701452] Lustre: Failing over lustre-MDT0000 [ 733.214824] Lustre: server umount lustre-MDT0000 complete [ 750.433195] Lustre: 3310:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787118641/real 1787118641] req@ffff89df030d8000 x1873929077665664/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787118657 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 750.483270] Lustre: 3310:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 7 previous similar messages [ 750.496106] 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 [ 750.565785] LustreError: MGC192.168.203.112@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 760.818250] LustreError: 3307:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff89df06dd6a00 x1873929077667072/t0(0) o250->MGC192.168.203.112@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 [ 761.307404] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 761.402270] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 766.316321] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 774.618435] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 774.771668] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 774.835453] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:44 to 0x240000400:129) [ 774.850238] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:44 to 0x280000400:129) [ 775.525085] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 775.531768] Lustre: Skipped 1 previous similar message [ 781.803584] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 783.563381] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 792.888492] Lustre: DEBUG MARKER: == replay-single test 2a: touch ========================== 01:51:37 (1787118697) [ 796.305716] LustreError: 19205:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 797.365692] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 799.538554] Lustre: Failing over lustre-MDT0000 [ 800.017298] Lustre: server umount lustre-MDT0000 complete [ 816.480144] Lustre: 3309:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787118707/real 1787118707] req@ffff89df27aea300 x1873929077681280/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787118723 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 816.497097] Lustre: 3309:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 6 previous similar messages [ 816.508224] 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 [ 816.519734] Lustre: Skipped 1 previous similar message [ 817.578147] LustreError: MGC192.168.203.112@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 827.810323] LustreError: 3307:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff89df27ae8700 x1873929077683200/t0(0) o250->MGC192.168.203.112@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 [ 828.440177] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 828.504313] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 834.104843] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 841.178248] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 841.448082] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 841.531657] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:131 to 0x240000400:161) [ 841.545936] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:44 to 0x280000400:161) [ 841.584905] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 841.605020] Lustre: Skipped 1 previous similar message [ 847.758140] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 849.568704] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 858.330823] Lustre: DEBUG MARKER: == replay-single test 2b: touch ========================== 01:52:43 (1787118763) [ 861.628673] LustreError: 20797:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 862.739715] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 864.978050] Lustre: Failing over lustre-MDT0000 [ 865.485390] Lustre: server umount lustre-MDT0000 complete [ 882.658398] 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 [ 882.658656] LustreError: MGC192.168.203.112@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 882.688049] Lustre: Skipped 2 previous similar messages [ 893.616077] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 898.572992] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 907.695697] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 907.711458] Lustre: Skipped 1 previous similar message [ 907.737955] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 908.000679] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 908.087214] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:44 to 0x280000400:193) [ 908.090349] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:163 to 0x240000400:193) [ 914.679423] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 916.508890] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 926.986763] Lustre: DEBUG MARKER: == replay-single test 2c: setstripe replay =============== 01:53:51 (1787118831) [ 932.060072] LustreError: 22399:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 933.483783] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 935.882961] Lustre: Failing over lustre-MDT0000 [ 936.205495] Lustre: server umount lustre-MDT0000 complete [ 954.786047] Lustre: 3309:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787118845/real 1787118845] req@ffff89df2721dc00 x1873929077715456/t0(0) o400->MGC192.168.203.112@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1787118861 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 954.831833] Lustre: 3309:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 14 previous similar messages [ 954.848232] LustreError: MGC192.168.203.112@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 954.853148] 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 [ 954.881230] Lustre: Skipped 1 previous similar message [ 965.090166] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x9b881f90d52aa41a [ 965.622864] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 965.627276] Lustre: Skipped 1 previous similar message [ 965.679799] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 969.963081] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 979.419485] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 979.672314] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 979.730490] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:225) [ 979.733083] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:225) [ 979.944915] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 979.953395] Lustre: Skipped 2 previous similar messages [ 985.526915] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 987.514897] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 997.367791] Lustre: DEBUG MARKER: == replay-single test 2d: setdirstripe replay ============ 01:55:02 (1787118902) [ 1000.740129] LustreError: 24003:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 1001.792590] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1004.018915] Lustre: Failing over lustre-MDT0000 [ 1004.681539] Lustre: server umount lustre-MDT0000 complete [ 1021.794157] 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 [ 1021.905124] LustreError: MGC192.168.203.112@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1032.163564] LustreError: 3307:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff89df10fdaa00 x1873929077733760/t0(0) o250->MGC192.168.203.112@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 [ 1033.021343] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1037.908716] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1045.987138] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1046.135724] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1046.195189] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:257) [ 1046.196346] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:257) [ 1052.189646] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1053.800972] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1062.848300] Lustre: DEBUG MARKER: == replay-single test 2e: O_CREAT|O_EXCL create replay === 01:56:08 (1787118968) [ 1063.931820] Lustre: *** cfs_fail_loc=13b, val=315*** [ 1063.941903] Lustre: *** cfs_fail_loc=13b, val=2147483648*** [ 1063.947803] LustreError: 24615:0:(ldlm_lib.c:3346:target_send_reply_msg()) @@@ dropping reply req@ffff89df414d3480 x1873929056676736/t38654705666(0) o35->51083077-1bb3-4059-b062-e6ad68ec3b36@192.168.203.12@tcp:12/0 lens 392/456 e 0 to 0 dl 1787118987 ref 1 fl Interpret:/600/0 rc 0/0 job:'openfile.0' uid:0 gid:0 projid:0 [ 1067.811236] LustreError: 25645:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 1068.711567] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1070.793578] Lustre: Failing over lustre-MDT0000 [ 1071.143339] Lustre: server umount lustre-MDT0000 complete [ 1088.992152] LustreError: MGC192.168.203.112@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1099.232778] LustreError: 3307:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff89df030d8700 x1873929077750656/t0(0) o250->MGC192.168.203.112@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 [ 1099.992787] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1104.698118] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1111.241098] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:289) [ 1111.241446] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:289) [ 1111.262452] Lustre: 26258:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff89df3f930a80 x1873929056676736/t38654705666(0) o35->51083077-1bb3-4059-b062-e6ad68ec3b36@192.168.203.12@tcp:59/0 lens 392/456 e 0 to 0 dl 1787119034 ref 1 fl Interpret:/602/0 rc 0/0 job:'openfile.0' uid:0 gid:0 projid:0 [ 1114.125142] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 1114.138234] Lustre: Skipped 3 previous similar messages [ 1118.567147] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1120.162138] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1129.275273] Lustre: DEBUG MARKER: == replay-single test 3a: replay failed open(O_DIRECTORY) ========================================================== 01:57:14 (1787119034) [ 1133.227245] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1135.418076] Lustre: Failing over lustre-MDT0000 [ 1135.916852] Lustre: server umount lustre-MDT0000 complete [ 1155.873266] 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 [ 1155.889791] Lustre: Skipped 3 previous similar messages [ 1166.307550] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x9b881f90d52ab14f [ 1167.011189] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1172.886217] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1178.076150] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1178.093463] Lustre: Skipped 1 previous similar message [ 1178.297636] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1178.310580] Lustre: Skipped 1 previous similar message [ 1178.369031] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:321) [ 1178.369680] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:321) [ 1184.895454] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1186.725717] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1195.888252] Lustre: DEBUG MARKER: == replay-single test 3b: replay failed open -ENOMEM ===== 01:58:21 (1787119101) [ 1199.275921] LustreError: 28821:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 1199.296612] LustreError: 28821:0:(osd_handler.c:715:osd_ro()) Skipped 1 previous similar message [ 1200.340904] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1201.378497] Lustre: *** cfs_fail_loc=114, val=0*** [ 1204.505927] Lustre: Failing over lustre-MDT0000 [ 1206.768765] LustreError: 27839:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1206.806966] LustreError: 27839:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 2 previous similar messages [ 1206.863453] Lustre: server umount lustre-MDT0000 complete [ 1223.136674] Lustre: 3308:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787119113/real 1787119113] req@ffff89df3fa6dc00 x1873929077782656/t0(0) o400->MGC192.168.203.112@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1787119129 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1223.190719] Lustre: 3308:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 36 previous similar messages [ 1223.200766] LustreError: MGC192.168.203.112@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1223.218352] LustreError: Skipped 1 previous similar message [ 1233.101540] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1233.109407] Lustre: Skipped 3 previous similar messages [ 1233.247676] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1234.546058] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:353) [ 1234.546638] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:353) [ 1238.147729] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1248.266840] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1250.027819] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1259.955544] Lustre: DEBUG MARKER: == replay-single test 3c: replay failed open -ENOMEM ===== 01:59:25 (1787119165) [ 1264.176822] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1265.311808] Lustre: *** cfs_fail_loc=128, val=0*** [ 1268.110757] Lustre: Failing over lustre-MDT0000 [ 1268.392769] Lustre: server umount lustre-MDT0000 complete [ 1292.852819] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1295.978880] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:385) [ 1295.990973] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:385) [ 1302.699429] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1304.761777] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1313.700062] Lustre: DEBUG MARKER: == replay-single test 4a: |x| 10 open(O_CREAT)s ========== 02:00:18 (1787119218) [ 1317.448643] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1320.000970] Lustre: Failing over lustre-MDT0000 [ 1320.466550] Lustre: server umount lustre-MDT0000 complete [ 1344.779197] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1349.046196] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:391 to 0x280000400:417) [ 1349.046932] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:391 to 0x240000400:417) [ 1355.967913] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1357.958359] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1367.687766] Lustre: DEBUG MARKER: == replay-single test 4b: |x| rm 10 files ================ 02:01:12 (1787119272) [ 1372.313956] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1374.562570] Lustre: Failing over lustre-MDT0000 [ 1374.836842] Lustre: server umount lustre-MDT0000 complete [ 1401.707036] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x9b881f90d52acb11 [ 1401.731689] Lustre: MGC192.168.203.112@tcp: Connection restored to 0@lo (at 0@lo) [ 1401.753688] Lustre: Skipped 10 previous similar messages [ 1402.348831] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1402.364409] Lustre: Skipped 2 previous similar messages [ 1406.900404] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1416.418203] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:423 to 0x240000400:449) [ 1416.418336] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:423 to 0x280000400:449) [ 1423.159657] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1424.797522] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1434.103993] Lustre: DEBUG MARKER: == replay-single test 5: |x| 220 open(O_CREAT) =========== 02:02:18 (1787119338) [ 1439.885080] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1451.908739] Lustre: Failing over lustre-MDT0000 [ 1451.998702] Lustre: lustre-MDT0000: Not available for connect from 192.168.203.12@tcp (stopping) [ 1452.313514] Lustre: server umount lustre-MDT0000 complete [ 1468.904364] 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 [ 1468.924595] Lustre: Skipped 9 previous similar messages [ 1484.113490] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1491.355143] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1491.373882] Lustre: Skipped 4 previous similar messages [ 1494.656978] Lustre: lustre-MDT0000: Recovery over after 0:03, of 1 clients 1 recovered and 0 were evicted. [ 1494.663239] Lustre: Skipped 4 previous similar messages [ 1494.710940] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:577) [ 1494.712651] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:577) [ 1500.861859] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1502.574497] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1528.842736] Lustre: DEBUG MARKER: == replay-single test 6a: mkdir + contained create ======= 02:03:53 (1787119433) [ 1532.404139] LustreError: 37016:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 1532.413735] LustreError: 37016:0:(osd_handler.c:715:osd_ro()) Skipped 4 previous similar messages [ 1533.484509] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1535.743979] Lustre: Failing over lustre-MDT0000 [ 1536.078685] Lustre: server umount lustre-MDT0000 complete [ 1555.564813] LustreError: MGC192.168.203.112@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1555.576193] LustreError: Skipped 4 previous similar messages [ 1561.017600] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1564.301587] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:609) [ 1564.311246] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:609) [ 1571.944309] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1573.542409] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1584.324808] Lustre: DEBUG MARKER: == replay-single test 6b: |X| rmdir ====================== 02:04:49 (1787119489) [ 1588.436414] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1590.536251] Lustre: Failing over lustre-MDT0000 [ 1590.826605] Lustre: server umount lustre-MDT0000 complete [ 1620.675883] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:641) [ 1620.677727] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:641) [ 1623.396773] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1634.076427] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1635.816466] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1645.055447] Lustre: DEBUG MARKER: == replay-single test 7: mkdir |X| contained create ====== 02:05:50 (1787119550) [ 1650.021892] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1652.564119] Lustre: Failing over lustre-MDT0000 [ 1653.054073] Lustre: server umount lustre-MDT0000 complete [ 1679.377765] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1679.397742] Lustre: Skipped 3 previous similar messages [ 1682.100286] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:673) [ 1682.101801] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:673) [ 1684.728436] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1696.135376] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1697.871134] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1706.467298] Lustre: DEBUG MARKER: == replay-single test 8: creat open |X| close ============ 02:06:51 (1787119611) [ 1711.226983] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1713.829108] Lustre: Failing over lustre-MDT0000 [ 1714.144062] Lustre: server umount lustre-MDT0000 complete [ 1736.672321] Lustre: 3311:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787119627/real 1787119627] req@ffff89df40079180 x1873929077982080/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787119643 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1736.713359] Lustre: 3311:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 58 previous similar messages [ 1744.591154] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:705) [ 1744.593794] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:705) [ 1747.886570] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1758.449090] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1760.315702] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1770.170818] Lustre: DEBUG MARKER: == replay-single test 9: |X| create (same inum/gen) ====== 02:07:54 (1787119674) [ 1774.841104] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1777.152904] Lustre: Failing over lustre-MDT0000 [ 1777.585923] Lustre: server umount lustre-MDT0000 complete [ 1796.526925] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1796.531390] Lustre: Skipped 8 previous similar messages [ 1800.868745] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1805.936944] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:737) [ 1805.937417] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:737) [ 1811.256162] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1812.699250] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1820.576565] Lustre: DEBUG MARKER: == replay-single test 10: create |X| rename unlink ======= 02:08:45 (1787119725) [ 1824.672182] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1826.710211] Lustre: Failing over lustre-MDT0000 [ 1827.039778] Lustre: server umount lustre-MDT0000 complete [ 1852.899234] LustreError: 3307:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff89df41498e00 x1873929078014720/t0(0) o250->MGC192.168.203.112@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 [ 1857.786648] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1858.223161] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:769) [ 1858.230544] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:769) [ 1867.926530] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1870.050349] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1879.651098] Lustre: DEBUG MARKER: == replay-single test 11: create open write rename |X| create-old-name read ========================================================== 02:09:44 (1787119784) [ 1884.029785] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1886.100881] Lustre: Failing over lustre-MDT0000 [ 1886.468207] Lustre: server umount lustre-MDT0000 complete [ 1915.853469] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:771 to 0x280000400:801) [ 1915.853787] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:771 to 0x240000400:801) [ 1918.651504] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1927.888758] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1928.548061] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 1928.567499] Lustre: Skipped 16 previous similar messages [ 1929.512317] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1937.829457] Lustre: DEBUG MARKER: == replay-single test 12: open, unlink |X| close ========= 02:10:42 (1787119842) [ 1942.175570] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1944.462807] Lustre: Failing over lustre-MDT0000 [ 1944.978543] Lustre: server umount lustre-MDT0000 complete [ 1968.952814] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1970.884624] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:771 to 0x280000400:833) [ 1970.886443] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:771 to 0x240000400:833) [ 1979.363303] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1981.376858] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1990.361555] Lustre: DEBUG MARKER: == replay-single test 13: open chmod 0 |x| write close === 02:11:35 (1787119895) [ 1995.138923] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1997.529134] Lustre: Failing over lustre-MDT0000 [ 1997.973541] Lustre: server umount lustre-MDT0000 complete [ 2016.229207] 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 [ 2016.260122] Lustre: Skipped 17 previous similar messages [ 2025.443680] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x9b881f90d52b8bd7 [ 2028.012092] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 2028.023811] Lustre: Skipped 8 previous similar messages [ 2028.217632] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 2028.226270] Lustre: Skipped 8 previous similar messages [ 2028.279347] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:771 to 0x240000400:865) [ 2028.286890] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:835 to 0x280000400:865) [ 2031.197725] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2041.426918] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2042.909744] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2051.464791] Lustre: DEBUG MARKER: == replay-single test 14: open(O_CREAT), unlink |X| close ========================================================== 02:12:36 (1787119956) [ 2054.434678] LustreError: 51290:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 2054.440994] LustreError: 51290:0:(osd_handler.c:715:osd_ro()) Skipped 8 previous similar messages [ 2055.240993] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2057.387467] Lustre: Failing over lustre-MDT0000 [ 2057.858333] Lustre: server umount lustre-MDT0000 complete [ 2076.202417] LustreError: MGC192.168.203.112@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2076.211540] LustreError: Skipped 8 previous similar messages [ 2081.301169] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2085.510715] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:867 to 0x280000400:897) [ 2085.511570] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:771 to 0x240000400:897) [ 2091.909366] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2093.700849] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2103.640472] Lustre: DEBUG MARKER: == replay-single test 15: open(O_CREAT), unlink |X| touch new, close ========================================================== 02:13:28 (1787120008) [ 2108.185643] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2110.563982] Lustre: Failing over lustre-MDT0000 [ 2110.851763] Lustre: server umount lustre-MDT0000 complete [ 2139.108656] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x9b881f90d52b95a1 [ 2145.731666] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2152.255764] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:899 to 0x280000400:929) [ 2152.258543] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:899 to 0x240000400:929) [ 2159.197447] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2161.355312] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2172.002912] Lustre: DEBUG MARKER: == replay-single test 16: |X| open(O_CREAT), unlink, touch new, unlink new ========================================================== 02:14:37 (1787120077) [ 2176.794932] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2178.787145] Lustre: Failing over lustre-MDT0000 [ 2179.049421] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2179.170983] Lustre: server umount lustre-MDT0000 complete [ 2197.989360] LustreError: 55090:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.203.12@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 2198.409374] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 2198.421057] Lustre: Skipped 8 previous similar messages [ 2200.147208] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:931 to 0x240000400:961) [ 2200.152944] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:899 to 0x280000400:961) [ 2203.015995] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2213.326993] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2214.903511] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2225.400797] Lustre: DEBUG MARKER: == replay-single test 17: |X| open(O_CREAT), |replay| close ========================================================== 02:15:29 (1787120129) [ 2230.048851] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2232.685053] Lustre: Failing over lustre-MDT0000 [ 2232.971691] Lustre: server umount lustre-MDT0000 complete [ 2266.350746] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2274.945820] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:899 to 0x280000400:993) [ 2274.946182] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:963 to 0x240000400:993) [ 2280.665503] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2282.372288] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2290.503221] Lustre: DEBUG MARKER: == replay-single test 18: open(O_CREAT), unlink, touch new, close, touch, unlink ========================================================== 02:16:35 (1787120195) [ 2294.287712] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2296.485531] Lustre: Failing over lustre-MDT0000 [ 2296.783448] Lustre: server umount lustre-MDT0000 complete [ 2316.009427] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:995 to 0x280000400:1025) [ 2316.011676] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:995 to 0x240000400:1025) [ 2318.909859] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2328.743991] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2330.394801] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2339.147632] Lustre: DEBUG MARKER: == replay-single test 19: mcreate, open, write, rename === 02:17:24 (1787120244) [ 2342.992262] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2344.990178] Lustre: Failing over lustre-MDT0000 [ 2345.315778] Lustre: server umount lustre-MDT0000 complete [ 2365.474319] Lustre: 3309:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787120256/real 1787120256] req@ffff89df03f79c00 x1873929078161024/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787120272 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2365.511900] Lustre: 3309:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 68 previous similar messages [ 2367.711779] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2373.287678] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1027 to 0x280000400:1057) [ 2373.290152] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1027 to 0x240000400:1057) [ 2378.260762] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2379.777617] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2387.423834] Lustre: DEBUG MARKER: == replay-single test 20a: |X| open(O_CREAT), unlink, replay, close (test mds_cleanup_orphans) ========================================================== 02:18:12 (1787120292) [ 2391.135433] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2393.116254] Lustre: Failing over lustre-MDT0000 [ 2393.551929] Lustre: server umount lustre-MDT0000 complete [ 2419.684752] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x9b881f90d52baf5c [ 2420.235428] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 2420.242156] Lustre: Skipped 10 previous similar messages [ 2421.639367] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1027 to 0x240000400:1089) [ 2421.639369] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1059 to 0x280000400:1089) [ 2424.643108] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2433.703794] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2435.214487] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2444.273824] Lustre: DEBUG MARKER: == replay-single test 20b: write, unlink, eviction, replay (test mds_cleanup_orphans) ========================================================== 02:19:09 (1787120349) [ 2450.262498] Lustre: 62467:0:(genops.c:1795:obd_export_evict_by_uuid()) lustre-MDT0000: evicting 51083077-1bb3-4059-b062-e6ad68ec3b36 at adminstrative request [ 2456.136138] Lustre: Failing over lustre-MDT0000 [ 2456.547089] Lustre: server umount lustre-MDT0000 complete [ 2476.609265] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1059 to 0x280000400:1121) [ 2476.609780] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1091 to 0x240000400:1121) [ 2480.630864] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2489.745422] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2491.236556] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2496.656592] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 2510.942645] Lustre: DEBUG MARKER: before 4096, after 4096 [ 2517.578833] Lustre: DEBUG MARKER: == replay-single test 20c: check that client eviction does not affect file content ========================================================== 02:20:22 (1787120422) [ 2518.692828] Lustre: 64552:0:(genops.c:1795:obd_export_evict_by_uuid()) lustre-MDT0000: evicting 51083077-1bb3-4059-b062-e6ad68ec3b36 at adminstrative request [ 2529.736467] Lustre: DEBUG MARKER: == replay-single test 21: |X| open(O_CREAT), unlink touch new, replay, close (test mds_cleanup_orphans) ========================================================== 02:20:34 (1787120434) [ 2533.376924] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2535.531873] Lustre: Failing over lustre-MDT0000 [ 2535.774258] Lustre: server umount lustre-MDT0000 complete [ 2563.556660] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x9b881f90d52bb95e [ 2563.578744] Lustre: MGC192.168.203.112@tcp: Connection restored to 0@lo (at 0@lo) [ 2563.590055] Lustre: Skipped 24 previous similar messages [ 2564.912862] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1123 to 0x280000400:1153) [ 2564.914164] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1124 to 0x240000400:1153) [ 2568.892461] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2578.695244] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2580.419400] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2588.637462] Lustre: DEBUG MARKER: == replay-single test 22: open(O_CREAT), |X| unlink, replay, close (test mds_cleanup_orphans) ========================================================== 02:21:34 (1787120494) [ 2592.273172] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2594.110138] Lustre: Failing over lustre-MDT0000 [ 2594.406272] Lustre: server umount lustre-MDT0000 complete [ 2616.831763] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2621.035653] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1155 to 0x240000400:1185) [ 2621.036461] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1155 to 0x280000400:1185) [ 2625.431947] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2626.867629] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2633.901082] Lustre: DEBUG MARKER: == replay-single test 23: open(O_CREAT), |X| unlink touch new, replay, close (test mds_cleanup_orphans) ========================================================== 02:22:19 (1787120539) [ 2637.132216] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2638.981226] Lustre: Failing over lustre-MDT0000 [ 2639.263627] Lustre: server umount lustre-MDT0000 complete [ 2657.076398] 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 [ 2657.089083] Lustre: Skipped 21 previous similar messages [ 2657.754775] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 2657.771318] Lustre: Skipped 10 previous similar messages [ 2657.941319] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 2657.952458] Lustre: Skipped 10 previous similar messages [ 2657.988475] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1187 to 0x280000400:1217) [ 2657.998965] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1187 to 0x240000400:1217) [ 2661.178468] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2670.548337] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2672.297246] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2680.699836] Lustre: DEBUG MARKER: == replay-single test 24: open(O_CREAT), replay, unlink, close (test mds_cleanup_orphans) ========================================================== 02:23:05 (1787120585) [ 2683.825888] LustreError: 69670:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 2683.831820] LustreError: 69670:0:(osd_handler.c:715:osd_ro()) Skipped 9 previous similar messages [ 2684.730370] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2686.770027] Lustre: Failing over lustre-MDT0000 [ 2687.152335] Lustre: server umount lustre-MDT0000 complete [ 2704.353102] LustreError: MGC192.168.203.112@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2704.364291] LustreError: Skipped 10 previous similar messages [ 2713.573955] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x9b881f90d52bc7ff [ 2715.432618] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1219 to 0x240000400:1249) [ 2715.437221] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1219 to 0x280000400:1249) [ 2720.542971] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2730.293790] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2732.074048] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2740.690092] Lustre: DEBUG MARKER: == replay-single test 25: open(O_CREAT), unlink, replay, close (test mds_cleanup_orphans) ========================================================== 02:24:05 (1787120645) [ 2745.520423] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2747.788432] Lustre: Failing over lustre-MDT0000 [ 2748.174230] Lustre: server umount lustre-MDT0000 complete [ 2776.765609] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1251 to 0x240000400:1281) [ 2776.765658] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1219 to 0x280000400:1281) [ 2780.074263] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2789.527340] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2790.874701] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2799.452488] Lustre: DEBUG MARKER: == replay-single test 26: |X| open(O_CREAT), unlink two, close one, replay, close one (test mds_cleanup_orphans) ========================================================== 02:25:04 (1787120704) [ 2804.078663] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2806.631623] Lustre: Failing over lustre-MDT0000 [ 2807.017201] Lustre: server umount lustre-MDT0000 complete [ 2827.453096] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 2827.469344] Lustre: Skipped 10 previous similar messages [ 2830.798360] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2833.077137] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1283 to 0x240000400:1313) [ 2833.083440] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1283 to 0x280000400:1313) [ 2840.499032] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2842.098287] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2850.270378] Lustre: DEBUG MARKER: == replay-single test 27: |X| open(O_CREAT), unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 02:25:55 (1787120755) [ 2853.995423] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2856.211539] Lustre: Failing over lustre-MDT0000 [ 2856.774768] Lustre: server umount lustre-MDT0000 complete [ 2885.367932] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1315 to 0x280000400:1345) [ 2885.369836] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1315 to 0x240000400:1345) [ 2888.912799] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2898.901561] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2900.748324] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2909.579851] Lustre: DEBUG MARKER: == replay-single test 28: open(O_CREAT), |X| unlink two, close one, replay, close one (test mds_cleanup_orphans) ========================================================== 02:26:54 (1787120814) [ 2913.254396] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2915.207798] Lustre: Failing over lustre-MDT0000 [ 2915.460403] Lustre: server umount lustre-MDT0000 complete [ 2938.366849] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2941.604407] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1347 to 0x280000400:1377) [ 2941.609988] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1347 to 0x240000400:1377) [ 2947.887379] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2949.441938] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2957.386608] Lustre: DEBUG MARKER: == replay-single test 29: open(O_CREAT), |X| unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 02:27:42 (1787120862) [ 2961.487442] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2963.392737] Lustre: Failing over lustre-MDT0000 [ 2963.776988] Lustre: server umount lustre-MDT0000 complete [ 2981.344095] Lustre: 3308:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787120871/real 1787120871] req@ffff89df40013b80 x1873929078338816/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787120887 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2981.385579] Lustre: 3308:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 85 previous similar messages [ 2990.564893] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x9b881f90d52be200 [ 2992.874820] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1379 to 0x280000400:1409) [ 2992.883532] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1379 to 0x240000400:1409) [ 2996.140854] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3006.970976] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3008.533807] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3016.045030] Lustre: DEBUG MARKER: == replay-single test 30: open(O_CREAT) two, unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 02:28:41 (1787120921) [ 3019.660172] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3021.372128] Lustre: Failing over lustre-MDT0000 [ 3021.672226] Lustre: server umount lustre-MDT0000 complete [ 3039.570628] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3039.574844] Lustre: Skipped 10 previous similar messages [ 3043.628397] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3049.094436] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1411 to 0x240000400:1441) [ 3049.100832] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1411 to 0x280000400:1441) [ 3054.684770] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3056.266867] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3064.778286] Lustre: DEBUG MARKER: == replay-single test 31: open(O_CREAT) two, unlink one, |X| unlink one, close two (test mds_cleanup_orphans) ========================================================== 02:29:29 (1787120969) [ 3068.772266] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3070.758306] Lustre: Failing over lustre-MDT0000 [ 3071.100729] Lustre: server umount lustre-MDT0000 complete [ 3089.890087] LustreError: 81425:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3089.908810] LustreError: 81425:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 2 previous similar messages [ 3091.773133] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1443 to 0x240000400:1473) [ 3091.773163] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1443 to 0x280000400:1473) [ 3094.558669] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3103.704788] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3104.952134] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3113.723480] Lustre: DEBUG MARKER: == replay-single test 32: close() notices client eviction; close() after client eviction ========================================================== 02:30:19 (1787121019) [ 3114.924928] Lustre: 82311:0:(genops.c:1795:obd_export_evict_by_uuid()) lustre-MDT0000: evicting 51083077-1bb3-4059-b062-e6ad68ec3b36 at adminstrative request [ 3123.743503] Lustre: DEBUG MARKER: == replay-single test 33a: fid seq shouldn't be reused after abort recovery ========================================================== 02:30:28 (1787121028) [ 3127.879812] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3129.709540] Lustre: Failing over lustre-MDT0000 [ 3130.132761] Lustre: server umount lustre-MDT0000 complete [ 3140.061820] Lustre: lustre-MDT0000: Aborting client recovery [ 3140.066830] LustreError: 83225:0:(ldlm_lib.c:3004:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 3140.077194] Lustre: 83273:0:(ldlm_lib.c:2404:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 3140.088646] Lustre: 83273:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 51083077-1bb3-4059-b062-e6ad68ec3b36@ [ 3140.098867] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 3140.183857] Lustre: lustre-MDT0000-osd: cancel update llog [0x200000400:0x1:0x0] [ 3140.348732] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1479 to 0x240000400:1505) [ 3140.355742] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1480 to 0x280000400:1505) [ 3144.885894] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3159.685921] Lustre: DEBUG MARKER: == replay-single test 33b: test fid seq allocation ======= 02:31:04 (1787121064) [ 3165.240406] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3168.070479] Lustre: Failing over lustre-MDT0000 [ 3168.709338] Lustre: server umount lustre-MDT0000 complete [ 3179.695173] Lustre: *** cfs_fail_loc=1311, val=0*** [ 3179.730734] Lustre: lustre-MDT0000: Aborting client recovery [ 3179.733103] LustreError: 84600:0:(ldlm_lib.c:3004:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 3179.742234] Lustre: 84645:0:(ldlm_lib.c:2404:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 3179.752403] Lustre: 84645:0:(ldlm_lib.c:2404:target_recovery_overseer()) Skipped 2 previous similar messages [ 3179.763160] Lustre: 84645:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 51083077-1bb3-4059-b062-e6ad68ec3b36@ [ 3179.776670] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 3179.867955] Lustre: lustre-MDT0000-osd: cancel update llog [0x200015bc0:0x1:0x0] [ 3180.170279] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1516 to 0x240000400:1537) [ 3180.178622] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1516 to 0x280000400:1537) [ 3184.616787] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 3184.624317] Lustre: Skipped 26 previous similar messages [ 3186.069473] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3192.259852] Lustre: *** cfs_fail_loc=1311, val=0*** [ 3199.804971] Lustre: DEBUG MARKER: == replay-single test 34: abort recovery before client does replay (test mds_cleanup_orphans) ========================================================== 02:31:45 (1787121105) [ 3204.332776] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3206.363485] Lustre: Failing over lustre-MDT0000 [ 3206.705819] Lustre: server umount lustre-MDT0000 complete [ 3215.332944] LustreError: 85984:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3215.818184] Lustre: lustre-MDT0000: Aborting client recovery [ 3215.821647] LustreError: 85973:0:(ldlm_lib.c:3004:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 3215.833736] Lustre: 86021:0:(ldlm_lib.c:2404:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 3215.849882] Lustre: 86021:0:(ldlm_lib.c:2404:target_recovery_overseer()) Skipped 2 previous similar messages [ 3215.869143] Lustre: 86021:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 51083077-1bb3-4059-b062-e6ad68ec3b36@ [ 3215.885250] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 3215.950752] Lustre: lustre-MDT0000-osd: cancel update llog [0x200016778:0x1:0x0] [ 3216.129414] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1544 to 0x280000400:1569) [ 3216.133635] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1543 to 0x240000400:1569) [ 3220.586807] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3233.686871] Lustre: DEBUG MARKER: == replay-single test 35: test recovery from llog for unlink op ========================================================== 02:32:18 (1787121138) [ 3234.856787] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 3234.861405] LustreError: 85984:0:(ldlm_lib.c:3346:target_send_reply_msg()) @@@ dropping reply req@ffff89df07e5a300 x1873929057678592/t201863462916(0) o36->51083077-1bb3-4059-b062-e6ad68ec3b36@192.168.203.12@tcp:667/0 lens 512/456 e 0 to 0 dl 1787121152 ref 1 fl Interpret:/200/0 rc 0/0 job:'rm.0' uid:0 gid:0 projid:4294967295 [ 3238.525679] Lustre: Failing over lustre-MDT0000 [ 3238.825097] Lustre: server umount lustre-MDT0000 complete [ 3248.105662] Lustre: lustre-MDT0000: Aborting client recovery [ 3248.109918] LustreError: 87198:0:(ldlm_lib.c:3004:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 3248.120421] Lustre: 87245:0:(ldlm_lib.c:2404:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 3248.127391] Lustre: 87245:0:(ldlm_lib.c:2404:target_recovery_overseer()) Skipped 2 previous similar messages [ 3248.134074] Lustre: 87245:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 51083077-1bb3-4059-b062-e6ad68ec3b36@ [ 3248.144479] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 3248.207132] Lustre: lustre-MDT0000-osd: cancel update llog [0x200017330:0x1:0x0] [ 3248.354270] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1543 to 0x240000400:1601) [ 3248.363502] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1571 to 0x280000400:1601) [ 3252.586508] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3265.124489] Lustre: DEBUG MARKER: SKIP: replay-single test_36 skipping ALWAYS excluded test 36 [ 3267.025506] Lustre: DEBUG MARKER: == replay-single test 37: abort recovery before client does replay (test mds_cleanup_orphans for directories) ========================================================== 02:32:51 (1787121171) [ 3271.912965] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3275.003708] Lustre: Failing over lustre-MDT0000 [ 3275.276308] Lustre: server umount lustre-MDT0000 complete [ 3285.099716] 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 [ 3285.116246] Lustre: Skipped 26 previous similar messages [ 3285.312718] Lustre: lustre-MDT0000: Aborting client recovery [ 3285.315507] LustreError: 88662:0:(ldlm_lib.c:3004:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 3285.321469] Lustre: 88708:0:(ldlm_lib.c:2404:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 3285.326753] Lustre: 88708:0:(ldlm_lib.c:2404:target_recovery_overseer()) Skipped 2 previous similar messages [ 3285.331515] Lustre: 88708:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 51083077-1bb3-4059-b062-e6ad68ec3b36@ [ 3285.342596] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 3285.383375] Lustre: lustre-MDT0000-osd: cancel update llog [0x200017b00:0x1:0x0] [ 3285.486362] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1571 to 0x280000400:1633) [ 3285.489448] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1543 to 0x240000400:1633) [ 3290.287250] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3304.450521] Lustre: DEBUG MARKER: == replay-single test 38: test recovery from unlink llog (test llog_gen_rec) ========================================================== 02:33:29 (1787121209) [ 3338.497859] LustreError: 89791:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 3338.505972] LustreError: 89791:0:(osd_handler.c:715:osd_ro()) Skipped 11 previous similar messages [ 3339.453951] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3341.240309] Lustre: Failing over lustre-MDT0000 [ 3341.510931] Lustre: server umount lustre-MDT0000 complete [ 3359.382399] LustreError: MGC192.168.203.112@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3359.393093] LustreError: Skipped 12 previous similar messages [ 3361.292550] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 3361.305859] Lustre: Skipped 8 previous similar messages [ 3361.454680] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 3361.460313] Lustre: Skipped 8 previous similar messages [ 3361.515637] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2034 to 0x240000400:2049) [ 3361.515705] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2034 to 0x280000400:2049) [ 3363.825484] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3373.293241] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3374.899581] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3396.792902] Lustre: DEBUG MARKER: == replay-single test 39: test recovery from unlink llog (test llog_gen_rec) ========================================================== 02:35:02 (1787121302) [ 3423.531629] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3435.413065] Lustre: Failing over lustre-MDT0000 [ 3435.847499] Lustre: server umount lustre-MDT0000 complete [ 3453.986965] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 3453.991030] Lustre: Skipped 21 previous similar messages [ 3457.442170] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3467.318447] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2450 to 0x280000400:2465) [ 3467.322562] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2450 to 0x240000400:2465) [ 3473.366655] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3474.854527] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3496.105062] Lustre: DEBUG MARKER: == replay-single test 41: read from a valid osc while other oscs are invalid ========================================================== 02:36:41 (1787121401) [ 3498.528229] Lustre: setting import lustre-OST0001_UUID INACTIVE by administrator request [ 3499.624504] Lustre: lustre-OST0001: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnecting [ 3499.640551] LustreError: lustre-OST0001-osc-MDT0000: This client was evicted by lustre-OST0001; in progress operations using this service will fail. [ 3506.439213] Lustre: DEBUG MARKER: == replay-single test 42: recovery after ost failure ===== 02:36:51 (1787121411) [ 3535.487881] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 3550.119611] Lustre: Failing over lustre-OST0000 [ 3550.269458] Lustre: server umount lustre-OST0000 complete [ 3550.697955] LustreError: 36654:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.203.12@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3550.723527] LustreError: 36654:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 1 previous similar message [ 3554.274476] LustreError: 36647:0:(ldlm_lib.c:1192: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. [ 3559.396205] LustreError: 6683:0:(ldlm_lib.c:1192: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. [ 3559.432322] LustreError: 6683:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 1 previous similar message [ 3576.030477] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3638.162639] Lustre: DEBUG MARKER: == replay-single test 43: mds osc import failure during recovery; don't LBUG ========================================================== 02:39:03 (1787121543) [ 3642.089614] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3645.025668] Lustre: Failing over lustre-MDT0000 [ 3645.339090] Lustre: server umount lustre-MDT0000 complete [ 3662.817897] Lustre: 3308:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787121553/real 1787121553] req@ffff89df04975c00 x1873929078946560/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787121569 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3662.880680] Lustre: 3308:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 59 previous similar messages [ 3673.518777] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3673.522743] Lustre: Skipped 9 previous similar messages [ 3674.694983] Lustre: *** cfs_fail_loc=204, val=2147483648*** [ 3674.696098] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2866 to 0x280000400:2881) [ 3677.879316] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3689.604680] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3690.978278] LustreError: 96674:0:(osp_precreate.c:974:osp_precreate_cleanup_orphans()) lustre-OST0000-osc-MDT0000: cannot cleanup orphans: rc = -11 [ 3690.981327] Lustre: lustre-OST0000: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnecting [ 3691.474693] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3692.001891] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2867 to 0x240000400:2913) [ 3710.967555] Lustre: DEBUG MARKER: == replay-single test 44a: race in target handle connect ========================================================== 02:40:16 (1787121616) [ 3716.356897] LustreError: 96651:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_race id 701 sleeping [ 3721.696123] LustreError: 96651:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 3721.707272] Lustre: lustre-MDT0000: Client 51083077-1bb3-4059-b062-e6ad68ec3b36 (at 192.168.203.12@tcp) reconnecting [ 3721.748969] LustreError: 36655:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_fail_race id 701 waking [ 3723.537439] LustreError: 97761:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_race id 701 sleeping [ 3728.864239] LustreError: 97761:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 3728.872114] Lustre: lustre-MDT0000: Client 51083077-1bb3-4059-b062-e6ad68ec3b36 (at 192.168.203.12@tcp) reconnecting [ 3730.793387] LustreError: 96651:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_race id 701 sleeping [ 3736.032257] LustreError: 96651:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 3736.045115] Lustre: lustre-MDT0000: Client 51083077-1bb3-4059-b062-e6ad68ec3b36 (at 192.168.203.12@tcp) reconnecting [ 3737.920094] LustreError: 96653:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_race id 701 sleeping [ 3743.200879] LustreError: 96653:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 3745.291778] LustreError: 96651:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_race id 701 sleeping [ 3750.368154] LustreError: 96651:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 3750.381594] Lustre: lustre-MDT0000: Client 51083077-1bb3-4059-b062-e6ad68ec3b36 (at 192.168.203.12@tcp) reconnecting [ 3750.389581] Lustre: Skipped 1 previous similar message [ 3759.244180] LustreError: 96652:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_race id 701 sleeping [ 3759.254486] LustreError: 96652:0:(ldlm_lib.c:1178:target_handle_connect()) Skipped 1 previous similar message [ 3764.704958] LustreError: 96652:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 3764.710162] LustreError: 96652:0:(ldlm_lib.c:1178:target_handle_connect()) Skipped 1 previous similar message [ 3771.872405] Lustre: lustre-MDT0000: Client 51083077-1bb3-4059-b062-e6ad68ec3b36 (at 192.168.203.12@tcp) reconnecting [ 3771.880583] Lustre: Skipped 2 previous similar messages [ 3780.211412] LustreError: 96652:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_race id 701 sleeping [ 3780.217179] LustreError: 96652:0:(ldlm_lib.c:1178:target_handle_connect()) Skipped 2 previous similar messages [ 3785.698380] LustreError: 96652:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 3785.707378] LustreError: 96652:0:(ldlm_lib.c:1178:target_handle_connect()) Skipped 2 previous similar messages [ 3793.704507] Lustre: DEBUG MARKER: == replay-single test 44b: race in target handle connect ========================================================== 02:41:39 (1787121699) [ 3795.277155] LustreError: 96653:0:(ldlm_lib.c:1436:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 3804.636136] Lustre: lustre-MDT0000: Export ffff89df09b51000 already connecting from 192.168.203.12@tcp [ 3809.781224] Lustre: lustre-MDT0000: Export ffff89df09b51000 already connecting from 192.168.203.12@tcp [ 3814.878949] Lustre: lustre-MDT0000: Export ffff89df09b51000 already connecting from 192.168.203.12@tcp [ 3817.550754] Lustre: lustre-MDT0000: Export ffff89df09b51000 already connecting from 192.168.203.12@tcp [ 3825.115502] Lustre: lustre-MDT0000: Export ffff89df09b51000 already connecting from 192.168.203.12@tcp [ 3825.137755] Lustre: Skipped 1 previous similar message [ 3835.336742] LustreError: 96653:0:(ldlm_lib.c:1436:target_handle_connect()) cfs_fail_timeout id 704 awake [ 3835.342709] Lustre: 96653:0:(service.c:2582:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/20s); client may timeout req@ffff89df400a3480 x1873929060318976/t0(0) o38->51083077-1bb3-4059-b062-e6ad68ec3b36@192.168.203.12@tcp:0/0 lens 520/416 e 0 to 0 dl 1787121721 ref 1 fl Complete:H/200/0 rc 0/0 job:'lctl.0' uid:0 gid:0 projid:4294967295 [ 3835.354208] Lustre: lustre-MDT0000: Client 51083077-1bb3-4059-b062-e6ad68ec3b36 (at 192.168.203.12@tcp) reconnecting [ 3835.382317] Lustre: Skipped 3 previous similar messages [ 3835.385225] LustreError: 97761:0:(ldlm_lib.c:1436:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 3860.954908] Lustre: lustre-MDT0000: Export ffff89df09b51000 already connecting from 192.168.203.12@tcp [ 3860.970182] Lustre: Skipped 1 previous similar message [ 3875.424270] LustreError: 97761:0:(ldlm_lib.c:1436:target_handle_connect()) cfs_fail_timeout id 704 awake [ 3875.431661] Lustre: 97761:0:(service.c:2582:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/21s); client may timeout req@ffff89df10306d80 x1873929060321920/t0(0) o38->51083077-1bb3-4059-b062-e6ad68ec3b36@192.168.203.12@tcp:0/0 lens 520/416 e 0 to 0 dl 1787121761 ref 1 fl Complete:H/200/0 rc 0/0 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3876.313127] LustreError: 97200:0:(ldlm_lib.c:1436:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 3900.892083] Lustre: lustre-MDT0000: Export ffff89df09b51000 already connecting from 192.168.203.12@tcp [ 3900.898741] Lustre: Skipped 3 previous similar messages [ 3916.408190] LustreError: 97200:0:(ldlm_lib.c:1436:target_handle_connect()) cfs_fail_timeout id 704 awake [ 3916.422342] Lustre: 97200:0:(service.c:2582:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/21s); client may timeout req@ffff89df353ac700 x1873929060323840/t0(0) o38->51083077-1bb3-4059-b062-e6ad68ec3b36@192.168.203.12@tcp:0/0 lens 520/416 e 0 to 0 dl 1787121802 ref 1 fl Complete:H/200/0 rc 0/0 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3921.370992] Lustre: lustre-MDT0000: Client 51083077-1bb3-4059-b062-e6ad68ec3b36 (at 192.168.203.12@tcp) reconnecting [ 3921.381215] Lustre: Skipped 1 previous similar message [ 3921.390894] LustreError: 96652:0:(ldlm_lib.c:1436:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 3946.969594] Lustre: lustre-MDT0000: Export ffff89df09b51000 already connecting from 192.168.203.12@tcp [ 3946.987186] Lustre: Skipped 4 previous similar messages [ 3961.488225] LustreError: 96652:0:(ldlm_lib.c:1436:target_handle_connect()) cfs_fail_timeout id 704 awake [ 3961.498815] Lustre: 96652:0:(service.c:2582:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/21s); client may timeout req@ffff89df048c2300 x1873929060326016/t0(0) o38->51083077-1bb3-4059-b062-e6ad68ec3b36@192.168.203.12@tcp:0/0 lens 520/416 e 0 to 0 dl 1787121847 ref 1 fl Complete:H/200/0 rc 0/0 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3962.329472] LustreError: 99416:0:(ldlm_lib.c:1436:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 4002.337508] LustreError: 99416:0:(ldlm_lib.c:1436:target_handle_connect()) cfs_fail_timeout id 704 awake [ 4002.347835] Lustre: 99416:0:(service.c:2582:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/20s); client may timeout req@ffff89de087d3b80 x1873929060327936/t0(0) o38->51083077-1bb3-4059-b062-e6ad68ec3b36@192.168.203.12@tcp:0/0 lens 520/416 e 0 to 0 dl 1787121888 ref 1 fl Complete:H/200/0 rc 0/0 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4003.290648] LustreError: 96653:0:(ldlm_lib.c:1436:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 4020.500348] LustreError: 96653:0:(ldlm_lib.c:1436:target_handle_connect()) cfs_fail_timeout interrupted [ 4025.145476] Lustre: DEBUG MARKER: == replay-single test 44c: race in target handle connect ========================================================== 02:45:30 (1787121930) [ 4028.285470] LustreError: 100502:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 4028.291468] LustreError: 100502:0:(osd_handler.c:715:osd_ro()) Skipped 3 previous similar messages [ 4029.067422] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4033.251463] Lustre: Failing over lustre-MDT0000 [ 4033.637560] Lustre: server umount lustre-MDT0000 complete [ 4041.813252] LustreError: MGC192.168.203.112@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4041.819244] LustreError: Skipped 2 previous similar messages [ 4042.071185] Lustre: *** cfs_fail_loc=712, val=0*** [ 4042.076067] 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 [ 4042.079783] LustreError: 34938:0:(service.c:1394:ptlrpc_check_req()) @@@ Invalid replay without recovery req@ffff89df10306d80 x1873929079030784/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 [ 4042.089315] Lustre: Skipped 9 previous similar messages [ 4042.307574] Lustre: lustre-MDT0000: Aborting client recovery [ 4042.311277] LustreError: 101179:0:(ldlm_lib.c:3004:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 4042.317111] Lustre: 101226:0:(ldlm_lib.c:2404:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 4042.323755] Lustre: 101226:0:(ldlm_lib.c:2404:target_recovery_overseer()) Skipped 2 previous similar messages [ 4042.333870] Lustre: 101226:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 51083077-1bb3-4059-b062-e6ad68ec3b36@ [ 4042.352283] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 4042.406573] Lustre: lustre-MDT0000-osd: cancel update llog [0x2000182d0:0x1:0x0] [ 4042.509359] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2866 to 0x280000400:2913) [ 4042.516779] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2867 to 0x240000400:2945) [ 4047.018938] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4047.334191] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 4047.338621] Lustre: Skipped 16 previous similar messages [ 4054.772529] Lustre: Failing over lustre-MDT0000 [ 4055.096889] Lustre: server umount lustre-MDT0000 complete [ 4073.811401] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4073.819021] Lustre: Skipped 5 previous similar messages [ 4075.005204] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4075.025378] Lustre: Skipped 3 previous similar messages [ 4075.166231] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4075.174383] Lustre: Skipped 3 previous similar messages [ 4075.225316] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2866 to 0x280000400:2945) [ 4075.227405] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2867 to 0x240000400:2977) [ 4078.016879] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4087.037705] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4088.339511] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4096.142993] Lustre: DEBUG MARKER: == replay-single test 45: Handle failed close ============ 02:46:41 (1787122001) [ 4096.270773] Lustre: lustre-MDT0000: Client 51083077-1bb3-4059-b062-e6ad68ec3b36 (at 192.168.203.12@tcp) reconnecting [ 4096.284465] Lustre: Skipped 2 previous similar messages [ 4103.605954] Lustre: DEBUG MARKER: == replay-single test 46: Don't leak file handle after open resend (3325) ========================================================== 02:46:48 (1787122008) [ 4104.419408] Lustre: *** cfs_fail_loc=122, val=2147483648*** [ 4104.422504] LustreError: 102147:0:(ldlm_lib.c:3346:target_send_reply_msg()) @@@ dropping reply req@ffff89df3f054e00 x1873929060384512/t0(0) o700->51083077-1bb3-4059-b062-e6ad68ec3b36@192.168.203.12@tcp:27/0 lens 264/248 e 0 to 0 dl 1787122022 ref 1 fl Interpret:/200/0 rc 0/0 job:'touch.0' uid:0 gid:0 projid:4294967295 [ 4124.137598] Lustre: Failing over lustre-MDT0000 [ 4124.462972] Lustre: server umount lustre-MDT0000 complete [ 4150.753267] LustreError: 3307:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff89df10ec5f80 x1873929079060608/t0(0) o250->MGC192.168.203.112@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 [ 4151.902213] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2947 to 0x280000400:2977) [ 4151.902213] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2979 to 0x240000400:3009) [ 4155.664333] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4164.745719] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4166.669159] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4177.342902] Lustre: DEBUG MARKER: == replay-single test 47: MDS->OSC failure during precreate cleanup (2824) ========================================================== 02:48:02 (1787122082) [ 4179.939157] Lustre: Failing over lustre-OST0000 [ 4180.060613] Lustre: server umount lustre-OST0000 complete [ 4180.967382] LustreError: 12811:0:(ldlm_lib.c:1192: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. [ 4180.996607] LustreError: 12811:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 3 previous similar messages [ 4182.518315] LustreError: 36657:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.203.12@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4186.086719] LustreError: 6685:0:(ldlm_lib.c:1192: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. [ 4191.201833] LustreError: 36652:0:(ldlm_lib.c:1192: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. [ 4191.223451] LustreError: 36652:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 1 previous similar message [ 4204.405521] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4213.440256] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 4214.895275] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4285.809498] Lustre: DEBUG MARKER: == replay-single test 48: MDS->OSC failure during precreate cleanup (2824) ========================================================== 02:49:51 (1787122191) [ 4289.236284] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4291.589752] Lustre: Failing over lustre-MDT0000 [ 4291.896680] Lustre: server umount lustre-MDT0000 complete [ 4310.033914] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4310.038559] Lustre: Skipped 4 previous similar messages [ 4311.114518] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2998 to 0x280000400:3041) [ 4311.116442] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3030 to 0x240000400:3073) [ 4311.904355] Lustre: 3311:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787122202/real 1787122202] req@ffff89df07250000 x1873929079103232/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787122218 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4311.951824] Lustre: 3311:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 28 previous similar messages [ 4314.839861] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4382.787415] Lustre: *** cfs_fail_loc=216, val=0*** [ 4387.960800] Lustre: DEBUG MARKER: == replay-single test 50: Double OSC recovery, don't LASSERT (3812) ========================================================== 02:51:33 (1787122293) [ 4390.045721] Lustre: lustre-OST0000: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnecting [ 4390.050280] Lustre: Skipped 2 previous similar messages [ 4402.028916] Lustre: DEBUG MARKER: == replay-single test 52: time out lock replay (3764) ==== 02:51:47 (1787122307) [ 4405.053858] Lustre: Failing over lustre-MDT0000 [ 4405.345558] Lustre: server umount lustre-MDT0000 complete [ 4432.800894] LustreError: 3307:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff89df3f055f80 x1873929079140224/t0(0) o250->MGC192.168.203.112@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 [ 4434.605837] Lustre: *** cfs_fail_loc=157, val=2147483648*** [ 4434.613329] LustreError: 108628:0:(ldlm_lib.c:3346:target_send_reply_msg()) @@@ dropping reply req@ffff89df400a3800 x1873929060501888/t0(0) o101->51083077-1bb3-4059-b062-e6ad68ec3b36@192.168.203.12@tcp:357/0 lens 328/344 e 0 to 0 dl 1787122352 ref 1 fl Complete:/240/0 rc 0/0 job:'ldlm_lock_repla.0' uid:0 gid:0 projid:4294967295 [ 4440.114875] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4450.781822] Lustre: lustre-MDT0000: Client 51083077-1bb3-4059-b062-e6ad68ec3b36 (at 192.168.203.12@tcp) reconnected, waiting for 1 clients in recovery for 1:24 [ 4450.974521] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3084 to 0x240000400:3105) [ 4450.978151] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3053 to 0x280000400:3073) [ 4456.993951] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4458.659741] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4467.159442] Lustre: DEBUG MARKER: == replay-single test 53a: |X| close request while two MDC requests in flight ========================================================== 02:52:52 (1787122372) [ 4469.329708] Lustre: *** cfs_fail_loc=115, val=2147483648*** [ 4474.264510] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4476.097472] Lustre: Failing over lustre-MDT0000 [ 4476.360628] Lustre: server umount lustre-MDT0000 complete [ 4496.234993] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3107 to 0x240000400:3137) [ 4496.238943] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3053 to 0x280000400:3105) [ 4499.009828] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4507.671824] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4508.917549] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4516.357550] Lustre: DEBUG MARKER: == replay-single test 53b: |X| open request while two MDC requests in flight ========================================================== 02:53:41 (1787122421) [ 4517.207510] Lustre: *** cfs_fail_loc=107, val=2147483648*** [ 4522.024294] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4523.677730] Lustre: Failing over lustre-MDT0000 [ 4523.936481] Lustre: server umount lustre-MDT0000 complete [ 4552.167671] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x9b881f90d5307d6b [ 4558.318076] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3107 to 0x240000400:3169) [ 4558.326499] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3107 to 0x280000400:3137) [ 4558.802366] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4570.318234] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4572.051686] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4580.503856] Lustre: DEBUG MARKER: == replay-single test 53c: |X| open request and close request while two MDC requests in flight ========================================================== 02:54:45 (1787122485) [ 4581.518659] Lustre: *** cfs_fail_loc=107, val=2147483648*** [ 4586.989073] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4588.913807] Lustre: Failing over lustre-MDT0000 [ 4589.045348] Lustre: lustre-MDT0000: Not available for connect from 192.168.203.12@tcp (stopping) [ 4589.057623] Lustre: Skipped 1 previous similar message [ 4589.206486] Lustre: server umount lustre-MDT0000 complete [ 4607.970782] Lustre: lustre-MDT0000: Not available for connect from 0@lo (not set up) [ 4608.668271] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3139 to 0x280000400:3169) [ 4608.668352] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3107 to 0x240000400:3201) [ 4613.576351] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4626.639543] Lustre: DEBUG MARKER: == replay-single test 53d: close reply while two MDC requests in flight ========================================================== 02:55:31 (1787122531) [ 4628.705888] Lustre: *** cfs_fail_loc=13b, val=315*** [ 4628.711632] Lustre: *** cfs_fail_loc=13b, val=2147483648*** [ 4628.729959] LustreError: 113720:0:(ldlm_lib.c:3346:target_send_reply_msg()) @@@ dropping reply req@ffff89df4001d880 x1873929060550016/t257698037777(0) o35->51083077-1bb3-4059-b062-e6ad68ec3b36@192.168.203.12@tcp:551/0 lens 392/456 e 0 to 0 dl 1787122546 ref 1 fl Interpret:/600/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 4631.546712] Lustre: Failing over lustre-MDT0000 [ 4632.031948] Lustre: server umount lustre-MDT0000 complete [ 4649.440432] 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 [ 4649.449645] Lustre: Skipped 18 previous similar messages [ 4650.272767] LustreError: MGC192.168.203.112@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4650.281898] LustreError: Skipped 7 previous similar messages [ 4665.017856] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4669.944364] Lustre: 115016:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff89df3fa6e680 x1873929060550016/t257698037777(0) o35->51083077-1bb3-4059-b062-e6ad68ec3b36@192.168.203.12@tcp:592/0 lens 392/456 e 0 to 0 dl 1787122587 ref 1 fl Interpret:/602/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 4669.966642] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3107 to 0x240000400:3233) [ 4669.967335] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3171 to 0x280000400:3201) [ 4674.545339] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 4674.552678] Lustre: Skipped 19 previous similar messages [ 4675.701872] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4677.255294] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4685.495498] Lustre: DEBUG MARKER: == replay-single test 53e: |X| open reply while two MDC requests in flight ========================================================== 02:56:30 (1787122590) [ 4686.640587] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 4686.650849] LustreError: 115014:0:(ldlm_lib.c:3346:target_send_reply_msg()) @@@ dropping reply req@ffff89df05a23480 x1873929060563968/t261993005072(0) o36->51083077-1bb3-4059-b062-e6ad68ec3b36@192.168.203.12@tcp:609/0 lens 504/448 e 0 to 0 dl 1787122604 ref 1 fl Interpret:/200/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 4692.285981] LustreError: 116097:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 4692.298396] LustreError: 116097:0:(osd_handler.c:715:osd_ro()) Skipped 4 previous similar messages [ 4693.311202] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4695.390184] Lustre: Failing over lustre-MDT0000 [ 4695.523400] Lustre: lustre-MDT0000: Not available for connect from 192.168.203.12@tcp (stopping) [ 4695.539231] Lustre: Skipped 1 previous similar message [ 4695.798541] Lustre: server umount lustre-MDT0000 complete [ 4715.058235] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4715.067971] Lustre: Skipped 8 previous similar messages [ 4716.004242] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4716.012691] Lustre: Skipped 8 previous similar messages [ 4716.121997] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4716.128517] Lustre: Skipped 8 previous similar messages [ 4716.159619] Lustre: 116704:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff89df3fa6ce00 x1873929060563968/t261993005072(0) o36->51083077-1bb3-4059-b062-e6ad68ec3b36@192.168.203.12@tcp:638/0 lens 504/2880 e 0 to 0 dl 1787122633 ref 1 fl Interpret:/202/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 4716.183535] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3235 to 0x240000400:3265) [ 4716.186055] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3171 to 0x280000400:3233) [ 4719.022832] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4727.814920] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4729.425916] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4737.869319] Lustre: DEBUG MARKER: == replay-single test 53f: |X| open reply and close reply while two MDC requests in flight ========================================================== 02:57:23 (1787122643) [ 4739.161697] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 4739.166478] LustreError: 116704:0:(ldlm_lib.c:3346:target_send_reply_msg()) @@@ dropping reply req@ffff89df27aea300 x1873929060577280/t266287972368(0) o36->51083077-1bb3-4059-b062-e6ad68ec3b36@192.168.203.12@tcp:661/0 lens 504/448 e 0 to 0 dl 1787122656 ref 1 fl Interpret:/200/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 4740.982279] Lustre: *** cfs_fail_loc=13b, val=315*** [ 4744.330919] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4746.083784] Lustre: Failing over lustre-MDT0000 [ 4746.314749] Lustre: server umount lustre-MDT0000 complete [ 4767.823639] Lustre: 118383:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff89df3fa5e300 x1873929060577280/t266287972368(0) o36->51083077-1bb3-4059-b062-e6ad68ec3b36@192.168.203.12@tcp:690/0 lens 504/2880 e 0 to 0 dl 1787122685 ref 1 fl Interpret:/202/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 4767.856774] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3267 to 0x240000400:3297) [ 4767.862101] Lustre: 118383:0:(mdt_recovery.c:102:mdt_req_from_lrd()) Skipped 1 previous similar message [ 4767.865530] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3171 to 0x280000400:3265) [ 4770.502880] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4782.715731] Lustre: DEBUG MARKER: == replay-single test 53g: |X| drop open reply and close request while close and open are both in flight ========================================================== 02:58:07 (1787122687) [ 4783.907819] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 4783.912441] Lustre: Skipped 1 previous similar message [ 4783.919088] LustreError: 118384:0:(ldlm_lib.c:3346:target_send_reply_msg()) @@@ dropping reply req@ffff89df0a11e300 x1873929060589952/t270582939664(0) o36->51083077-1bb3-4059-b062-e6ad68ec3b36@192.168.203.12@tcp:706/0 lens 504/448 e 0 to 0 dl 1787122701 ref 1 fl Interpret:/200/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 4783.944694] LustreError: 118384:0:(ldlm_lib.c:3346:target_send_reply_msg()) Skipped 1 previous similar message [ 4785.739683] Lustre: *** cfs_fail_loc=115, val=2147483648*** [ 4785.746246] Lustre: Skipped 1 previous similar message [ 4790.112765] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4792.056333] Lustre: Failing over lustre-MDT0000 [ 4792.481392] Lustre: server umount lustre-MDT0000 complete [ 4815.039370] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4825.087249] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3171 to 0x280000400:3297) [ 4825.087261] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3299 to 0x240000400:3329) [ 4825.104728] Lustre: 119926:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff89df353a8700 x1873929060589952/t270582939664(0) o36->51083077-1bb3-4059-b062-e6ad68ec3b36@192.168.203.12@tcp:747/0 lens 504/2880 e 0 to 0 dl 1787122742 ref 1 fl Interpret:/202/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 4833.966870] Lustre: DEBUG MARKER: == replay-single test 53h: open request and close reply while two MDC requests in flight ========================================================== 02:58:59 (1787122739) [ 4835.033186] Lustre: *** cfs_fail_loc=107, val=2147483648*** [ 4836.786412] Lustre: *** cfs_fail_loc=13b, val=315*** [ 4836.792168] Lustre: *** cfs_fail_loc=13b, val=2147483648*** [ 4836.800301] LustreError: 119928:0:(ldlm_lib.c:3346:target_send_reply_msg()) @@@ dropping reply req@ffff89df03f78380 x1873929060602240/t274877906960(0) o35->51083077-1bb3-4059-b062-e6ad68ec3b36@192.168.203.12@tcp:4/0 lens 392/456 e 0 to 0 dl 1787122754 ref 1 fl Interpret:/600/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 4841.521906] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4843.504964] Lustre: Failing over lustre-MDT0000 [ 4843.825541] Lustre: server umount lustre-MDT0000 complete [ 4873.187082] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x9b881f90d530a0db [ 4876.398315] Lustre: 121410:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff89df356a4000 x1873929060602240/t274877906960(0) o35->51083077-1bb3-4059-b062-e6ad68ec3b36@192.168.203.12@tcp:43/0 lens 392/456 e 0 to 0 dl 1787122793 ref 1 fl Interpret:/602/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 4876.414320] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3299 to 0x280000400:3329) [ 4876.420472] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3299 to 0x240000400:3361) [ 4879.328705] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4892.214670] Lustre: DEBUG MARKER: == replay-single test 55: let MDS_CHECK_RESENT return the original return code instead of 0 ========================================================== 02:59:57 (1787122797) [ 4893.390310] Lustre: *** cfs_fail_loc=12b, val=2147483991*** [ 4893.401280] LustreError: 121960:0:(ldlm_lib.c:3346:target_send_reply_msg()) @@@ dropping reply req@ffff89df09034a80 x1873929060612992/t279172874255(0) o101->51083077-1bb3-4059-b062-e6ad68ec3b36@192.168.203.12@tcp:60/0 lens 664/608 e 0 to 0 dl 1787122810 ref 1 fl Interpret:/600/0 rc 301/0 job:'touch.0' uid:0 gid:0 projid:0 [ 4909.537780] Lustre: lustre-MDT0000: Client 51083077-1bb3-4059-b062-e6ad68ec3b36 (at 192.168.203.12@tcp) reconnecting [ 4909.555770] Lustre: Skipped 1 previous similar message [ 4909.580763] Lustre: 121409:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff89df067e9500 x1873929060612992/t279172874255(0) o101->51083077-1bb3-4059-b062-e6ad68ec3b36@192.168.203.12@tcp:77/0 lens 664/3488 e 0 to 0 dl 1787122827 ref 1 fl Interpret:/602/0 rc 0/0 job:'touch.0' uid:0 gid:0 projid:0 [ 4918.724838] Lustre: DEBUG MARKER: == replay-single test 56: don't replay a symlink open request (3440) ========================================================== 03:00:23 (1787122823) [ 4924.015976] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4926.165531] Lustre: Failing over lustre-MDT0000 [ 4926.526541] Lustre: server umount lustre-MDT0000 complete [ 4945.377147] Lustre: 3309:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787122835/real 1787122835] req@ffff89df359bb480 x1873929079287040/t0(0) o400->MGC192.168.203.112@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1787122851 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4945.394575] Lustre: 3309:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 76 previous similar messages [ 4955.089884] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4955.094840] Lustre: Skipped 9 previous similar messages [ 4959.640367] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4968.015718] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3363 to 0x240000400:3393) [ 4968.016124] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3299 to 0x280000400:3361) [ 4973.053370] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4974.414575] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4992.507766] Lustre: DEBUG MARKER: == replay-single test 57: test recovery from llog for setattr op ========================================================== 03:01:37 (1787122897) [ 4996.767987] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4998.374044] Lustre: Failing over lustre-MDT0000 [ 4998.627909] Lustre: server umount lustre-MDT0000 complete [ 5026.598809] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x9b881f90d530ab38 [ 5033.245804] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5039.703120] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3299 to 0x280000400:3393) [ 5039.703200] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3395 to 0x240000400:3425) [ 5047.359189] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5048.810692] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5054.506660] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 5067.172791] Lustre: DEBUG MARKER: == replay-single test 58a: test recovery from llog for setattr op (test llog_gen_rec) ========================================================== 03:02:52 (1787122972) [ 5112.770900] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5114.570130] Lustre: Failing over lustre-MDT0000 [ 5115.116522] Lustre: server umount lustre-MDT0000 complete [ 5132.760409] LustreError: 126996:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.203.12@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 5132.778845] LustreError: 126996:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 3 previous similar messages [ 5134.968483] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:4676 to 0x240000400:4705) [ 5134.970228] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:4644 to 0x280000400:4673) [ 5137.264566] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5145.616950] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5147.276607] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5203.782146] Lustre: DEBUG MARKER: == replay-single test 58b: test replay of setxattr op ==== 03:05:09 (1787123109) [ 5208.333303] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5210.116150] Lustre: Failing over lustre-MDT0000 [ 5210.465592] Lustre: server umount lustre-MDT0000 complete [ 5232.770629] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5235.314362] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:4676 to 0x240000400:4737) [ 5235.315287] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:4675 to 0x280000400:4705) [ 5241.949570] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5243.425386] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5254.893900] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount FULL mgc.*.mgs_server_uuid 1475 0 [ 5256.488835] Lustre: DEBUG MARKER: mgc.*.mgs_server_uuid in FULL state after 0 sec [ 5262.906047] Lustre: DEBUG MARKER: == replay-single test 58c: resend/reconstruct setxattr op ========================================================== 03:06:08 (1787123168) [ 5269.474246] Lustre: *** cfs_fail_loc=123, val=2147483648*** [ 5271.535292] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 5271.539360] Lustre: Skipped 1 previous similar message [ 5271.543301] LustreError: 129958:0:(ldlm_lib.c:3346:target_send_reply_msg()) @@@ dropping reply req@ffff89df13a38850 x1873929063394048/t296352743435(0) o36->51083077-1bb3-4059-b062-e6ad68ec3b36@192.168.203.12@tcp:439/0 lens 66040/440 e 0 to 0 dl 1787123189 ref 1 fl Interpret:/600/0 rc 0/0 job:'setfattr.0' uid:0 gid:0 projid:0 [ 5287.979641] Lustre: 128863:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff89df067e8000 x1873929063394048/t296352743435(0) o36->51083077-1bb3-4059-b062-e6ad68ec3b36@192.168.203.12@tcp:455/0 lens 66040/440 e 0 to 0 dl 1787123205 ref 1 fl Interpret:/602/0 rc 0/0 job:'setfattr.0' uid:0 gid:0 projid:0 [ 5299.018616] Lustre: DEBUG MARKER: SKIP: replay-single test_59 skipping ALWAYS excluded test 59 [ 5301.371715] Lustre: DEBUG MARKER: == replay-single test 60: test llog post recovery init vs llog unlink ========================================================== 03:06:46 (1787123206) [ 5311.855799] LustreError: 130717:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 5311.860437] LustreError: 130717:0:(osd_handler.c:715:osd_ro()) Skipped 7 previous similar messages [ 5312.630299] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5315.720627] Lustre: Failing over lustre-MDT0000 [ 5316.080960] Lustre: server umount lustre-MDT0000 complete [ 5334.776569] LustreError: MGC192.168.203.112@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5334.787744] LustreError: Skipped 8 previous similar messages [ 5335.088577] Lustre: lustre-MDT0000: Not available for connect from 192.168.203.12@tcp (not set up) [ 5335.183833] 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 [ 5335.203501] Lustre: Skipped 17 previous similar messages [ 5335.419616] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 5335.430620] Lustre: Skipped 7 previous similar messages [ 5337.133388] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 5337.146910] Lustre: Skipped 7 previous similar messages [ 5338.368809] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 5338.380381] Lustre: Skipped 7 previous similar messages [ 5338.439641] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:4806 to 0x280000400:4833) [ 5338.441820] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:4839 to 0x240000400:4865) [ 5339.893963] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5340.660585] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 5340.668441] Lustre: Skipped 19 previous similar messages [ 5349.908457] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5351.687879] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5363.734327] Lustre: DEBUG MARKER: == replay-single test 61a: test race llog recovery vs llog cleanup ========================================================== 03:07:48 (1787123268) [ 5387.010941] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 5402.911729] Lustre: Failing over lustre-OST0000 [ 5402.974563] Lustre: server umount lustre-OST0000 complete [ 5405.287530] LustreError: lustre-OST0000-osc-MDT0000: operation ost_destroy to node 0@lo failed: rc = -107 [ 5405.311896] LustreError: 36656:0:(ldlm_lib.c:1192: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. [ 5405.312503] LustreError: Skipped 4 previous similar messages [ 5412.323186] LustreError: 6683:0:(ldlm_lib.c:1192: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. [ 5412.342086] LustreError: 6683:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 1 previous similar message [ 5417.444451] LustreError: 6685:0:(ldlm_lib.c:1192: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. [ 5430.257703] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5444.917440] Lustre: Failing over lustre-OST0000 [ 5444.942231] LustreError: 133854:0:(ldlm_lib.c:3004:target_stop_recovery_thread()) lustre-OST0000: Aborting recovery [ 5444.955613] Lustre: 133290:0:(ldlm_lib.c:2404:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 5444.962187] Lustre: 133290:0:(ldlm_lib.c:2404:target_recovery_overseer()) Skipped 2 previous similar messages [ 5444.969986] Lustre: 133290:0:(ldlm_lib.c:1914:abort_req_replay_queue()) @@@ aborted: req@ffff89df40d86300 x1873929080089344/t0(17179870644) o6->lustre-MDT0000-mdtlov_UUID@0@lo:616/0 lens 544/0 e 2 to 0 dl 1787123366 ref 1 fl Complete:/204/ffffffff rc 0/-1 job:'osp-syn-0-0.0' uid:0 gid:0 projid:4294967295 [ 5444.998729] LustreError: 133290:0:(ofd_obd.c:1324:ofd_iocontrol()) lustre-OST0000: iocontrol from 'tgt_recover_0' cmd=c00866c1 _IOWR('f', 193, 8) unrecognized: rc = -25 [ 5445.000653] LustreError: lustre-OST0000-osc-MDT0000: operation ost_destroy to node 0@lo failed: rc = -19 [ 5445.024273] LustreError: Skipped 3 previous similar messages [ 5445.037264] Lustre: lustre-OST0000: Not available for connect from 0@lo (stopping) [ 5445.111089] Lustre: server umount lustre-OST0000 complete [ 5450.221862] LustreError: 36657:0:(ldlm_lib.c:1192: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. [ 5450.256361] LustreError: 36657:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 1 previous similar message [ 5471.546290] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5475.489167] LustreError: 3307:0:(client.c:3435:ptlrpc_replay_interpret()) @@@ status 0, old was -19 req@ffff89df2721d500 x1873929080089344/t17179870644(17179870644) o6->lustre-OST0000-osc-MDT0000@0@lo:28/4 lens 544/432 e 3 to 0 dl 1787123401 ref 2 fl Interpret:RQU/204/0 rc 0/0 job:'osp-syn-0-0.0' uid:0 gid:0 projid:4294967295 [ 5483.150971] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 5485.083315] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 5525.772277] Lustre: DEBUG MARKER: == replay-single test 61b: test race mds llog sync vs llog cleanup ========================================================== 03:10:30 (1787123430) [ 5528.935744] Lustre: Failing over lustre-MDT0000 [ 5529.252570] Lustre: server umount lustre-MDT0000 complete [ 5549.092568] Lustre: 3309:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787123439/real 1787123439] req@ffff89df34956d80 x1873929080225536/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787123455 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5549.128567] Lustre: 3309:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 35 previous similar messages [ 5549.173369] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5234 to 0x280000400:5249) [ 5549.179932] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5266 to 0x240000400:5281) [ 5553.978801] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5569.561186] Lustre: Failing over lustre-MDT0000 [ 5569.979432] Lustre: server umount lustre-MDT0000 complete [ 5589.423187] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 5589.431484] Lustre: Skipped 7 previous similar messages [ 5590.151836] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5234 to 0x280000400:5281) [ 5590.154814] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5266 to 0x240000400:5313) [ 5594.317456] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5603.885443] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5605.548933] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5613.973182] Lustre: DEBUG MARKER: == replay-single test 61c: test race mds llog sync vs llog cleanup ========================================================== 03:11:59 (1787123519) [ 5628.215054] Lustre: Failing over lustre-OST0000 [ 5628.395906] Lustre: server umount lustre-OST0000 complete [ 5630.433541] LustreError: 36656:0:(ldlm_lib.c:1192: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. [ 5630.464416] LustreError: 36656:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 2 previous similar messages [ 5656.333827] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5669.355667] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 5671.814752] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 5685.758704] Lustre: DEBUG MARKER: == replay-single test 61d: error in llog_setup should cleanup the llog context correctly ========================================================== 03:13:10 (1787123590) [ 5688.710177] Lustre: Failing over lustre-MDT0000 [ 5689.280213] Lustre: server umount lustre-MDT0000 complete [ 5702.543802] Lustre: *** cfs_fail_loc=605, val=0*** [ 5702.546670] LustreError: 139871:0:(llog_obd.c:192:llog_setup()) MGS: ctxt 0 lop_setup=ffffffffc12994b0 failed: rc = -95 [ 5702.559713] LustreError: 139871:0:(obd_config.c:845:class_setup()) setup MGS failed (-95) [ 5702.564835] LustreError: 139871:0:(obd_mount.c:259:lustre_start_simple()) MGS setup error -95 [ 5702.574278] LustreError: 139871:0:(tgt_mount.c:116:server_deregister_mount()) MGS not registered [ 5702.579668] LustreError: Failed to start MGS 'MGS' (-95). Is the 'mgs' module loaded? [ 5702.585971] LustreError: 139871:0:(tgt_mount.c:2129:server_put_super()) no obd lustre-MDT0000 [ 5702.692640] Lustre: server umount lustre-MDT0000 complete [ 5702.694695] LustreError: 139871:0:(super25.c:179:lustre_fill_super()) llite: Unable to mount : rc = -95 [ 5719.258217] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5315 to 0x240000400:5345) [ 5719.259348] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5283 to 0x280000400:5313) [ 5722.963828] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5735.222564] Lustre: DEBUG MARKER: == replay-single test 62: don't mis-drop resent replay === 03:14:00 (1787123640) [ 5739.800760] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5743.909598] Lustre: Failing over lustre-MDT0000 [ 5744.299655] Lustre: server umount lustre-MDT0000 complete [ 5773.300640] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x9b881f90d5360436 [ 5779.371754] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5785.573777] Lustre: *** cfs_fail_loc=707, val=0*** [ 5801.969612] Lustre: lustre-MDT0000: Client 51083077-1bb3-4059-b062-e6ad68ec3b36 (at 192.168.203.12@tcp) reconnected, waiting for 1 clients in recovery for 0:53 [ 5802.633091] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5359 to 0x240000400:5377) [ 5802.633304] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5326 to 0x280000400:5345) [ 5808.464920] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5810.168590] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5820.138114] Lustre: DEBUG MARKER: == replay-single test 65a: AT: verify early replies ====== 03:15:25 (1787123725) [ 5851.331523] LustreError: 141576:0:(service.c:2558:ptlrpc_server_handle_request()) @@@ HIT req@ffff89df048c2a00 x1873929064273792/t0(0) o101->51083077-1bb3-4059-b062-e6ad68ec3b36@192.168.203.12@tcp:263/0 lens 664/0 e 0 to 0 dl 1787123768 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 5851.386993] LustreError: 141576:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a sleeping for 11000ms [ 5862.440150] LustreError: 141576:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a awake [ 5862.469417] LustreError: 141578:0:(service.c:2558:ptlrpc_server_handle_request()) @@@ HIT req@ffff89df10306680 x1873929064275200/t0(0) o35->51083077-1bb3-4059-b062-e6ad68ec3b36@192.168.203.12@tcp:281/0 lens 392/0 e 0 to 0 dl 1787123786 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 5864.832301] LustreError: 141575:0:(service.c:2558:ptlrpc_server_handle_request()) @@@ HIT req@ffff89df353ac000 x1873929064281088/t0(0) o101->51083077-1bb3-4059-b062-e6ad68ec3b36@192.168.203.12@tcp:317/0 lens 576/0 e 0 to 0 dl 1787123822 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'unlinkmany.0' uid:0 gid:0 projid:0 [ 5864.859943] LustreError: 141575:0:(service.c:2558:ptlrpc_server_handle_request()) Skipped 27 previous similar messages [ 5869.107090] LustreError: 36653:0:(service.c:2558:ptlrpc_server_handle_request()) @@@ HIT req@ffff89df353af100 x1873929080316032/t0(0) o6->lustre-MDT0000-mdtlov_UUID@0@lo:281/0 lens 544/0 e 0 to 0 dl 1787123786 ref 1 fl Interpret:/200/ffffffff rc 0/-1 job:'osp-syn-0-0.0' uid:0 gid:0 projid:4294967295 [ 5869.127871] LustreError: 36653:0:(service.c:2558:ptlrpc_server_handle_request()) Skipped 20 previous similar messages [ 5874.165234] LustreError: 34938:0:(service.c:2558:ptlrpc_server_handle_request()) @@@ HIT req@ffff89df4007b100 x1873929080317440/t0(0) o6->lustre-MDT0000-mdtlov_UUID@0@lo:286/0 lens 544/0 e 0 to 0 dl 1787123791 ref 1 fl Interpret:/200/ffffffff rc 0/-1 job:'osp-syn-1-0.0' uid:0 gid:0 projid:4294967295 [ 5874.198062] LustreError: 34938:0:(service.c:2558:ptlrpc_server_handle_request()) Skipped 7 previous similar messages [ 5882.375780] Lustre: DEBUG MARKER: == replay-single test 65b: AT: verify early replies on packed reply / bulk ========================================================== 03:16:27 (1787123787) [ 5913.622526] LustreError: 35646:0:(tgt_handler.c:2830:tgt_brw_write()) cfs_fail_timeout id 224 sleeping for 11000ms [ 5924.665534] LustreError: 35646:0:(tgt_handler.c:2830:tgt_brw_write()) cfs_fail_timeout id 224 awake [ 5934.033071] Lustre: DEBUG MARKER: == replay-single test 66a: AT: verify MDT service time adjusts with no early replies ========================================================== 03:17:19 (1787123839) [ 5963.050438] LustreError: 141576:0:(service.c:2558:ptlrpc_server_handle_request()) @@@ HIT req@ffff89df06de9500 x1873929064299136/t0(0) o101->51083077-1bb3-4059-b062-e6ad68ec3b36@192.168.203.12@tcp:375/0 lens 576/0 e 0 to 0 dl 1787123880 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 5963.077561] LustreError: 141576:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a sleeping for 5000ms [ 5968.104571] LustreError: 141576:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a awake [ 5981.080155] LustreError: 141575:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a awake [ 5981.105231] LustreError: 141989:0:(service.c:2558:ptlrpc_server_handle_request()) @@@ HIT req@ffff89df356a7b80 x1873929064321920/t0(0) o101->51083077-1bb3-4059-b062-e6ad68ec3b36@192.168.203.12@tcp:432/0 lens 664/0 e 0 to 0 dl 1787123937 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 5981.156824] LustreError: 141989:0:(service.c:2558:ptlrpc_server_handle_request()) Skipped 120 previous similar messages [ 6000.728628] Lustre: DEBUG MARKER: == replay-single test 66b: AT: verify net latency adjusts ========================================================== 03:18:25 (1787123905) [ 6096.115274] Lustre: DEBUG MARKER: == replay-single test 67a: AT: verify slow request processing doesn't induce reconnects ========================================================== 03:20:01 (1787124001) [ 6128.001870] LustreError: 142018:0:(service.c:2558:ptlrpc_server_handle_request()) @@@ HIT req@ffff89df09710700 x1873929064378112/t0(0) o101->51083077-1bb3-4059-b062-e6ad68ec3b36@192.168.203.12@tcp:540/0 lens 576/0 e 0 to 0 dl 1787124045 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 6128.036188] LustreError: 142018:0:(service.c:2558:ptlrpc_server_handle_request()) Skipped 100 previous similar messages [ 6128.062596] LustreError: 142018:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a sleeping for 400ms [ 6128.082056] LustreError: 142018:0:(service.c:2559:ptlrpc_server_handle_request()) Skipped 1 previous similar message [ 6128.536134] LustreError: 142018:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a awake [ 6144.150355] LustreError: 141575:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a sleeping for 400ms [ 6144.156684] LustreError: 141575:0:(service.c:2559:ptlrpc_server_handle_request()) Skipped 36 previous similar messages [ 6144.576102] LustreError: 141575:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a awake [ 6144.586224] LustreError: 141575:0:(service.c:2559:ptlrpc_server_handle_request()) Skipped 36 previous similar messages [ 6172.882474] LustreError: 36647:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout interrupted [ 6172.889403] LustreError: 36647:0:(service.c:2559:ptlrpc_server_handle_request()) Skipped 5 previous similar messages [ 6180.006591] Lustre: DEBUG MARKER: == replay-single test 67b: AT: verify instant slowdown doesn't induce reconnects ========================================================== 03:21:25 (1787124085) [ 6214.169798] Lustre: DEBUG MARKER: phase 2 [ 6224.988394] Lustre: DEBUG MARKER: == replay-single test 68: AT: verify slowing locks ======= 03:22:10 (1787124130) [ 6308.613915] Lustre: DEBUG MARKER: == replay-single test 70a: check multi client t-f ======== 03:23:32 (1787124212) [ 6310.473299] Lustre: DEBUG MARKER: SKIP: replay-single test_70a Need two or more clients, have 1 [ 6312.883963] Lustre: DEBUG MARKER: == replay-single test 70b: dbench 1mdts recovery; 1 clients ========================================================== 03:23:37 (1787124217) [ 6318.886444] Lustre: DEBUG MARKER: Started rundbench load pid=128738 ... [ 6323.976218] LustreError: 148418:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 6323.983698] LustreError: 148418:0:(osd_handler.c:715:osd_ro()) Skipped 2 previous similar messages [ 6325.096437] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 6328.297452] Lustre: DEBUG MARKER: test_70b fail mds1 1 times [ 6330.840218] Lustre: Failing over lustre-MDT0000 [ 6331.244442] Lustre: server umount lustre-MDT0000 complete [ 6350.677086] LustreError: MGC192.168.203.112@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 6350.693289] LustreError: Skipped 4 previous similar messages [ 6350.821977] 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 [ 6350.842468] Lustre: Skipped 11 previous similar messages [ 6350.848213] LustreError: 149071:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 6350.865026] LustreError: 149071:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 7 previous similar messages [ 6351.310436] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 6351.314749] Lustre: Skipped 3 previous similar messages [ 6351.392408] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 6351.403715] Lustre: Skipped 7 previous similar messages [ 6352.162603] Lustre: 3308:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787124242/real 1787124242] req@ffff89df04071880 x1873929080445568/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787124258 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6352.209278] Lustre: 3308:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 30 previous similar messages [ 6355.627142] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6356.454403] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 6356.464438] Lustre: Skipped 12 previous similar messages [ 6368.920616] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 6368.935215] Lustre: Skipped 7 previous similar messages [ 6369.607811] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 6369.620983] Lustre: Skipped 7 previous similar messages [ 6369.657735] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5480 to 0x240000400:5505) [ 6369.658628] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5427 to 0x280000400:5473) [ 6378.036836] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6380.257448] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6388.961650] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 6391.665479] Lustre: DEBUG MARKER: test_70b fail mds1 2 times [ 6393.646458] Lustre: Failing over lustre-MDT0000 [ 6393.895727] Lustre: server umount lustre-MDT0000 complete [ 6416.889047] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6431.302034] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5498 to 0x280000400:5537) [ 6431.305734] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5530 to 0x240000400:5569) [ 6438.566921] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6441.381825] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6470.725353] Lustre: DEBUG MARKER: == replay-single test 70c: tar 1mdts recovery ============ 03:26:16 (1787124376) [ 6596.899553] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 6609.264525] Lustre: DEBUG MARKER: test_70c fail mds1 1 times [ 6611.411178] Lustre: Failing over lustre-MDT0000 [ 6612.061682] Lustre: server umount lustre-MDT0000 complete [ 6637.037309] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6656.323064] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6163 to 0x280000400:6209) [ 6656.369751] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6195 to 0x240000400:6241) [ 6664.008239] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6666.083105] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6712.561673] Lustre: DEBUG MARKER: == replay-single test 70d: mkdir/rmdir striped dir 1mdts recovery ========================================================== 03:30:18 (1787124618) [ 6714.478195] Lustre: DEBUG MARKER: SKIP: replay-single test_70d needs >= 2 MDTs [ 6716.064351] Lustre: DEBUG MARKER: == replay-single test 70e: rename cross-MDT with random fails ========================================================== 03:30:21 (1787124621) [ 6717.657147] Lustre: DEBUG MARKER: SKIP: replay-single test_70e needs >= 2 MDTs [ 6719.256742] Lustre: DEBUG MARKER: == replay-single test 70f: OSS O_DIRECT recovery with 1 clients ========================================================== 03:30:24 (1787124624) [ 6727.338309] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 6729.898848] Lustre: DEBUG MARKER: test_70f failing OST 1 times [ 6731.785697] Lustre: Failing over lustre-OST0000 [ 6731.845732] Lustre: server umount lustre-OST0000 complete [ 6733.281413] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 6733.289157] LustreError: 12811:0:(ldlm_lib.c:1192: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. [ 6741.975887] LustreError: 36652:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.203.12@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 6741.999962] LustreError: 36652:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 3 previous similar messages [ 6756.390932] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6765.649247] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 6767.774455] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 6779.372265] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 6782.419093] Lustre: DEBUG MARKER: test_70f failing OST 2 times [ 6784.566871] Lustre: Failing over lustre-OST0000 [ 6784.647310] Lustre: server umount lustre-OST0000 complete [ 6785.512115] LustreError: 36652:0:(ldlm_lib.c:1192: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. [ 6785.537181] LustreError: 36652:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 2 previous similar messages [ 6814.384691] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6827.250986] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 6830.467982] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 6845.459242] Lustre: DEBUG MARKER: == replay-single test 71a: mkdir/rmdir striped dir with 2 mdts recovery ========================================================== 03:32:29 (1787124749) [ 6847.730679] Lustre: DEBUG MARKER: SKIP: replay-single test_71a needs >= 2 MDTs [ 6849.973360] Lustre: DEBUG MARKER: == replay-single test 73a: open(O_CREAT), unlink, replay, reconnect before open replay, close ========================================================== 03:32:34 (1787124754) [ 6854.574563] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 6857.331480] Lustre: Failing over lustre-MDT0000 [ 6857.606204] Lustre: server umount lustre-MDT0000 complete [ 6876.133387] Lustre: *** cfs_fail_loc=302, val=2147483648*** [ 6880.592931] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6891.528866] Lustre: lustre-MDT0000: Client 51083077-1bb3-4059-b062-e6ad68ec3b36 (at 192.168.203.12@tcp) reconnected, waiting for 1 clients in recovery for 0:54 [ 6891.736732] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6282 to 0x240000400:6305) [ 6891.740245] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6249 to 0x280000400:6273) [ 6897.498440] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6899.374323] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6908.771886] Lustre: DEBUG MARKER: == replay-single test 73b: open(O_CREAT), unlink, replay, reconnect at open_replay reply, close ========================================================== 03:33:33 (1787124813) [ 6913.087330] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 6916.110961] Lustre: Failing over lustre-MDT0000 [ 6916.411297] Lustre: server umount lustre-MDT0000 complete [ 6948.794687] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6958.093921] Lustre: *** cfs_fail_loc=157, val=2147483648*** [ 6958.102654] LustreError: 159266:0:(ldlm_lib.c:3346:target_send_reply_msg()) @@@ dropping reply req@ffff89df0778d880 x1873929070430464/t335007449091(335007449091) o101->51083077-1bb3-4059-b062-e6ad68ec3b36@192.168.203.12@tcp:615/0 lens 592/608 e 0 to 0 dl 1787124875 ref 1 fl Interpret:/604/0 rc 301/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 6958.306727] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 6958.315074] Lustre: Skipped 9 previous similar messages [ 6973.484571] Lustre: lustre-MDT0000: Client 51083077-1bb3-4059-b062-e6ad68ec3b36 (at 192.168.203.12@tcp) reconnected, waiting for 1 clients in recovery for 0:55 [ 6973.503852] Lustre: 159265:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff89df35671f80 x1873929070430464/t335007449091(335007449091) o101->51083077-1bb3-4059-b062-e6ad68ec3b36@192.168.203.12@tcp:631/0 lens 592/3488 e 0 to 0 dl 1787124891 ref 1 fl Interpret:/606/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 6973.588822] Lustre: lustre-MDT0000: Recovery over after 0:15, of 1 clients 1 recovered and 0 were evicted. [ 6973.597747] Lustre: Skipped 5 previous similar messages [ 6973.653521] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6249 to 0x280000400:6305) [ 6973.657255] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6307 to 0x240000400:6337) [ 6979.172690] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6980.434699] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6988.711844] Lustre: DEBUG MARKER: == replay-single test 74: Ensure applications don't fail waiting for OST recovery ========================================================== 03:34:54 (1787124894) [ 6992.122961] Lustre: Failing over lustre-OST0000 [ 6992.264268] Lustre: server umount lustre-OST0000 complete [ 6994.408989] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 6994.422351] 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 [ 6994.432353] Lustre: Skipped 11 previous similar messages [ 6994.442676] LustreError: 6684:0:(ldlm_lib.c:1192: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. [ 6994.458974] LustreError: 6684:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 7 previous similar messages [ 6996.110061] Lustre: Failing over lustre-MDT0000 [ 6996.329534] Lustre: server umount lustre-MDT0000 complete [ 7014.201463] LustreError: MGC192.168.203.112@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 7014.211493] LustreError: Skipped 4 previous similar messages [ 7014.653313] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 7014.659292] Lustre: Skipped 6 previous similar messages [ 7014.793430] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6249 to 0x280000400:6337) [ 7016.673140] Lustre: 3310:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787124907/real 1787124907] req@ffff89df0969a680 x1873929081257472/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787124923 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 7016.714016] Lustre: 3310:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 33 previous similar messages [ 7019.429678] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7028.602591] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 7028.613813] Lustre: Skipped 6 previous similar messages [ 7030.597825] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 7030.609361] Lustre: Skipped 6 previous similar messages [ 7030.614054] Lustre: lustre-OST0000: Denying connection for new client 44270887-5cf9-4f6c-b054-e931cc2ce178 (at 192.168.203.12@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:59 [ 7030.653638] Lustre: Skipped 11 previous similar messages [ 7034.009664] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6307 to 0x240000400:6369) [ 7036.402146] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7047.352562] Lustre: DEBUG MARKER: == replay-single test 80a: DNE: create remote dir, drop update rep from MDT0, fail MDT0 ========================================================== 03:35:52 (1787124952) [ 7048.850724] Lustre: DEBUG MARKER: SKIP: replay-single test_80a needs >= 2 MDTs [ 7050.799985] Lustre: DEBUG MARKER: == replay-single test 80b: DNE: create remote dir, drop update rep from MDT0, fail MDT1 ========================================================== 03:35:56 (1787124956) [ 7052.953228] Lustre: DEBUG MARKER: SKIP: replay-single test_80b needs >= 2 MDTs [ 7054.910105] Lustre: DEBUG MARKER: == replay-single test 80c: DNE: create remote dir, drop update rep from MDT1, fail MDT[0,1] ========================================================== 03:35:59 (1787124959) [ 7056.909659] Lustre: DEBUG MARKER: SKIP: replay-single test_80c needs >= 2 MDTs [ 7059.050979] Lustre: DEBUG MARKER: == replay-single test 80d: DNE: create remote dir, drop update rep from MDT1, fail 2 MDTs ========================================================== 03:36:03 (1787124963) [ 7060.606619] Lustre: DEBUG MARKER: SKIP: replay-single test_80d needs >= 2 MDTs [ 7062.477401] Lustre: DEBUG MARKER: == replay-single test 80e: DNE: create remote dir, drop MDT1 rep, fail MDT0 ========================================================== 03:36:07 (1787124967) [ 7064.488317] Lustre: DEBUG MARKER: SKIP: replay-single test_80e needs >= 2 MDTs [ 7066.499238] Lustre: DEBUG MARKER: == replay-single test 80f: DNE: create remote dir, drop MDT1 rep, fail MDT1 ========================================================== 03:36:11 (1787124971) [ 7068.433168] Lustre: DEBUG MARKER: SKIP: replay-single test_80f needs >= 2 MDTs [ 7070.339532] Lustre: DEBUG MARKER: == replay-single test 80g: DNE: create remote dir, drop MDT1 rep, fail MDT0, then MDT1 ========================================================== 03:36:15 (1787124975) [ 7071.936096] Lustre: DEBUG MARKER: SKIP: replay-single test_80g needs >= 2 MDTs [ 7073.758472] Lustre: DEBUG MARKER: == replay-single test 80h: DNE: create remote dir, drop MDT1 rep, fail 2 MDTs ========================================================== 03:36:18 (1787124978) [ 7075.380953] Lustre: DEBUG MARKER: SKIP: replay-single test_80h needs >= 2 MDTs [ 7077.093271] Lustre: DEBUG MARKER: == replay-single test 81a: DNE: unlink remote dir, drop MDT0 update rep, fail MDT1 ========================================================== 03:36:22 (1787124982) [ 7078.684224] Lustre: DEBUG MARKER: SKIP: replay-single test_81a needs >= 2 MDTs [ 7080.495080] Lustre: DEBUG MARKER: == replay-single test 81b: DNE: unlink remote dir, drop MDT0 update reply, fail MDT0 ========================================================== 03:36:25 (1787124985) [ 7082.141464] Lustre: DEBUG MARKER: SKIP: replay-single test_81b needs >= 2 MDTs [ 7083.700068] Lustre: DEBUG MARKER: == replay-single test 81c: DNE: unlink remote dir, drop MDT0 update reply, fail MDT0,MDT1 ========================================================== 03:36:29 (1787124989) [ 7085.317464] Lustre: DEBUG MARKER: SKIP: replay-single test_81c needs >= 2 MDTs [ 7087.108758] Lustre: DEBUG MARKER: == replay-single test 81d: DNE: unlink remote dir, drop MDT0 update reply, fail 2 MDTs ========================================================== 03:36:32 (1787124992) [ 7088.920710] Lustre: DEBUG MARKER: SKIP: replay-single test_81d needs >= 2 MDTs [ 7090.841938] Lustre: DEBUG MARKER: == replay-single test 81e: DNE: unlink remote dir, drop MDT1 req reply, fail MDT0 ========================================================== 03:36:35 (1787124995) [ 7092.651695] Lustre: DEBUG MARKER: SKIP: replay-single test_81e needs >= 2 MDTs [ 7094.561787] Lustre: DEBUG MARKER: == replay-single test 81f: DNE: unlink remote dir, drop MDT1 req reply, fail MDT1 ========================================================== 03:36:39 (1787124999) [ 7096.277415] Lustre: DEBUG MARKER: SKIP: replay-single test_81f needs >= 2 MDTs [ 7098.090429] Lustre: DEBUG MARKER: == replay-single test 81g: DNE: unlink remote dir, drop req reply, fail M0, then M1 ========================================================== 03:36:43 (1787125003) [ 7099.579830] Lustre: DEBUG MARKER: SKIP: replay-single test_81g needs >= 2 MDTs [ 7101.360452] Lustre: DEBUG MARKER: == replay-single test 81h: DNE: unlink remote dir, drop request reply, fail 2 MDTs ========================================================== 03:36:46 (1787125006) [ 7102.675491] Lustre: DEBUG MARKER: SKIP: replay-single test_81h needs >= 2 MDTs [ 7104.308910] Lustre: DEBUG MARKER: == replay-single test 84a: stale open during export disconnect ========================================================== 03:36:49 (1787125009) [ 7105.892455] Lustre: 163891:0:(genops.c:1795:obd_export_evict_by_uuid()) lustre-MDT0000: evicting 44270887-5cf9-4f6c-b054-e931cc2ce178 at adminstrative request [ 7115.626364] Lustre: DEBUG MARKER: == replay-single test 85a: check the cancellation of unused locks during recovery(IBITS) ========================================================== 03:37:00 (1787125020) [ 7123.585323] Lustre: Failing over lustre-MDT0000 [ 7124.042130] Lustre: server umount lustre-MDT0000 complete [ 7151.586329] LustreError: 3307:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff89df40d1d880 x1873929081292160/t0(0) o250->MGC192.168.203.112@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 [ 7157.904307] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7167.937159] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6389 to 0x280000400:6433) [ 7167.938594] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6421 to 0x240000400:6465) [ 7173.175348] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 7174.923911] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7182.962588] Lustre: DEBUG MARKER: == replay-single test 85b: check the cancellation of unused locks during recovery(EXTENT) ========================================================== 03:38:08 (1787125088) [ 7200.471495] Lustre: Failing over lustre-OST0000 [ 7200.739331] Lustre: lustre-OST0000: Not available for connect from 192.168.203.12@tcp (stopping) [ 7202.620047] Lustre: server umount lustre-OST0000 complete [ 7202.797195] LustreError: 36652:0:(ldlm_lib.c:1192: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. [ 7202.828130] LustreError: 36652:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 6 previous similar messages [ 7227.863392] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7238.794298] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 7240.723840] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 7250.993725] Lustre: DEBUG MARKER: == replay-single test 86: umount server after clear nid_stats should not hit LBUG ========================================================== 03:39:16 (1787125156) [ 7257.531577] Lustre: Failing over lustre-MDT0000 [ 7257.973616] Lustre: server umount lustre-MDT0000 complete [ 7265.204797] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6389 to 0x280000400:6465) [ 7265.214815] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6566 to 0x240000400:6593) [ 7269.791192] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7280.006493] Lustre: DEBUG MARKER: == replay-single test 87a: write replay ================== 03:39:45 (1787125185) [ 7284.451487] LustreError: 168339:0:(osd_handler.c:715:osd_ro()) lustre-OST0000: *** setting device osd-zfs read-only *** [ 7284.461626] LustreError: 168339:0:(osd_handler.c:715:osd_ro()) Skipped 6 previous similar messages [ 7285.385380] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 7288.718886] Lustre: Failing over lustre-OST0000 [ 7288.801032] Lustre: server umount lustre-OST0000 complete [ 7290.864823] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 7313.817788] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7323.150453] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 7324.825168] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 7333.190096] Lustre: DEBUG MARKER: == replay-single test 87b: write replay with changed data (checksum resend) ========================================================== 03:40:38 (1787125238) [ 7337.418302] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 7341.126478] Lustre: Failing over lustre-OST0000 [ 7341.163578] Lustre: server umount lustre-OST0000 complete [ 7343.088773] LustreError: 127826:0:(ldlm_lib.c:1192: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. [ 7343.127194] LustreError: 127826:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 13 previous similar messages [ 7363.588896] LustreError: lustre-OST0000: BAD WRITE CHECKSUM: from 12345-192.168.203.12@tcp inode [0x2000284a1:0x5:0x0] object 0x240000400:6595 extent [0-1048575]: client csum 14d495d0, server csum aa16127e [ 7369.967968] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7381.315703] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 7383.344457] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 7392.295702] Lustre: DEBUG MARKER: == replay-single test 88: MDS should not assign same objid to different files ========================================================== 03:41:37 (1787125297) [ 7395.921438] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 7399.536329] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 7405.857640] Lustre: Failing over lustre-MDT0000 [ 7406.121054] Lustre: server umount lustre-MDT0000 complete [ 7409.953979] LustreError: 127827:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787125316 with bad export cookie 11207242379624756696 [ 7420.386418] Lustre: Failing over lustre-OST0000 [ 7420.472372] Lustre: server umount lustre-OST0000 complete [ 7454.561942] LustreError: 3307:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff89df1d93f480 x1873929081381888/t0(0) o250->MGC192.168.203.112@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 [ 7460.069843] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7471.403869] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6504 to 0x280000400:6529) [ 7485.600063] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6596 to 0x240000400:6625) [ 7487.238148] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7505.765218] Lustre: DEBUG MARKER: == replay-single test 89: no disk space leak on late ost connection ========================================================== 03:43:30 (1787125410) [ 7523.062122] Lustre: Failing over lustre-OST0000 [ 7523.172495] Lustre: server umount lustre-OST0000 complete [ 7527.196266] Lustre: Failing over lustre-MDT0000 [ 7527.461713] Lustre: server umount lustre-MDT0000 complete [ 7547.725569] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6504 to 0x280000400:6561) [ 7550.865823] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7564.931475] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7567.527773] Lustre: lustre-OST0000: Denying connection for new client 30da3ec4-3c27-4225-9f7f-79a566a734ad (at 192.168.203.12@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 1:05 [ 7567.556470] Lustre: Skipped 1 previous similar message [ 7588.317220] Lustre: lustre-OST0000: Denying connection for new client 30da3ec4-3c27-4225-9f7f-79a566a734ad (at 192.168.203.12@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 0:45 [ 7588.340900] Lustre: Skipped 3 previous similar messages [ 7624.151996] Lustre: lustre-OST0000: Denying connection for new client 30da3ec4-3c27-4225-9f7f-79a566a734ad (at 192.168.203.12@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 0:09 [ 7624.168826] Lustre: Skipped 6 previous similar messages [ 7633.500364] Lustre: lustre-OST0000: recovery is timed out, evict stale exports [ 7633.506341] Lustre: 176245:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-OST0000: disconnect stale client adfe577a-b3ff-403f-b522-678b195eb91a@ [ 7633.523390] Lustre: lustre-OST0000: disconnecting 1 stale clients [ 7633.611268] Lustre: lustre-OST0000: Recovery over after 1:10, of 2 clients 1 recovered and 1 was evicted. [ 7633.612175] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 7633.619192] Lustre: Skipped 8 previous similar messages [ 7633.621929] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6636 to 0x240000400:6657) [ 7633.625779] Lustre: Skipped 13 previous similar messages [ 7636.991563] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 60 sec [ 7652.581069] Lustre: DEBUG MARKER: free_before: 7520256 free_after: 7520256 [ 7659.813194] Lustre: DEBUG MARKER: == replay-single test 90: lfs find identifies the missing striped file segments ========================================================== 03:46:04 (1787125564) [ 7664.235447] Lustre: Failing over lustre-OST0000 [ 7664.424731] Lustre: server umount lustre-OST0000 complete [ 7664.617255] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 7664.626896] 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 [ 7664.653759] Lustre: Skipped 11 previous similar messages [ 7664.661674] LustreError: 36651:0:(ldlm_lib.c:1192: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. [ 7664.684907] LustreError: 36651:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 39 previous similar messages [ 7684.439953] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 7684.448232] Lustre: Skipped 10 previous similar messages [ 7684.468368] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 7684.486105] Lustre: Skipped 8 previous similar messages [ 7685.546528] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 7685.553987] Lustre: Skipped 8 previous similar messages [ 7690.485049] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7701.044174] Lustre: DEBUG MARKER: == replay-single test 93a: replay + reconnect ============ 03:46:46 (1787125606) [ 7704.518678] Lustre: Failing over lustre-OST0000 [ 7704.619953] Lustre: server umount lustre-OST0000 complete [ 7724.215723] LustreError: 179329:0:(ldlm_lib.c:2905:target_recovery_thread()) cfs_fail_timeout id 715 sleeping for 40000ms [ 7724.226242] LustreError: 179329:0:(ldlm_lib.c:2905:target_recovery_thread()) Skipped 82 previous similar messages [ 7728.410722] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7730.147408] Lustre: *** cfs_fail_loc=715, val=40*** [ 7739.413492] Lustre: lustre-OST0000: Client 30da3ec4-3c27-4225-9f7f-79a566a734ad (at 192.168.203.12@tcp) reconnected, waiting for 2 clients in recovery for 1:25 [ 7740.384172] Lustre: 3307:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787125630/real 1787125630] req@ffff89df3f26c700 x1873929081455360/t0(0) o400->lustre-OST0000-osc-MDT0000@0@lo:28/4 lens 224/224 e 0 to 1 dl 1787125646 ref 1 fl Rpc:XQr/2c0/ffffffff rc 0/-1 job:'ldlm_lock_repla.0' uid:0 gid:0 projid:4294967295 [ 7740.430983] Lustre: 3307:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 23 previous similar messages [ 7740.438598] Lustre: lustre-OST0000: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnected, waiting for 2 clients in recovery for 1:24 [ 7745.504374] Lustre: *** cfs_fail_loc=715, val=40*** [ 7745.506587] Lustre: Skipped 1 previous similar message [ 7746.528403] Lustre: *** cfs_fail_loc=715, val=40*** [ 7755.736628] Lustre: lustre-OST0000: Client 30da3ec4-3c27-4225-9f7f-79a566a734ad (at 192.168.203.12@tcp) reconnected, waiting for 2 clients in recovery for 1:08 [ 7761.890411] Lustre: *** cfs_fail_loc=715, val=40*** [ 7764.304632] LustreError: 179329:0:(ldlm_lib.c:2905:target_recovery_thread()) cfs_fail_timeout id 715 awake [ 7764.311809] LustreError: 179329:0:(ldlm_lib.c:2905:target_recovery_thread()) Skipped 75 previous similar messages [ 7770.415906] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 7771.913748] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 7782.439886] Lustre: DEBUG MARKER: == replay-single test 93b: replay + reconnect on mds ===== 03:48:07 (1787125687) [ 7788.875220] Lustre: Failing over lustre-MDT0000 [ 7789.661591] Lustre: server umount lustre-MDT0000 complete [ 7807.456495] LustreError: MGC192.168.203.112@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 7807.470505] LustreError: Skipped 4 previous similar messages [ 7819.453277] LustreError: 180931:0:(ldlm_lib.c:2905:target_recovery_thread()) cfs_fail_timeout id 715 sleeping for 80000ms [ 7823.121595] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7825.889045] Lustre: *** cfs_fail_loc=715, val=80*** [ 7825.894792] Lustre: Skipped 1 previous similar message [ 7835.611992] Lustre: lustre-MDT0000: Client 30da3ec4-3c27-4225-9f7f-79a566a734ad (at 192.168.203.12@tcp) reconnected, waiting for 1 clients in recovery for 0:53 [ 7835.626268] Lustre: Skipped 1 previous similar message [ 7841.764394] Lustre: *** cfs_fail_loc=715, val=80*** [ 7851.995343] Lustre: lustre-MDT0000: Client 30da3ec4-3c27-4225-9f7f-79a566a734ad (at 192.168.203.12@tcp) reconnected, waiting for 1 clients in recovery for 0:37 [ 7858.144164] Lustre: *** cfs_fail_loc=715, val=80*** [ 7867.354071] Lustre: lustre-MDT0000: Client 30da3ec4-3c27-4225-9f7f-79a566a734ad (at 192.168.203.12@tcp) reconnected, waiting for 1 clients in recovery for 0:22 [ 7883.738123] Lustre: lustre-MDT0000: Client 30da3ec4-3c27-4225-9f7f-79a566a734ad (at 192.168.203.12@tcp) reconnected, waiting for 1 clients in recovery for 0:05 [ 7899.496168] LustreError: 180931:0:(ldlm_lib.c:2905:target_recovery_thread()) cfs_fail_timeout id 715 awake [ 7899.566965] Lustre: 180931:0:(ldlm_lib.c:2951:target_recovery_thread()) too long recovery - read logs [ 7899.575774] LustreError: dumping log to /tmp/lustre-log.1787125806.180931 [ 7899.723241] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6574 to 0x280000400:6593) [ 7899.731534] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6671 to 0x240000400:6689) [ 7904.995867] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 7906.599972] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7915.841669] Lustre: DEBUG MARKER: == replay-single test complete, duration 7612 sec ======== 03:50:21 (1787125821) [ 7917.351597] Lustre: DEBUG MARKER: === replay-single: start cleanup 03:50:22 (1787125822) === [ 7927.494044] Lustre: DEBUG MARKER: === replay-single: finish cleanup 03:50:32 (1787125832) === [ 7957.480061] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 7957.489501] Lustre: Skipped 1 previous similar message [ 7957.891951] Lustre: server umount lustre-MDT0000 complete [ 7962.786312] LustreError: 127827:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787125869 with bad export cookie 11207242379624769100 [ 7962.798425] LustreError: 127827:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 7962.883884] Lustre: server umount lustre-OST0000 complete [ 7967.093462] Lustre: server umount lustre-OST0001 complete [ 7980.850837] Lustre: DEBUG MARKER: oleg312-server.virtnet: executing unload_modules_local [ 7983.912816] Key type lgssc unregistered [ 7984.266379] LNet: 183068:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 7984.277102] LNetError: 183068:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 7985.319826] LNet: Removed LNI 192.168.203.112@tcp [ 7986.536153] Key type .llcrypt unregistered [ 7986.538200] Key type ._llcrypt unregistered