[ 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 505355489 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2400.000 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.001015] APIC: Switch to symmetric I/O mode setup [ 0.003270] x2apic enabled [ 0.004008] Switched APIC routing to physical x2apic. [ 0.005013] kvm-guest: setup PV IPIs [ 0.007873] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.008000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x22983777dd9, max_idle_ns: 440795300422 ns [ 0.008026] Calibrating delay loop (skipped) preset value.. 4800.00 BogoMIPS (lpj=2400000) [ 0.009011] pid_max: default: 32768 minimum: 301 [ 0.010178] LSM: Security Framework initializing [ 0.011059] Yama: becoming mindful. [ 0.012048] SELinux: Initializing. [ 0.013074] *** VALIDATE selinux *** [ 0.022203] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.028153] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.030091] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.031149] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.032150] *** VALIDATE tmpfs *** [ 0.034037] *** VALIDATE proc *** [ 0.035199] *** VALIDATE cgroup *** [ 0.036009] *** VALIDATE cgroup2 *** [ 0.037353] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.038164] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.039010] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.041029] Spectre V2 : User space: Vulnerable [ 0.042009] Speculative Store Bypass: Vulnerable [ 0.045617] debug: unmapping init [mem 0xffffffff95a59000-0xffffffff95a60fff] [ 0.047913] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.048771] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.049036] ... version: 2 [ 0.050019] ... bit width: 48 [ 0.051028] ... generic registers: 4 [ 0.052023] ... value mask: 0000ffffffffffff [ 0.053024] ... max period: 00007fffffffffff [ 0.054019] ... fixed-purpose events: 3 [ 0.055028] ... event mask: 000000070000000f [ 0.056399] rcu: Hierarchical SRCU implementation. [ 0.058620] smp: Bringing up secondary CPUs ... [ 0.059769] x86: Booting SMP configuration: [ 0.060023] .... node #0, CPUs: #1 #2 #3 [ 0.063527] smp: Brought up 1 node, 4 CPUs [ 0.065020] smpboot: Max logical packages: 1 [ 0.066022] smpboot: Total of 4 processors activated (19200.00 BogoMIPS) [ 0.145627] node 0 deferred pages initialised in 74ms [ 0.149009] devtmpfs: initialized [ 0.150273] x86/mm: Memory block size: 128MB [ 0.152887] gcov: version magic: 0x41383552 [ 0.154240] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.155082] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.156287] pinctrl core: initialized pinctrl subsystem [ 0.157189] [ 0.157889] ************************************************************* [ 0.158019] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.159016] ** ** [ 0.160019] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.161019] ** ** [ 0.162016] ** This means that this kernel is built to expose internal ** [ 0.163014] ** IOMMU data structures, which may compromise security on ** [ 0.164025] ** your system. ** [ 0.165015] ** ** [ 0.166016] ** If you see this message and you are not debugging the ** [ 0.167017] ** kernel, report this immediately to your vendor! ** [ 0.168016] ** ** [ 0.169013] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.170016] ************************************************************* [ 0.171767] NET: Registered protocol family 16 [ 0.172526] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.173068] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.174066] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.175478] cpuidle: using governor menu [ 0.178147] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.181510] PCI: Using configuration type 1 for base access [ 0.183144] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.193165] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.194040] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.196217] cryptd: max_cpu_qlen set to 1000 [ 0.199289] ACPI: Added _OSI(Module Device) [ 0.201025] ACPI: Added _OSI(Processor Device) [ 0.203033] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.204013] ACPI: Added _OSI(Processor Aggregator Device) [ 0.209677] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.218342] ACPI: Interpreter enabled [ 0.219076] ACPI: PM: (supports S0 S3 S4 S5) [ 0.221015] ACPI: Using IOAPIC for interrupt routing [ 0.223148] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.228520] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.238835] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.241045] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.244022] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.248113] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.252000] acpiphp: Slot [2] registered [ 0.254148] acpiphp: Slot [5] registered [ 0.256125] acpiphp: Slot [6] registered [ 0.257098] acpiphp: Slot [7] registered [ 0.258174] acpiphp: Slot [8] registered [ 0.260168] acpiphp: Slot [9] registered [ 0.262121] acpiphp: Slot [10] registered [ 0.263108] acpiphp: Slot [3] registered [ 0.264074] acpiphp: Slot [4] registered [ 0.265087] acpiphp: Slot [11] registered [ 0.267147] acpiphp: Slot [12] registered [ 0.268105] acpiphp: Slot [13] registered [ 0.270109] acpiphp: Slot [14] registered [ 0.271105] acpiphp: Slot [15] registered [ 0.272102] acpiphp: Slot [16] registered [ 0.274127] acpiphp: Slot [17] registered [ 0.276126] acpiphp: Slot [18] registered [ 0.277126] acpiphp: Slot [19] registered [ 0.278093] acpiphp: Slot [20] registered [ 0.280119] acpiphp: Slot [21] registered [ 0.281193] acpiphp: Slot [22] registered [ 0.283115] acpiphp: Slot [23] registered [ 0.284157] acpiphp: Slot [24] registered [ 0.286142] acpiphp: Slot [25] registered [ 0.287124] acpiphp: Slot [26] registered [ 0.289102] acpiphp: Slot [27] registered [ 0.290159] acpiphp: Slot [28] registered [ 0.291119] acpiphp: Slot [29] registered [ 0.293188] acpiphp: Slot [30] registered [ 0.294135] acpiphp: Slot [31] registered [ 0.296157] PCI host bridge to bus 0000:00 [ 0.297021] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.299088] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.301018] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.304024] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.306025] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.308023] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.310436] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.314461] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.318349] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.329874] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.334010] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.337027] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.340030] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.344031] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.346562] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.348771] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.351045] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.356066] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.361018] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.377029] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.382017] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.388626] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.405025] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.413023] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.430017] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.440542] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.453036] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.465027] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.500022] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.521962] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.529016] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.543023] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.560017] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.574063] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.589027] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.599024] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.631022] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.646341] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.656023] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.670025] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.696024] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 0.709556] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.717024] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.728024] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.744016] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 0.756094] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.759447] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.764484] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.768637] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.771470] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.776196] iommu: Default domain type: Passthrough [ 0.780715] SCSI subsystem initialized [ 0.782189] ACPI: bus type USB registered [ 0.784308] usbcore: registered new interface driver usbfs [ 0.785125] usbcore: registered new interface driver hub [ 0.787128] usbcore: registered new device driver usb [ 0.789239] pps_core: LinuxPPS API ver. 1 registered [ 0.791017] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.794161] PTP clock support registered [ 0.797127] EDAC MC: Ver: 3.0.0 [ 0.800072] PCI: Using ACPI for IRQ routing [ 0.802301] NetLabel: Initializing [ 0.803015] NetLabel: domain hash size = 128 [ 0.805017] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.806089] NetLabel: unlabeled traffic allowed by default [ 0.808167] vgaarb: loaded [ 0.810373] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.812016] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.820871] clocksource: Switched to clocksource kvm-clock [ 0.935022] VFS: Disk quotas dquot_6.6.0 [ 0.936543] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.939324] *** VALIDATE ramfs *** [ 0.940583] *** VALIDATE hugetlbfs *** [ 0.942163] pnp: PnP ACPI init [ 0.944750] pnp: PnP ACPI: found 6 devices [ 0.960509] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.964187] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.966518] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.968887] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.971630] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.974281] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.977617] NET: Registered protocol family 2 [ 0.980494] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.985975] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.990314] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.996978] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 1.000742] TCP: Hash tables configured (established 65536 bind 65536) [ 1.003657] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 1.006451] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 1.008855] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 1.011458] NET: Registered protocol family 1 [ 1.013795] RPC: Registered named UNIX socket transport module. [ 1.016295] RPC: Registered udp transport module. [ 1.018410] RPC: Registered tcp transport module. [ 1.020304] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 1.022936] NET: Registered protocol family 44 [ 1.024316] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 1.025856] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 1.027662] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 1.029299] PCI: CLS 0 bytes, default 64 [ 1.030679] Unpacking initramfs... [ 2.456594] debug: unmapping init [mem 0xffff93d27cc54000-0xffff93d27ffbffff] [ 2.460977] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.463541] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.467897] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x22983777dd9, max_idle_ns: 440795300422 ns [ 2.974907] Initialise system trusted keyrings [ 2.976829] Key type blacklist registered [ 2.978874] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.988515] zbud: loaded [ 2.991932] *** VALIDATE nfs *** [ 2.993247] *** VALIDATE nfs4 *** [ 2.995329] pstore: using deflate compression [ 2.999788] Platform Keyring initialized [ 3.120658] NET: Registered protocol family 38 [ 3.122563] Key type asymmetric registered [ 3.123924] Asymmetric key parser 'x509' registered [ 3.125426] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 3.128348] io scheduler mq-deadline registered [ 3.129967] io scheduler kyber registered [ 3.131169] io scheduler bfq registered [ 3.132683] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 3.135739] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 3.138281] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 3.141214] ACPI: Power Button [PWRF] [ 3.150425] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 3.159185] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 3.178605] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 3.188592] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 3.208731] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 3.236970] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.265191] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.270939] Non-volatile memory driver v1.3 [ 3.273250] Linux agpgart interface v0.103 [ 3.309825] virtio_blk virtio1: [vda] 146000 512-byte logical blocks (74.8 MB/71.3 MiB) [ 3.316250] vda: detected capacity change from 0 to 74752000 [ 3.334054] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.337680] vdb: detected capacity change from 0 to 1073741824 [ 3.352270] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.355368] vdc: detected capacity change from 0 to 2621440000 [ 3.368673] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.371556] vdd: detected capacity change from 0 to 2621440000 [ 3.388056] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.391806] vde: detected capacity change from 0 to 4294967296 [ 3.409114] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.411567] vdf: detected capacity change from 0 to 4294967296 [ 3.417228] libphy: Fixed MDIO Bus: probed [ 3.425213] usbcore: registered new interface driver usbserial_generic [ 3.427622] usbserial: USB Serial support registered for generic [ 3.429589] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.434348] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.436666] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.440070] mousedev: PS/2 mouse device common for all mice [ 3.442713] rtc_cmos 00:05: RTC can wake from S4 [ 3.450396] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.451189] rtc_cmos 00:05: registered as rtc0 [ 3.456440] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.460289] intel_pstate: CPU model not supported [ 3.463499] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.468560] hid: raw HID events driver (C) Jiri Kosina [ 3.471345] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.471442] usbcore: registered new interface driver usbhid [ 3.476520] usbhid: USB HID core driver [ 3.478637] drop_monitor: Initializing network drop monitor service [ 3.482128] Initializing XFRM netlink socket [ 3.485066] NET: Registered protocol family 10 [ 3.488582] Segment Routing with IPv6 [ 3.490697] NET: Registered protocol family 17 [ 3.493507] mpls_gso: MPLS GSO support [ 3.500176] RAS: Correctable Errors collector initialized. [ 3.503773] AVX version of gcm_enc/dec engaged. [ 3.505786] AES CTR mode by8 optimization enabled [ 3.596538] sched_clock: Marking stable (3596488982, 0)->(4531089084, -934600102) [ 3.600321] registered taskstats version 1 [ 3.602398] Loading compiled-in X.509 certificates [ 3.604600] zswap: loaded using pool lzo/zbud [ 3.634654] Key type big_key registered [ 3.650332] Key type encrypted registered [ 3.652194] ima: No TPM chip found, activating TPM-bypass! [ 3.654386] ima: Allocated hash algorithm: sha1 [ 3.656145] ima: No architecture policies found [ 3.657974] evm: Initialising EVM extended attributes: [ 3.659986] evm: security.selinux [ 3.661184] evm: security.ima [ 3.662426] evm: security.capability [ 3.663770] evm: HMAC attrs: 0x1 [ 3.666798] rtc_cmos 00:05: setting system clock to 2026-08-19 04:46:10 UTC (1787114770) [ 3.672975] debug: unmapping init [mem 0xffffffff96a03000-0xffffffff96bfffff] [ 3.676056] debug: unmapping init [mem 0xffffffff95782000-0xffffffff95a58fff] [ 3.685119] Write protecting the kernel read-only data: 28672k [ 3.690579] debug: unmapping init [mem 0xffffffff93e03000-0xffffffff93ffffff] [ 3.693572] debug: unmapping init [mem 0xffffffff94714000-0xffffffff947fffff] [ 3.736409] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 3.743161] systemd[1]: Detected virtualization kvm. [ 3.745687] systemd[1]: Detected architecture x86-64. [ 3.748100] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.772068] systemd[1]: No hostname configured. [ 3.774077] systemd[1]: Set hostname to . [ 3.776306] random: systemd: uninitialized urandom read (16 bytes read) [ 3.779181] systemd[1]: Initializing machine ID from random generator. [ 3.842863] random: ln: uninitialized urandom read (6 bytes read) [ 3.921337] random: systemd: uninitialized urandom read (16 bytes read) [ 3.923712] systemd[1]: Reached target Timers. [ OK ] Reached target Timers. [ 3.928492] systemd[1]: Reached target Slices. [ OK ] Reached target Slices. [ 3.934666] systemd[1]: Listening on Journal Socket (/dev/log). [ OK ] Listening on Journal Socket (/dev/log). [ OK ] Listening on Journal Socket. [ OK ] Started Memstrack Anylazing Service. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Initrd Root Device. [ OK ] Listening on udev Control Socket. [ OK ] Reached target Local File Systems. Starting Journal Service... Starting Create Volatile Files and Directories... Starting Apply Kernel Variables... Starting Setup Virtual Console... [ OK ] Reached target Swap. [ OK ] Listening on udev Kernel Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Paths. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Apply Kernel Variables. [ OK ] Started Setup Virtual Console. Starting dracut cmdline hook... Starting Create Static Device Nodes in /dev... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started Journal Service. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 4.603468] device-mapper: uevent: version 1.0.3 [ 4.606463] 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. [ 5.381047] random: fast init done [ 5.425082] virtio_net virtio0 ens2: renamed from eth0 [ 5.470251] scsi host0: ata_piix [ 5.475456] scsi host1: ata_piix [ 5.477270] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 5.480139] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 9.169617] dracut-initqueue[584]: RTNETLINK answers: File exists [ 10.175798] random: crng init done [ 10.178739] random: 7 urandom warning(s) missed due to ratelimiting Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Mounting /sysroot... [ 10.748531] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped target Timers. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Sockets. [ OK ] Stopped target Slices. [ OK ] Stopped target Paths. [ OK ] Stopped target System Initialization. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. Stopping udev Kernel Device Manager... [ OK ] Stopped target Swap. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Closed udev Kernel Socket. [ OK ] Closed udev Control Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 11.978538] printk: systemd: 26 output lines suppressed due to ratelimiting [ 12.270334] SELinux: Disabled at runtime. [ 12.338087] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 12.348703] systemd[1]: Detected virtualization kvm. [ 12.350966] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 12.927821] systemd[1]: initrd-switch-root.service: Succeeded. [ 12.932842] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 12.938859] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 12.945771] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 12.948608] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 12.955815] systemd[1]: Starting Journal Service... Starting Journal Service... [ 12.962417] systemd[1]: Created slice User and Session Slice. [ OK ] Created slice User and Session Slice. [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Listening on initctl Compatibility Named Pipe. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd File Systems. [ OK ] Stopped target Initrd Root File System. Mounting POSIX Message Queue File System... Starting Remount Root and Kernel File Systems... [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Listening on udev Control Socket. [ OK ] Created slice system-sshd\x2dkeygen.slice. Mounting Kernel Debug File System... [ OK ] Reached target Slices. [ OK ] Listening on udev Kernel Socket. Starting udev Coldplug all Devices... [ OK ] Listening on Process Core Dump Socket. Starting Apply Kernel Variables... [ OK ] Created slice system-getty.slice. [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Reached target rpc_pipefs.target. [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Reached target RPC Port Mapper. Activating swap /dev/disk/by-label/SWAP... Mounting Huge Pages File System... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Paths. [ OK ] Reached target Local Encrypted Volumes. [ 13.133031] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS [ OK ] Started Journal Service. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Mounted POSIX Message Queue File System. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Mounted Kernel Debug File System. [ OK ] Started Apply Kernel Variables. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Mounted Huge Pages File System. [ OK ] Reached target Swap. Starting Configure read-only root support... Starting Create Static Device Nodes in /dev... Starting Flush Journal to Persistent Storage... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started udev Coldplug all Devices. [ 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. [ 13.474872] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 13.796921] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 13.803982] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 13.959093] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 13.975346] EDAC sbridge: Ver: 1.1.2 [ 15.908494] Key type dns_resolver registered [ 16.226161] NFS: Registering the id_resolver key type [ 16.228102] Key type id_resolver registered [ 16.229663] Key type id_legacy registered [ 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 RPC Bind. [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Started Daily Cleanup of Temporary Directories. [ 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 Login Service... [ OK ] Started D-Bus System Message Bus. Starting Network Manager... Starting Restore /run/initramfs on shutdown... [ OK ] Reached target sshd-keygen.target. [ OK ] Started Login Service. [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Network Manager. [ OK ] Reached target Network. Starting Dynamic System Tuning Daemon... Starting GSSAPI Proxy Daemon... Starting OpenSSH server daemon... Starting Network Manager Wait Online... [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Started OpenSSH server daemon. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... Starting Hostname Service... [ OK ] Started Permit User Sessions. [ OK ] Started Command Scheduler. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Getty on tty1. [ OK ] Started Serial Getty on ttyS1. [ OK ] Reached target Login Prompts. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting System Logging Service... Starting Crash recovery kernel arming... Starting Notify NFS peers of a restart... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Starting Authorization Manager... [ OK ] Started Authorization Manager. [ OK ] Started Dynamic System Tuning Daemon. [ OK ] Reached target Multi-User System. [ OK ] Reached target Graphical Interface. Starting Update UTMP about System Runlevel Changes... [ OK ] Started Update UTMP about System Runlevel Changes. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg415-server login: [ 35.960385] spl: loading out-of-tree module taints kernel. [ 38.646757] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 43.770772] Key type ._llcrypt registered [ 43.772720] Key type .llcrypt registered [ 43.829669] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_hostid [ 53.092408] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing load_modules_local [ 53.671083] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 53.681929] alg: No test for adler32 (adler32-zlib) [ 54.729485] Lustre: Lustre: Build Version: 2.17.56_3_g13af17f [ 55.099887] LNet: Added LNI 192.168.204.115@tcp [8/256/0/180] [ 56.743180] Key type lgssc registered [ 59.172477] Lustre: Echo OBD driver; http://www.lustre.org/ [ 69.661292] vdc: vdc1 vdc9 [ 77.990917] vde: vde1 vde9 [ 78.013721] vde: vde1 vde9 [ 86.891875] vdf: vdf1 vdf9 [ 109.057762] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing load_modules_local [ 112.839632] hrtimer: interrupt took 4165353 ns [ 119.522722] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 120.772821] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 121.017686] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 121.139612] Lustre: lustre-MDT0000: new disk, initializing [ 121.602098] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 121.664226] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 127.498315] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 132.431171] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 139.601343] Lustre: lustre-OST0000: new disk, initializing [ 139.608348] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 139.620547] Lustre: Skipped 1 previous similar message [ 139.856114] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 147.189746] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 149.555165] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:0:ost [ 149.582036] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:0:ost] [ 149.869431] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x240000400 [ 160.756698] Lustre: lustre-OST0001: new disk, initializing [ 160.762919] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 160.964246] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 166.755820] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:1:ost [ 166.775264] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:1:ost] [ 166.969755] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x280000400 [ 169.153634] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 182.030507] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 191.297437] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 198.339725] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing check_logdir /tmp/testlogs/ [ 203.960069] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing yml_node [ 210.196987] Lustre: DEBUG MARKER: Client: 2.17.56.3 [ 213.571601] Lustre: DEBUG MARKER: MDS: 2.17.56.3 [ 217.404682] Lustre: DEBUG MARKER: OSS: 2.17.56.3 [ 219.813454] Lustre: DEBUG MARKER: -----============= acceptance-small: replay-single ============----- Wed Aug 19 00:49:43 EDT 2026 [ 241.463918] Lustre: DEBUG MARKER: excepting tests: 59 36 [ 243.624284] Lustre: DEBUG MARKER: === replay-single: start setup 00:50:08 (1787115008) === [ 250.625250] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing check_config_client /mnt/lustre [ 269.907360] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 274.151289] Lustre: 11134:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 279.302342] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 284.012186] Lustre: DEBUG MARKER: === replay-single: finish setup 00:50:48 (1787115048) === [ 286.297506] Lustre: DEBUG MARKER: == replay-single test 0a: empty replay =================== 00:50:50 (1787115050) [ 289.877618] LustreError: 11631:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 290.934587] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 293.051721] Lustre: Failing over lustre-MDT0000 [ 293.352843] Lustre: server umount lustre-MDT0000 complete [ 310.751995] Lustre: 3279:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787115061/real 1787115061] req@ffff93d2edb57480 x1873925710604672/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787115077 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 310.764475] 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 [ 310.788177] Lustre: 3279:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 310.788452] LustreError: MGC192.168.204.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 310.827920] Lustre: Skipped 1 previous similar message [ 315.935478] Lustre: 3279:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787115066/real 1787115066] req@ffff93d2eea87b80 x1873925710605184/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787115082 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 315.967693] Lustre: 3279:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 320.992462] Lustre: 3282:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787115071/real 1787115071] req@ffff93d2edb54e00 x1873925710605440/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787115087 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 321.039749] Lustre: 3282:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 321.504669] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 326.438116] Lustre: 3281:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787115076/real 1787115076] req@ffff93d2e58ad500 x1873925710605952/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787115092 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 326.462390] Lustre: 3281:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 327.094147] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 335.247418] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 335.377931] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 335.663875] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 342.552848] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 344.452943] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 353.969529] Lustre: DEBUG MARKER: == replay-single test 0b: ensure object created after recover exists. (3284) ========================================================== 00:51:58 (1787115118) [ 356.181783] Lustre: Failing over lustre-OST0000 [ 356.277242] Lustre: server umount lustre-OST0000 complete [ 356.337634] 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 [ 361.439769] LustreError: 11617: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. [ 361.465437] LustreError: 11617:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 3 previous similar messages [ 365.970589] LustreError: 6574:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.204.15@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 371.091654] LustreError: 6573:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.204.15@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 371.111214] LustreError: 6573:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 1 previous similar message [ 375.744541] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 376.218479] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 377.681625] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 377.685286] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 377.708632] Lustre: Skipped 1 previous similar message [ 383.885814] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 395.390697] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 397.218971] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 406.890318] Lustre: DEBUG MARKER: == replay-single test 0c: check replay-barrier =========== 00:52:51 (1787115171) [ 410.057745] LustreError: 14576:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 411.239943] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 413.648670] Lustre: Failing over lustre-MDT0000 [ 414.108686] Lustre: server umount lustre-MDT0000 complete [ 432.119442] LustreError: MGC192.168.204.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 432.698352] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 433.504212] Lustre: 3279:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787115183/real 1787115183] req@ffff93d2e5888380 x1873925710637440/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787115199 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 433.516622] Lustre: 3279:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 433.521093] 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 [ 433.529718] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 437.319609] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 442.104791] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 442.117654] Lustre: lustre-MDT0000: Denying connection for new client 7696a68b-38d1-40e8-9a42-a5f926ba00ab (at 192.168.204.15@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 1:00 [ 442.721755] Lustre: 3281:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787115193/real 1787115193] req@ffff93d2d8659180 x1873925710638208/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787115209 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 442.775149] Lustre: 3281:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 447.369155] Lustre: lustre-MDT0000: Denying connection for new client 7696a68b-38d1-40e8-9a42-a5f926ba00ab (at 192.168.204.15@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:55 [ 452.487993] Lustre: lustre-MDT0000: Denying connection for new client 7696a68b-38d1-40e8-9a42-a5f926ba00ab (at 192.168.204.15@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:50 [ 457.607726] Lustre: lustre-MDT0000: Denying connection for new client 7696a68b-38d1-40e8-9a42-a5f926ba00ab (at 192.168.204.15@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:44 [ 462.735890] Lustre: lustre-MDT0000: Denying connection for new client 7696a68b-38d1-40e8-9a42-a5f926ba00ab (at 192.168.204.15@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:39 [ 472.967746] Lustre: lustre-MDT0000: Denying connection for new client 7696a68b-38d1-40e8-9a42-a5f926ba00ab (at 192.168.204.15@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:29 [ 472.991667] Lustre: Skipped 1 previous similar message [ 493.448130] Lustre: lustre-MDT0000: Denying connection for new client 7696a68b-38d1-40e8-9a42-a5f926ba00ab (at 192.168.204.15@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:09 [ 493.468695] Lustre: Skipped 3 previous similar messages [ 502.501042] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 502.503785] Lustre: 15170:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 79d85913-e249-482f-a0f5-ee37734128ed@ [ 502.550714] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 502.668451] Lustre: lustre-MDT0000: Recovery over after 1:00, of 1 clients 0 recovered and 1 was evicted. [ 502.762184] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:44 to 0x280000400:65) [ 502.771243] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:44 to 0x240000400:65) [ 514.879656] Lustre: DEBUG MARKER: == replay-single test 0d: expired recovery with no clients ========================================================== 00:54:39 (1787115279) [ 517.662262] LustreError: 15906:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 518.559394] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 520.250758] Lustre: Failing over lustre-MDT0000 [ 520.763857] Lustre: server umount lustre-MDT0000 complete [ 537.055142] Lustre: 3281:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787115287/real 1787115287] req@ffff93d2c7560380 x1873925710662528/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787115303 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 537.065530] 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 [ 537.105268] Lustre: 3281:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 4 previous similar messages [ 537.131770] Lustre: Skipped 2 previous similar messages [ 540.245683] LustreError: MGC192.168.204.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 540.790690] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 546.181550] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 546.732498] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 546.744503] Lustre: Skipped 1 previous similar message [ 548.978022] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 548.982963] Lustre: lustre-MDT0000: Denying connection for new client 4913e0be-d780-41d1-b675-48bb693774d0 (at 192.168.204.15@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:59 [ 548.991875] Lustre: Skipped 1 previous similar message [ 608.500334] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 608.504403] Lustre: 16502:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 7696a68b-38d1-40e8-9a42-a5f926ba00ab@ [ 608.512940] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 608.599116] Lustre: lustre-MDT0000: Recovery over after 1:00, of 1 clients 0 recovered and 1 was evicted. [ 608.634788] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:44 to 0x280000400:97) [ 608.640280] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:44 to 0x240000400:97) [ 622.148378] Lustre: DEBUG MARKER: == replay-single test 1: simple create =================== 00:56:26 (1787115386) [ 625.748798] LustreError: 17240:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 626.853234] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 629.214608] Lustre: Failing over lustre-MDT0000 [ 629.578595] Lustre: server umount lustre-MDT0000 complete [ 646.539668] LustreError: MGC192.168.204.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 646.992659] 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 [ 647.013550] Lustre: Skipped 1 previous similar message [ 647.239799] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 647.322185] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 648.482672] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 648.634767] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 648.688923] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:44 to 0x280000400:129) [ 648.691034] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:44 to 0x240000400:129) [ 650.090989] Lustre: 3280:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787115400/real 1787115400] req@ffff93d2e588a300 x1873925710687488/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787115416 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 650.137088] Lustre: 3280:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 6 previous similar messages [ 652.080593] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 652.273937] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 652.287498] Lustre: Skipped 1 previous similar message [ 661.850735] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 663.528647] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 673.369949] Lustre: DEBUG MARKER: == replay-single test 2a: touch ========================== 00:57:17 (1787115437) [ 676.941290] LustreError: 18791:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 678.245026] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 680.748822] Lustre: Failing over lustre-MDT0000 [ 681.317185] Lustre: server umount lustre-MDT0000 complete [ 698.271336] 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 [ 699.173938] LustreError: MGC192.168.204.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 709.344245] LustreError: 3278:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff93d2ed7b7800 x1873925710705408/t0(0) o250->MGC192.168.204.115@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 0 ref 1 fl Rpc:NQU/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 709.516517] Lustre: lustre-MDT0000: Not available for connect from 192.168.204.15@tcp (not set up) [ 709.866402] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 711.409052] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 711.695809] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 711.733503] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:131 to 0x240000400:161) [ 711.734212] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:44 to 0x280000400:161) [ 714.719401] Lustre: 3281:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787115465/real 1787115465] req@ffff93d2c7561c00 x1873925710704768/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787115481 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 714.789324] Lustre: 3281:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 12 previous similar messages [ 716.128915] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 723.949031] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 723.960278] Lustre: Skipped 1 previous similar message [ 726.189528] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 727.952282] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 736.282914] Lustre: DEBUG MARKER: == replay-single test 2b: touch ========================== 00:58:20 (1787115500) [ 739.601479] LustreError: 20324:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 740.566397] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 742.794276] Lustre: Failing over lustre-MDT0000 [ 743.166903] Lustre: server umount lustre-MDT0000 complete [ 761.504246] LustreError: MGC192.168.204.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 761.813189] Lustre: lustre-MDT0000: Not available for connect from 192.168.204.15@tcp (not set up) [ 761.909126] 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 [ 761.923454] Lustre: Skipped 2 previous similar messages [ 762.022308] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 762.026926] Lustre: Skipped 1 previous similar message [ 762.091417] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 763.681309] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 763.911453] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 763.975499] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:163 to 0x280000400:193) [ 763.976407] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:131 to 0x240000400:193) [ 766.352300] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 767.469946] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 767.478042] Lustre: Skipped 1 previous similar message [ 776.720990] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 778.268710] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 786.840333] Lustre: DEBUG MARKER: == replay-single test 2c: setstripe replay =============== 00:59:11 (1787115551) [ 790.452622] LustreError: 21864:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 791.348870] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 793.477593] Lustre: Failing over lustre-MDT0000 [ 793.900565] Lustre: server umount lustre-MDT0000 complete [ 813.820731] LustreError: MGC192.168.204.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 814.356338] 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 [ 814.381859] Lustre: lustre-MDT0000: Not available for connect from 0@lo (not set up) [ 814.808054] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 819.673697] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 819.683512] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 819.686504] Lustre: Skipped 1 previous similar message [ 822.153864] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 822.255374] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 822.281638] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:225) [ 822.284714] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:225) [ 828.964086] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 830.525085] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 841.025593] Lustre: DEBUG MARKER: == replay-single test 2d: setdirstripe replay ============ 01:00:05 (1787115605) [ 844.016347] LustreError: 23399:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 845.021817] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 847.004501] Lustre: Failing over lustre-MDT0000 [ 847.401621] Lustre: server umount lustre-MDT0000 complete [ 866.356697] LustreError: MGC192.168.204.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 866.826843] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 867.680376] Lustre: 3282:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787115617/real 1787115617] req@ffff93d2f53d8700 x1873925710752896/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787115633 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 867.694353] Lustre: 3282:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 16 previous similar messages [ 871.770688] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 873.548217] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:257) [ 873.555737] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:257) [ 883.850064] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 885.570508] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 895.906156] Lustre: DEBUG MARKER: == replay-single test 2e: O_CREAT|O_EXCL create replay === 01:01:00 (1787115660) [ 897.045264] Lustre: *** cfs_fail_loc=13b, val=315*** [ 897.059350] Lustre: *** cfs_fail_loc=13b, val=2147483648*** [ 897.066404] LustreError: 23956:0:(ldlm_lib.c:3345:target_send_reply_msg()) @@@ dropping reply req@ffff93d2d865b480 x1873925701230080/t38654705666(0) o35->4913e0be-d780-41d1-b675-48bb693774d0@192.168.204.15@tcp:480/0 lens 392/456 e 0 to 0 dl 1787115680 ref 1 fl Interpret:/600/0 rc 0/0 job:'openfile.0' uid:0 gid:0 projid:0 [ 901.842670] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 904.004211] Lustre: Failing over lustre-MDT0000 [ 904.124908] Lustre: lustre-MDT0000: Not available for connect from 192.168.204.15@tcp (stopping) [ 904.132021] Lustre: Skipped 1 previous similar message [ 904.336116] Lustre: server umount lustre-MDT0000 complete [ 922.465418] 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 [ 922.489225] Lustre: Skipped 4 previous similar messages [ 922.670256] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 922.674569] Lustre: Skipped 2 previous similar messages [ 922.804422] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 924.555116] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 924.561832] Lustre: Skipped 1 previous similar message [ 924.677844] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 924.691740] Lustre: Skipped 1 previous similar message [ 924.737706] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:289) [ 924.743283] Lustre: 25553:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff93d2edb56a00 x1873925701230080/t38654705666(0) o35->4913e0be-d780-41d1-b675-48bb693774d0@192.168.204.15@tcp:508/0 lens 392/456 e 0 to 0 dl 1787115708 ref 1 fl Interpret:/602/0 rc 0/0 job:'openfile.0' uid:0 gid:0 projid:0 [ 924.743336] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:289) [ 927.715686] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 927.724341] Lustre: Skipped 3 previous similar messages [ 928.120419] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 938.320930] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 939.968329] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 949.215895] Lustre: DEBUG MARKER: == replay-single test 3a: replay failed open(O_DIRECTORY) ========================================================== 01:01:53 (1787115713) [ 952.669586] LustreError: 26533:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 952.673781] LustreError: 26533:0:(osd_handler.c:720:osd_ro()) Skipped 1 previous similar message [ 953.801995] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 956.028986] Lustre: Failing over lustre-MDT0000 [ 956.459687] Lustre: server umount lustre-MDT0000 complete [ 974.030398] LustreError: MGC192.168.204.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 974.039289] LustreError: Skipped 1 previous similar message [ 974.710616] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 976.181292] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:321) [ 976.185792] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:321) [ 978.419154] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 988.969824] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 991.008895] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1000.367850] Lustre: DEBUG MARKER: == replay-single test 3b: replay failed open -ENOMEM ===== 01:02:44 (1787115764) [ 1005.979564] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1007.103632] Lustre: *** cfs_fail_loc=114, val=0*** [ 1009.982836] Lustre: Failing over lustre-MDT0000 [ 1010.444440] Lustre: server umount lustre-MDT0000 complete [ 1036.261814] LustreError: 3278:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff93d2f46bb480 x1873925710803456/t0(0) o250->MGC192.168.204.115@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 0 ref 1 fl Rpc:NQU/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1037.047579] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1037.388226] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:353) [ 1037.393178] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:353) [ 1042.054565] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1051.175426] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1052.683359] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1061.356891] Lustre: DEBUG MARKER: == replay-single test 3c: replay failed open -ENOMEM ===== 01:03:45 (1787115825) [ 1065.176697] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1066.040445] Lustre: *** cfs_fail_loc=128, val=0*** [ 1068.975259] Lustre: Failing over lustre-MDT0000 [ 1069.389723] Lustre: server umount lustre-MDT0000 complete [ 1087.951913] 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 [ 1087.967111] Lustre: Skipped 5 previous similar messages [ 1089.600635] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1089.617452] Lustre: Skipped 2 previous similar messages [ 1089.741123] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1089.747606] Lustre: Skipped 2 previous similar messages [ 1089.790360] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:385) [ 1089.793549] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:385) [ 1093.115552] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 1093.138769] Lustre: Skipped 5 previous similar messages [ 1093.337187] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1103.120679] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1105.112539] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1113.733469] Lustre: DEBUG MARKER: == replay-single test 4a: |x| 10 open(O_CREAT)s ========== 01:04:38 (1787115878) [ 1116.656629] LustreError: 31335:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 1116.669291] LustreError: 31335:0:(osd_handler.c:720:osd_ro()) Skipped 2 previous similar messages [ 1117.585612] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1120.077666] Lustre: Failing over lustre-MDT0000 [ 1120.520179] Lustre: server umount lustre-MDT0000 complete [ 1138.351621] LustreError: MGC192.168.204.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1138.360415] LustreError: Skipped 2 previous similar messages [ 1139.061118] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1139.069946] Lustre: Skipped 1 previous similar message [ 1139.746577] Lustre: 3279:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787115890/real 1787115890] req@ffff93d2c345d500 x1873925710833920/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787115906 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1139.782275] Lustre: 3279:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 40 previous similar messages [ 1140.147175] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:391 to 0x240000400:417) [ 1140.150384] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:391 to 0x280000400:417) [ 1144.722678] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1155.183871] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1156.637693] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1165.523332] Lustre: DEBUG MARKER: == replay-single test 4b: |x| rm 10 files ================ 01:05:30 (1787115930) [ 1169.509859] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1171.621066] Lustre: Failing over lustre-MDT0000 [ 1171.968459] Lustre: server umount lustre-MDT0000 complete [ 1201.148946] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1201.163603] Lustre: Skipped 4 previous similar messages [ 1205.364250] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1215.294487] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:423 to 0x240000400:449) [ 1215.295979] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:423 to 0x280000400:449) [ 1222.451233] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1224.383993] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1233.054952] Lustre: DEBUG MARKER: == replay-single test 5: |x| 220 open(O_CREAT) =========== 01:06:37 (1787115997) [ 1236.885322] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1245.112429] Lustre: Failing over lustre-MDT0000 [ 1245.518840] Lustre: server umount lustre-MDT0000 complete [ 1273.493426] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1273.503245] Lustre: Skipped 1 previous similar message [ 1279.099616] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1289.527826] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:577) [ 1289.531346] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:577) [ 1296.095254] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1297.916219] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1324.792198] Lustre: DEBUG MARKER: == replay-single test 6a: mkdir + contained create ======= 01:08:09 (1787116089) [ 1329.270576] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1331.682106] Lustre: Failing over lustre-MDT0000 [ 1332.058230] Lustre: server umount lustre-MDT0000 complete [ 1350.111215] 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 [ 1350.128056] Lustre: Skipped 7 previous similar messages [ 1359.329100] LustreError: 3278:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff93d1c4535500 x1873925710948352/t0(0) o250->MGC192.168.204.115@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 0 ref 1 fl Rpc:NQU/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1364.896603] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1373.578086] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1373.590194] Lustre: Skipped 3 previous similar messages [ 1373.825532] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1373.834609] Lustre: Skipped 3 previous similar messages [ 1373.878596] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:609) [ 1373.880488] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:609) [ 1374.252548] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 1374.256769] Lustre: Skipped 7 previous similar messages [ 1380.427217] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1382.557295] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1393.850911] Lustre: DEBUG MARKER: == replay-single test 6b: |X| rmdir ====================== 01:09:18 (1787116158) [ 1397.094881] LustreError: 37558:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 1397.101589] LustreError: 37558:0:(osd_handler.c:720:osd_ro()) Skipped 3 previous similar messages [ 1398.079820] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1400.341447] Lustre: Failing over lustre-MDT0000 [ 1400.741208] Lustre: server umount lustre-MDT0000 complete [ 1419.604430] LustreError: MGC192.168.204.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1419.622577] LustreError: Skipped 3 previous similar messages [ 1420.921084] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:641) [ 1420.928295] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:641) [ 1425.117084] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1435.227481] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1436.639576] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1445.425170] Lustre: DEBUG MARKER: == replay-single test 7: mkdir |X| contained create ====== 01:10:09 (1787116209) [ 1449.212899] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1450.896219] Lustre: Failing over lustre-MDT0000 [ 1450.993953] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1451.008812] Lustre: Skipped 1 previous similar message [ 1451.220808] Lustre: server umount lustre-MDT0000 complete [ 1476.081993] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1477.262742] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:673) [ 1477.279723] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:673) [ 1486.590070] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1488.389161] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1496.951578] Lustre: DEBUG MARKER: == replay-single test 8: creat open |X| close ============ 01:11:01 (1787116261) [ 1501.312880] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1503.828587] Lustre: Failing over lustre-MDT0000 [ 1504.315416] Lustre: server umount lustre-MDT0000 complete [ 1522.640504] Lustre: lustre-MDT0000: Not available for connect from 0@lo (not set up) [ 1522.653048] Lustre: Skipped 1 previous similar message [ 1523.628762] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:705) [ 1523.635642] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:705) [ 1529.017886] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1539.530453] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1541.520909] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1550.270980] Lustre: DEBUG MARKER: == replay-single test 9: |X| create (same inum/gen) ====== 01:11:54 (1787116314) [ 1554.628667] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1556.791020] Lustre: Failing over lustre-MDT0000 [ 1557.131930] Lustre: server umount lustre-MDT0000 complete [ 1584.609903] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xa7821dffd2f1008e [ 1585.143665] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1585.154795] Lustre: Skipped 4 previous similar messages [ 1585.714139] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:737) [ 1585.715265] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:737) [ 1590.243763] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1599.978625] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1601.430414] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1609.531107] Lustre: DEBUG MARKER: == replay-single test 10: create |X| rename unlink ======= 01:12:54 (1787116374) [ 1613.284126] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1615.088391] Lustre: Failing over lustre-MDT0000 [ 1615.470645] Lustre: server umount lustre-MDT0000 complete [ 1638.875413] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1643.103808] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:769) [ 1643.115753] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:769) [ 1649.847698] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1651.589188] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1660.812901] Lustre: DEBUG MARKER: == replay-single test 11: create open write rename |X| create-old-name read ========================================================== 01:13:45 (1787116425) [ 1665.671349] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1667.752536] Lustre: Failing over lustre-MDT0000 [ 1668.091744] Lustre: server umount lustre-MDT0000 complete [ 1685.983109] Lustre: 3282:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787116436/real 1787116436] req@ffff93d1c47ce680 x1873925711048192/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787116452 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1686.005734] Lustre: 3282:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 61 previous similar messages [ 1700.571976] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1710.647296] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:771 to 0x280000400:801) [ 1710.651176] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:771 to 0x240000400:801) [ 1715.792091] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1717.339097] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1725.301455] Lustre: DEBUG MARKER: == replay-single test 12: open, unlink |X| close ========= 01:14:49 (1787116489) [ 1729.635538] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1732.005381] Lustre: Failing over lustre-MDT0000 [ 1732.359922] Lustre: server umount lustre-MDT0000 complete [ 1750.837294] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1750.841983] Lustre: Skipped 8 previous similar messages [ 1751.645150] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:771 to 0x280000400:833) [ 1751.648123] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:771 to 0x240000400:833) [ 1755.898176] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1765.466659] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1767.288187] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1775.141306] Lustre: DEBUG MARKER: == replay-single test 13: open chmod 0 |x| write close === 01:15:39 (1787116539) [ 1779.363481] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1781.349865] Lustre: Failing over lustre-MDT0000 [ 1781.729068] Lustre: server umount lustre-MDT0000 complete [ 1806.357133] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1808.920113] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:835 to 0x280000400:865) [ 1808.920428] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:771 to 0x240000400:865) [ 1815.415709] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1817.161579] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1825.685785] Lustre: DEBUG MARKER: == replay-single test 14: open(O_CREAT), unlink |X| close ========================================================== 01:16:30 (1787116590) [ 1829.918526] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1831.901996] Lustre: Failing over lustre-MDT0000 [ 1832.196767] Lustre: server umount lustre-MDT0000 complete [ 1850.570524] Lustre: lustre-MDT0000: Not available for connect from 192.168.204.15@tcp (not set up) [ 1852.112033] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:771 to 0x240000400:897) [ 1852.112719] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:867 to 0x280000400:897) [ 1855.739689] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1865.168561] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1866.711922] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1874.440553] Lustre: DEBUG MARKER: == replay-single test 15: open(O_CREAT), unlink |X| touch new, close ========================================================== 01:17:19 (1787116639) [ 1878.337700] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1880.211366] Lustre: Failing over lustre-MDT0000 [ 1880.548930] 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 [ 1880.577473] Lustre: Skipped 18 previous similar messages [ 1880.687805] Lustre: server umount lustre-MDT0000 complete [ 1901.027319] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 1901.039394] Lustre: Skipped 20 previous similar messages [ 1904.577303] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1907.080432] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1907.089034] Lustre: Skipped 9 previous similar messages [ 1907.209498] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1907.215112] Lustre: Skipped 9 previous similar messages [ 1907.244306] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:899 to 0x240000400:929) [ 1907.250164] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:899 to 0x280000400:929) [ 1914.576662] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1916.165446] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1924.022150] Lustre: DEBUG MARKER: == replay-single test 16: |X| open(O_CREAT), unlink, touch new, unlink new ========================================================== 01:18:08 (1787116688) [ 1926.915363] LustreError: 52922:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 1926.922950] LustreError: 52922:0:(osd_handler.c:720:osd_ro()) Skipped 9 previous similar messages [ 1927.716286] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1929.601654] Lustre: Failing over lustre-MDT0000 [ 1930.070674] Lustre: server umount lustre-MDT0000 complete [ 1946.870902] LustreError: MGC192.168.204.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1946.878205] LustreError: Skipped 9 previous similar messages [ 1948.233107] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:931 to 0x280000400:961) [ 1948.237838] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:899 to 0x240000400:961) [ 1951.009843] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1959.512719] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1961.032603] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1969.195192] Lustre: DEBUG MARKER: == replay-single test 17: |X| open(O_CREAT), |replay| close ========================================================== 01:18:53 (1787116733) [ 1973.277575] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1975.366292] Lustre: Failing over lustre-MDT0000 [ 1975.630674] Lustre: server umount lustre-MDT0000 complete [ 1994.332204] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:963 to 0x280000400:993) [ 1994.336992] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:899 to 0x240000400:993) [ 1997.186876] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2005.352207] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2006.629602] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2013.908428] Lustre: DEBUG MARKER: == replay-single test 18: open(O_CREAT), unlink, touch new, close, touch, unlink ========================================================== 01:19:38 (1787116778) [ 2017.391539] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2019.391018] Lustre: Failing over lustre-MDT0000 [ 2019.696382] Lustre: server umount lustre-MDT0000 complete [ 2042.503633] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2045.571457] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:995 to 0x280000400:1025) [ 2045.576461] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:995 to 0x240000400:1025) [ 2052.107476] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2053.780724] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2062.181361] Lustre: DEBUG MARKER: == replay-single test 19: mcreate, open, write, rename === 01:20:26 (1787116826) [ 2065.603742] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2067.397354] Lustre: Failing over lustre-MDT0000 [ 2067.748812] Lustre: server umount lustre-MDT0000 complete [ 2086.558238] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1027 to 0x280000400:1057) [ 2086.561313] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1027 to 0x240000400:1057) [ 2089.026405] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2097.866487] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2099.336846] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2106.970142] Lustre: DEBUG MARKER: == replay-single test 20a: |X| open(O_CREAT), unlink, replay, close (test mds_cleanup_orphans) ========================================================== 01:21:11 (1787116871) [ 2110.509828] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2112.444595] Lustre: Failing over lustre-MDT0000 [ 2112.672902] Lustre: server umount lustre-MDT0000 complete [ 2130.046744] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 2130.061446] Lustre: Skipped 10 previous similar messages [ 2132.621676] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1059 to 0x240000400:1089) [ 2132.622337] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1027 to 0x280000400:1089) [ 2134.504837] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2143.149666] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2144.730876] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2152.661411] Lustre: DEBUG MARKER: == replay-single test 20b: write, unlink, eviction, replay (test mds_cleanup_orphans) ========================================================== 01:21:57 (1787116917) [ 2157.790229] Lustre: 60659:0:(genops.c:1795:obd_export_evict_by_uuid()) lustre-MDT0000: evicting 4913e0be-d780-41d1-b675-48bb693774d0 at adminstrative request [ 2162.239777] Lustre: Failing over lustre-MDT0000 [ 2162.643181] Lustre: server umount lustre-MDT0000 complete [ 2185.059199] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2189.822681] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1027 to 0x280000400:1121) [ 2189.823314] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1091 to 0x240000400:1121) [ 2195.263701] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2196.871318] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2202.508680] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 2216.412658] Lustre: DEBUG MARKER: before 4096, after 4096 [ 2221.719538] Lustre: DEBUG MARKER: == replay-single test 20c: check that client eviction does not affect file content ========================================================== 01:23:06 (1787116986) [ 2222.674405] Lustre: 62697:0:(genops.c:1795:obd_export_evict_by_uuid()) lustre-MDT0000: evicting 4913e0be-d780-41d1-b675-48bb693774d0 at adminstrative request [ 2231.095986] Lustre: DEBUG MARKER: == replay-single test 21: |X| open(O_CREAT), unlink touch new, replay, close (test mds_cleanup_orphans) ========================================================== 01:23:16 (1787116996) [ 2233.864897] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2235.472911] Lustre: Failing over lustre-MDT0000 [ 2235.787200] LustreError: 61219:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.204.15@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 2235.799891] LustreError: 61219:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 1 previous similar message [ 2235.862413] Lustre: server umount lustre-MDT0000 complete [ 2252.258487] LustreError: 63602: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. [ 2256.524077] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1124 to 0x280000400:1153) [ 2256.527503] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1123 to 0x240000400:1153) [ 2257.399149] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2267.113354] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2268.805528] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2276.391727] Lustre: DEBUG MARKER: == replay-single test 22: open(O_CREAT), |X| unlink, replay, close (test mds_cleanup_orphans) ========================================================== 01:24:01 (1787117041) [ 2280.315371] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2282.195076] Lustre: Failing over lustre-MDT0000 [ 2282.380994] Lustre: lustre-MDT0000: Not available for connect from 192.168.204.15@tcp (stopping) [ 2282.385657] Lustre: Skipped 2 previous similar messages [ 2282.454838] Lustre: server umount lustre-MDT0000 complete [ 2301.151096] Lustre: 3279:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787117050/real 1787117050] req@ffff93d2ed804000 x1873925711237504/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787117066 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2301.182416] Lustre: 3279:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 73 previous similar messages [ 2303.056063] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1155 to 0x280000400:1185) [ 2303.058872] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1155 to 0x240000400:1185) [ 2305.324604] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2314.342923] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2315.810910] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2323.658885] Lustre: DEBUG MARKER: == replay-single test 23: open(O_CREAT), |X| unlink touch new, replay, close (test mds_cleanup_orphans) ========================================================== 01:24:48 (1787117088) [ 2327.383512] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2329.356876] Lustre: Failing over lustre-MDT0000 [ 2329.639748] Lustre: server umount lustre-MDT0000 complete [ 2349.228982] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1187 to 0x280000400:1217) [ 2349.236326] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1187 to 0x240000400:1217) [ 2351.650429] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2362.176301] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2363.660440] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2372.209107] Lustre: DEBUG MARKER: == replay-single test 24: open(O_CREAT), replay, unlink, close (test mds_cleanup_orphans) ========================================================== 01:25:36 (1787117136) [ 2376.224946] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2377.985057] Lustre: Failing over lustre-MDT0000 [ 2378.317778] Lustre: server umount lustre-MDT0000 complete [ 2396.068080] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 2396.073719] Lustre: Skipped 12 previous similar messages [ 2401.417898] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2405.493713] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1219 to 0x240000400:1249) [ 2405.495396] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1219 to 0x280000400:1249) [ 2412.295651] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2414.055573] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2422.974904] Lustre: DEBUG MARKER: == replay-single test 25: open(O_CREAT), unlink, replay, close (test mds_cleanup_orphans) ========================================================== 01:26:27 (1787117187) [ 2426.762217] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2428.557764] Lustre: Failing over lustre-MDT0000 [ 2429.030068] Lustre: server umount lustre-MDT0000 complete [ 2446.218576] LustreError: 69738:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.204.15@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 2446.231028] LustreError: 69738:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 1 previous similar message [ 2448.010676] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1219 to 0x280000400:1281) [ 2448.010973] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1251 to 0x240000400:1281) [ 2451.234223] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2460.767658] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2462.566425] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2472.070967] Lustre: DEBUG MARKER: == replay-single test 26: |X| open(O_CREAT), unlink two, close one, replay, close one (test mds_cleanup_orphans) ========================================================== 01:27:16 (1787117236) [ 2476.048307] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2478.364173] Lustre: Failing over lustre-MDT0000 [ 2478.737154] Lustre: server umount lustre-MDT0000 complete [ 2498.015990] 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 [ 2498.026461] LustreError: 71296: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. [ 2498.054245] Lustre: Skipped 24 previous similar messages [ 2498.098096] LustreError: 71296:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 1 previous similar message [ 2499.893342] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1283 to 0x240000400:1313) [ 2499.894079] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1283 to 0x280000400:1313) [ 2502.820203] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2503.654430] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 2503.665995] Lustre: Skipped 23 previous similar messages [ 2512.072978] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2513.352984] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2521.101229] Lustre: DEBUG MARKER: == replay-single test 27: |X| open(O_CREAT), unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 01:28:05 (1787117285) [ 2525.140330] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2526.868361] Lustre: Failing over lustre-MDT0000 [ 2527.167977] Lustre: server umount lustre-MDT0000 complete [ 2545.543046] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 2545.546934] Lustre: Skipped 12 previous similar messages [ 2545.734896] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 2545.740556] Lustre: Skipped 12 previous similar messages [ 2545.798638] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1315 to 0x280000400:1345) [ 2545.805673] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1315 to 0x240000400:1345) [ 2550.312821] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2560.382561] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2562.262376] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2571.372244] Lustre: DEBUG MARKER: == replay-single test 28: open(O_CREAT), |X| unlink two, close one, replay, close one (test mds_cleanup_orphans) ========================================================== 01:28:55 (1787117335) [ 2574.694974] LustreError: 73816:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 2574.703156] LustreError: 73816:0:(osd_handler.c:720:osd_ro()) Skipped 11 previous similar messages [ 2575.658412] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2577.749058] Lustre: Failing over lustre-MDT0000 [ 2578.135264] Lustre: server umount lustre-MDT0000 complete [ 2597.593879] LustreError: MGC192.168.204.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2597.609665] LustreError: Skipped 12 previous similar messages [ 2597.795587] Lustre: lustre-MDT0000: Not available for connect from 192.168.204.15@tcp (not set up) [ 2599.263714] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1347 to 0x240000400:1377) [ 2599.267502] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1347 to 0x280000400:1377) [ 2603.590026] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2613.820457] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2615.541408] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2625.181829] Lustre: DEBUG MARKER: == replay-single test 29: open(O_CREAT), |X| unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 01:29:49 (1787117389) [ 2630.028848] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2632.509669] Lustre: Failing over lustre-MDT0000 [ 2633.056595] Lustre: server umount lustre-MDT0000 complete [ 2660.578460] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xa7821dffd2f16ae5 [ 2666.828256] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2674.972847] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1379 to 0x240000400:1409) [ 2674.976126] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1379 to 0x280000400:1409) [ 2682.046452] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2683.959101] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2693.554813] Lustre: DEBUG MARKER: == replay-single test 30: open(O_CREAT) two, unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 01:30:58 (1787117458) [ 2698.269570] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2700.128696] Lustre: Failing over lustre-MDT0000 [ 2700.472731] Lustre: server umount lustre-MDT0000 complete [ 2719.643757] LustreError: 77465: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. [ 2720.860164] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1411 to 0x280000400:1441) [ 2720.860164] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1411 to 0x240000400:1441) [ 2725.347127] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2735.896485] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2738.087885] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2749.030278] Lustre: DEBUG MARKER: == replay-single test 31: open(O_CREAT) two, unlink one, |X| unlink one, close two (test mds_cleanup_orphans) ========================================================== 01:31:53 (1787117513) [ 2753.150442] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2755.240481] Lustre: Failing over lustre-MDT0000 [ 2755.626384] Lustre: server umount lustre-MDT0000 complete [ 2775.228662] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 2775.239770] Lustre: Skipped 11 previous similar messages [ 2780.695339] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2783.301801] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1443 to 0x280000400:1473) [ 2783.302068] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1443 to 0x240000400:1473) [ 2791.637864] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2792.987178] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2802.010735] Lustre: DEBUG MARKER: == replay-single test 32: close() notices client eviction; close() after client eviction ========================================================== 01:32:46 (1787117566) [ 2803.228311] Lustre: 79889:0:(genops.c:1795:obd_export_evict_by_uuid()) lustre-MDT0000: evicting 4913e0be-d780-41d1-b675-48bb693774d0 at adminstrative request [ 2812.495730] Lustre: DEBUG MARKER: == replay-single test 33a: fid seq shouldn't be reused after abort recovery ========================================================== 01:32:56 (1787117576) [ 2815.511284] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2817.380534] Lustre: Failing over lustre-MDT0000 [ 2817.600682] Lustre: server umount lustre-MDT0000 complete [ 2825.487389] Lustre: lustre-MDT0000: Aborting client recovery [ 2825.491400] LustreError: 80753:0:(ldlm_lib.c:3003:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 2825.497952] Lustre: 80799:0:(ldlm_lib.c:2403:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 2825.503810] Lustre: 80799:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 4913e0be-d780-41d1-b675-48bb693774d0@ [ 2825.514492] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 2825.567296] Lustre: lustre-MDT0000-osd: cancel update llog [0x200000400:0x1:0x0] [ 2825.707254] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1479 to 0x280000400:1505) [ 2825.711208] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1480 to 0x240000400:1505) [ 2830.095310] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2842.753282] Lustre: DEBUG MARKER: == replay-single test 33b: test fid seq allocation ======= 01:33:27 (1787117607) [ 2846.925335] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2848.739271] Lustre: Failing over lustre-MDT0000 [ 2849.098289] Lustre: server umount lustre-MDT0000 complete [ 2857.520172] Lustre: *** cfs_fail_loc=1311, val=0*** [ 2857.556697] Lustre: lustre-MDT0000: Aborting client recovery [ 2857.560525] LustreError: 82079:0:(ldlm_lib.c:3003:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 2857.569715] Lustre: 82125:0:(ldlm_lib.c:2403:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 2857.585716] Lustre: 82125:0:(ldlm_lib.c:2403:target_recovery_overseer()) Skipped 2 previous similar messages [ 2857.595328] Lustre: 82125:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 4913e0be-d780-41d1-b675-48bb693774d0@ [ 2857.611302] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 2857.654862] Lustre: lustre-MDT0000-osd: cancel update llog [0x200015bc0:0x1:0x0] [ 2857.767686] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1516 to 0x240000400:1537) [ 2857.768552] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1516 to 0x280000400:1537) [ 2862.843679] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2868.335142] Lustre: *** cfs_fail_loc=1311, val=0*** [ 2875.799665] Lustre: DEBUG MARKER: == replay-single test 34: abort recovery before client does replay (test mds_cleanup_orphans) ========================================================== 01:34:00 (1787117640) [ 2879.359833] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2881.808647] Lustre: Failing over lustre-MDT0000 [ 2882.174877] Lustre: server umount lustre-MDT0000 complete [ 2892.855668] Lustre: lustre-MDT0000: Aborting client recovery [ 2892.858684] LustreError: 83401:0:(ldlm_lib.c:3003:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 2892.864350] Lustre: 83449:0:(ldlm_lib.c:2403:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 2892.873803] Lustre: 83449:0:(ldlm_lib.c:2403:target_recovery_overseer()) Skipped 2 previous similar messages [ 2892.880665] Lustre: 83449:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 4913e0be-d780-41d1-b675-48bb693774d0@ [ 2892.887896] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 2892.960620] Lustre: lustre-MDT0000-osd: cancel update llog [0x200016778:0x1:0x0] [ 2893.096684] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1543 to 0x280000400:1569) [ 2893.100056] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1544 to 0x240000400:1569) [ 2900.532880] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2904.031165] Lustre: 3279:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787117654/real 1787117654] req@ffff93d2fb345180 x1873925711439488/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787117670 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2904.062863] Lustre: 3279:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 86 previous similar messages [ 2914.410855] Lustre: DEBUG MARKER: == replay-single test 35: test recovery from llog for unlink op ========================================================== 01:34:39 (1787117679) [ 2915.599960] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 2915.607365] LustreError: 83413:0:(ldlm_lib.c:3345:target_send_reply_msg()) @@@ dropping reply req@ffff93d2c57e0000 x1873925702203264/t201863462916(0) o36->4913e0be-d780-41d1-b675-48bb693774d0@192.168.204.15@tcp:228/0 lens 512/456 e 0 to 0 dl 1787117693 ref 1 fl Interpret:/200/0 rc 0/0 job:'rm.0' uid:0 gid:0 projid:4294967295 [ 2919.365973] Lustre: Failing over lustre-MDT0000 [ 2919.637379] Lustre: server umount lustre-MDT0000 complete [ 2928.927529] Lustre: lustre-MDT0000: Aborting client recovery [ 2928.930263] LustreError: 84576:0:(ldlm_lib.c:3003:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 2928.935617] Lustre: 84620:0:(ldlm_lib.c:2403:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 2928.942473] Lustre: 84620:0:(ldlm_lib.c:2403:target_recovery_overseer()) Skipped 2 previous similar messages [ 2928.953146] Lustre: 84620:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 4913e0be-d780-41d1-b675-48bb693774d0@ [ 2928.970057] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 2929.050369] Lustre: lustre-MDT0000-osd: cancel update llog [0x200017330:0x1:0x0] [ 2929.288387] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1543 to 0x280000400:1601) [ 2929.304130] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1571 to 0x240000400:1601) [ 2934.529153] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2948.520981] Lustre: DEBUG MARKER: SKIP: replay-single test_36 skipping ALWAYS excluded test 36 [ 2950.421341] Lustre: DEBUG MARKER: == replay-single test 37: abort recovery before client does replay (test mds_cleanup_orphans for directories) ========================================================== 01:35:14 (1787117714) [ 2954.980578] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2957.761061] Lustre: Failing over lustre-MDT0000 [ 2957.989602] Lustre: server umount lustre-MDT0000 complete [ 2965.881472] Lustre: lustre-MDT0000: Aborting client recovery [ 2965.885453] LustreError: 85983:0:(ldlm_lib.c:3003:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 2965.891895] Lustre: 86030:0:(ldlm_lib.c:2403:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 2965.896470] Lustre: 86030:0:(ldlm_lib.c:2403:target_recovery_overseer()) Skipped 2 previous similar messages [ 2965.901393] Lustre: 86030:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 4913e0be-d780-41d1-b675-48bb693774d0@ [ 2965.907892] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 2965.970692] Lustre: lustre-MDT0000-osd: cancel update llog [0x200017b00:0x1:0x0] [ 2966.091075] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1571 to 0x240000400:1633) [ 2966.097558] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1543 to 0x280000400:1633) [ 2970.880353] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2984.579276] Lustre: DEBUG MARKER: == replay-single test 38: test recovery from unlink llog (test llog_gen_rec) ========================================================== 01:35:48 (1787117748) [ 3019.301397] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3021.766803] Lustre: Failing over lustre-MDT0000 [ 3022.172373] Lustre: server umount lustre-MDT0000 complete [ 3048.928465] LustreError: 3278:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff93d1c8712300 x1873925711544064/t0(0) o250->MGC192.168.204.115@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 0 ref 1 fl Rpc:NQU/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3049.897513] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3049.901567] Lustre: Skipped 12 previous similar messages [ 3051.477568] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2034 to 0x280000400:2049) [ 3051.478710] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2034 to 0x240000400:2049) [ 3054.978927] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3065.015677] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3066.823724] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3089.374672] Lustre: DEBUG MARKER: == replay-single test 39: test recovery from unlink llog (test llog_gen_rec) ========================================================== 01:37:34 (1787117854) [ 3113.413789] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3124.380800] Lustre: Failing over lustre-MDT0000 [ 3124.721510] Lustre: server umount lustre-MDT0000 complete [ 3141.599246] 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 [ 3141.615195] Lustre: Skipped 22 previous similar messages [ 3153.809587] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 3153.831264] Lustre: Skipped 5 previous similar messages [ 3157.588361] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3159.045282] Lustre: lustre-MDT0000: Recovery over after 0:06, of 1 clients 1 recovered and 0 were evicted. [ 3159.059652] Lustre: Skipped 5 previous similar messages [ 3159.135588] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2450 to 0x240000400:2465) [ 3159.134195] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2450 to 0x280000400:2465) [ 3166.498640] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 3166.508829] Lustre: Skipped 24 previous similar messages [ 3167.838275] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3169.268536] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3191.133972] Lustre: DEBUG MARKER: == replay-single test 41: read from a valid osc while other oscs are invalid ========================================================== 01:39:15 (1787117955) [ 3193.176860] Lustre: setting import lustre-OST0001_UUID INACTIVE by administrator request [ 3194.206215] Lustre: lustre-OST0001: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnecting [ 3194.214599] LustreError: lustre-OST0001-osc-MDT0000: This client was evicted by lustre-OST0001; in progress operations using this service will fail. [ 3200.283946] Lustre: DEBUG MARKER: == replay-single test 42: recovery after ost failure ===== 01:39:25 (1787117965) [ 3222.485548] LustreError: 91368:0:(osd_handler.c:720:osd_ro()) lustre-OST0000: *** setting device osd-zfs read-only *** [ 3222.496742] LustreError: 91368:0:(osd_handler.c:720:osd_ro()) Skipped 9 previous similar messages [ 3223.583733] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 3236.785468] Lustre: Failing over lustre-OST0000 [ 3236.938861] Lustre: server umount lustre-OST0000 complete [ 3238.370380] LustreError: 6574: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. [ 3238.396640] LustreError: 6574:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 1 previous similar message [ 3260.634891] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3321.365956] Lustre: DEBUG MARKER: == replay-single test 43: mds osc import failure during recovery; don't LBUG ========================================================== 01:41:26 (1787118086) [ 3325.384749] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3328.126764] Lustre: Failing over lustre-MDT0000 [ 3328.472907] Lustre: server umount lustre-MDT0000 complete [ 3345.617913] LustreError: MGC192.168.204.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3345.643478] LustreError: Skipped 10 previous similar messages [ 3346.990503] Lustre: *** cfs_fail_loc=204, val=2147483648*** [ 3346.992273] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2866 to 0x280000400:2881) [ 3350.197545] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3360.370644] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3362.052916] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3362.271287] LustreError: 93770:0:(osp_precreate.c:974:osp_precreate_cleanup_orphans()) lustre-OST0000-osc-MDT0000: cannot cleanup orphans: rc = -11 [ 3362.284594] Lustre: lustre-OST0000: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnecting [ 3363.301832] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2867 to 0x240000400:2913) [ 3381.096525] Lustre: DEBUG MARKER: == replay-single test 44a: race in target handle connect ========================================================== 01:42:25 (1787118145) [ 3385.434779] LustreError: 93747:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_race id 701 sleeping [ 3390.943128] LustreError: 93747:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 3390.952181] Lustre: lustre-MDT0000: Client 4913e0be-d780-41d1-b675-48bb693774d0 (at 192.168.204.15@tcp) reconnecting [ 3391.002191] LustreError: 12592:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_fail_race id 701 waking [ 3392.932438] LustreError: 94398:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_race id 701 sleeping [ 3398.115250] LustreError: 94398:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 3398.122489] Lustre: lustre-MDT0000: Client 4913e0be-d780-41d1-b675-48bb693774d0 (at 192.168.204.15@tcp) reconnecting [ 3399.947162] LustreError: 93747:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_race id 701 sleeping [ 3405.279119] LustreError: 93747:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 3405.291698] Lustre: lustre-MDT0000: Client 4913e0be-d780-41d1-b675-48bb693774d0 (at 192.168.204.15@tcp) reconnecting [ 3407.289842] LustreError: 93748:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_race id 701 sleeping [ 3412.448902] LustreError: 93748:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 3414.306984] LustreError: 93745:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_race id 701 sleeping [ 3419.615149] LustreError: 93745:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 3419.627140] Lustre: lustre-MDT0000: Client 4913e0be-d780-41d1-b675-48bb693774d0 (at 192.168.204.15@tcp) reconnecting [ 3419.638794] Lustre: Skipped 1 previous similar message [ 3428.565727] LustreError: 93745:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_race id 701 sleeping [ 3428.571746] LustreError: 93745:0:(ldlm_lib.c:1178:target_handle_connect()) Skipped 1 previous similar message [ 3433.951434] LustreError: 93745:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 3433.965723] LustreError: 93745:0:(ldlm_lib.c:1178:target_handle_connect()) Skipped 1 previous similar message [ 3441.119191] Lustre: lustre-MDT0000: Client 4913e0be-d780-41d1-b675-48bb693774d0 (at 192.168.204.15@tcp) reconnecting [ 3441.128711] Lustre: Skipped 2 previous similar messages [ 3450.049097] LustreError: 95161:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_race id 701 sleeping [ 3450.063769] LustreError: 95161:0:(ldlm_lib.c:1178:target_handle_connect()) Skipped 2 previous similar messages [ 3455.455138] LustreError: 95161:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 3455.467665] LustreError: 95161:0:(ldlm_lib.c:1178:target_handle_connect()) Skipped 2 previous similar messages [ 3463.850349] Lustre: DEBUG MARKER: == replay-single test 44b: race in target handle connect ========================================================== 01:43:48 (1787118228) [ 3465.637102] LustreError: 93748:0:(ldlm_lib.c:1435:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 3475.850427] Lustre: lustre-MDT0000: Export ffff93d2dfbee800 already connecting from 192.168.204.15@tcp [ 3478.859478] Lustre: lustre-MDT0000: Export ffff93d2dfbee800 already connecting from 192.168.204.15@tcp [ 3480.908506] Lustre: lustre-MDT0000: Export ffff93d2dfbee800 already connecting from 192.168.204.15@tcp [ 3486.088678] Lustre: lustre-MDT0000: Export ffff93d2dfbee800 already connecting from 192.168.204.15@tcp [ 3491.205225] Lustre: lustre-MDT0000: Export ffff93d2dfbee800 already connecting from 192.168.204.15@tcp [ 3491.216708] Lustre: Skipped 1 previous similar message [ 3501.448402] Lustre: lustre-MDT0000: Export ffff93d2dfbee800 already connecting from 192.168.204.15@tcp [ 3501.454190] Lustre: Skipped 1 previous similar message [ 3505.728874] LustreError: 93748:0:(ldlm_lib.c:1435:target_handle_connect()) cfs_fail_timeout id 704 awake [ 3505.739762] Lustre: 93748:0:(service.c:2582:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/20s); client may timeout req@ffff93d2d69cc700 x1873925704844416/t0(0) o38->4913e0be-d780-41d1-b675-48bb693774d0@192.168.204.15@tcp:0/0 lens 520/416 e 0 to 0 dl 1787118252 ref 1 fl Complete:H/200/0 rc 0/0 job:'lctl.0' uid:0 gid:0 projid:4294967295 [ 3506.569585] Lustre: lustre-MDT0000: Client 4913e0be-d780-41d1-b675-48bb693774d0 (at 192.168.204.15@tcp) reconnecting [ 3506.584759] Lustre: Skipped 3 previous similar messages [ 3506.589807] LustreError: 93747:0:(ldlm_lib.c:1435:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 3531.143082] Lustre: lustre-MDT0000: Export ffff93d2dfbee800 already connecting from 192.168.204.15@tcp [ 3546.647928] LustreError: 93747:0:(ldlm_lib.c:1435:target_handle_connect()) cfs_fail_timeout id 704 awake [ 3546.665860] Lustre: 93747:0:(service.c:2582:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/20s); client may timeout req@ffff93d2fb9e3480 x1873925704847744/t0(0) o38->4913e0be-d780-41d1-b675-48bb693774d0@192.168.204.15@tcp:0/0 lens 520/416 e 0 to 0 dl 1787118293 ref 1 fl Complete:H/200/0 rc 0/0 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3551.624090] LustreError: 95161:0:(ldlm_lib.c:1435:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 3576.206893] Lustre: lustre-MDT0000: Export ffff93d2dfbee800 already connecting from 192.168.204.15@tcp [ 3576.226882] Lustre: Skipped 4 previous similar messages [ 3591.671104] LustreError: 95161:0:(ldlm_lib.c:1435:target_handle_connect()) cfs_fail_timeout id 704 awake [ 3591.685730] Lustre: 95161:0:(service.c:2582:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/20s); client may timeout req@ffff93d2e8053800 x1873925704849920/t0(0) o38->4913e0be-d780-41d1-b675-48bb693774d0@192.168.204.15@tcp:0/0 lens 520/416 e 0 to 0 dl 1787118338 ref 1 fl Complete:H/200/0 rc 0/0 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3596.685401] Lustre: lustre-MDT0000: Client 4913e0be-d780-41d1-b675-48bb693774d0 (at 192.168.204.15@tcp) reconnecting [ 3596.701260] Lustre: Skipped 1 previous similar message [ 3596.713239] LustreError: 93747:0:(ldlm_lib.c:1435:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 3636.767195] LustreError: 93747:0:(ldlm_lib.c:1435:target_handle_connect()) cfs_fail_timeout id 704 awake [ 3636.775473] Lustre: 93747:0:(service.c:2582:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/20s); client may timeout req@ffff93d2ed289180 x1873925704852096/t0(0) o38->4913e0be-d780-41d1-b675-48bb693774d0@192.168.204.15@tcp:0/0 lens 520/416 e 0 to 0 dl 1787118383 ref 1 fl Complete:H/200/0 rc 0/0 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3641.741983] LustreError: 93748:0:(ldlm_lib.c:1435:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 3666.342736] Lustre: lustre-MDT0000: Export ffff93d2dfbee800 already connecting from 192.168.204.15@tcp [ 3666.358040] Lustre: Skipped 9 previous similar messages [ 3681.799138] LustreError: 93748:0:(ldlm_lib.c:1435:target_handle_connect()) cfs_fail_timeout id 704 awake [ 3681.804577] Lustre: 93748:0:(service.c:2582:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/20s); client may timeout req@ffff93d1c258a300 x1873925704854272/t0(0) o38->4913e0be-d780-41d1-b675-48bb693774d0@192.168.204.15@tcp:0/0 lens 520/416 e 0 to 0 dl 1787118428 ref 1 fl Complete:H/200/0 rc 0/0 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3686.792922] LustreError: 94398:0:(ldlm_lib.c:1435:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 3691.295266] LustreError: 94398:0:(ldlm_lib.c:1435:target_handle_connect()) cfs_fail_timeout interrupted [ 3696.343780] Lustre: DEBUG MARKER: == replay-single test 44c: race in target handle connect ========================================================== 01:47:40 (1787118460) [ 3700.089281] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3704.548604] Lustre: Failing over lustre-MDT0000 [ 3704.904564] Lustre: server umount lustre-MDT0000 complete [ 3712.957057] Lustre: *** cfs_fail_loc=712, val=0*** [ 3712.961117] LustreError: 12592:0:(service.c:1394:ptlrpc_check_req()) @@@ Invalid replay without recovery req@ffff93d2c61c0e00 x1873925712039680/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 [ 3713.138915] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3713.143161] Lustre: Skipped 3 previous similar messages [ 3713.234506] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 3713.236488] Lustre: lustre-MDT0000: Aborting client recovery [ 3713.241055] Lustre: Skipped 19 previous similar messages [ 3713.250426] LustreError: 98248:0:(ldlm_lib.c:3003:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 3713.256597] Lustre: 98298:0:(ldlm_lib.c:2403:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 3713.263885] Lustre: 98298:0:(ldlm_lib.c:2403:target_recovery_overseer()) Skipped 2 previous similar messages [ 3713.276087] Lustre: 98298:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 4913e0be-d780-41d1-b675-48bb693774d0@ [ 3713.295038] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 3713.361481] Lustre: lustre-MDT0000-osd: cancel update llog [0x2000182d0:0x1:0x0] [ 3713.488000] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2866 to 0x280000400:2913) [ 3713.515525] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2867 to 0x240000400:2945) [ 3717.134695] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3725.372968] Lustre: Failing over lustre-MDT0000 [ 3725.783181] Lustre: server umount lustre-MDT0000 complete [ 3744.647294] 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 [ 3744.661484] Lustre: Skipped 9 previous similar messages [ 3745.695572] Lustre: 3279:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787118495/real 1787118495] req@ffff93d2c57e0a80 x1873925712049536/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787118511 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3745.722506] Lustre: 3279:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 31 previous similar messages [ 3749.707766] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3753.521629] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2866 to 0x280000400:2945) [ 3753.522797] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2867 to 0x240000400:2977) [ 3759.291974] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3761.052643] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3769.150418] Lustre: DEBUG MARKER: == replay-single test 45: Handle failed close ============ 01:48:53 (1787118533) [ 3769.276074] Lustre: lustre-MDT0000: Client 4913e0be-d780-41d1-b675-48bb693774d0 (at 192.168.204.15@tcp) reconnecting [ 3769.285188] Lustre: Skipped 2 previous similar messages [ 3776.929149] Lustre: DEBUG MARKER: == replay-single test 46: Don't leak file handle after open resend (3325) ========================================================== 01:49:01 (1787118541) [ 3777.870185] Lustre: *** cfs_fail_loc=122, val=2147483648*** [ 3777.874706] LustreError: 99170:0:(ldlm_lib.c:3345:target_send_reply_msg()) @@@ dropping reply req@ffff93d2edb56d80 x1873925704910592/t0(0) o700->4913e0be-d780-41d1-b675-48bb693774d0@192.168.204.15@tcp:335/0 lens 264/248 e 0 to 0 dl 1787118555 ref 1 fl Interpret:/200/0 rc 0/0 job:'touch.0' uid:0 gid:0 projid:4294967295 [ 3796.571193] Lustre: Failing over lustre-MDT0000 [ 3796.839945] Lustre: server umount lustre-MDT0000 complete [ 3814.799508] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 3814.820809] Lustre: Skipped 3 previous similar messages [ 3814.986264] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 3814.995635] Lustre: Skipped 3 previous similar messages [ 3815.066218] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2979 to 0x240000400:3009) [ 3815.077493] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2947 to 0x280000400:2977) [ 3819.729174] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3820.008285] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 3820.014901] Lustre: Skipped 10 previous similar messages [ 3830.210363] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3831.918085] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3843.118463] Lustre: DEBUG MARKER: == replay-single test 47: MDS->OSC failure during precreate cleanup (2824) ========================================================== 01:50:07 (1787118607) [ 3845.658656] Lustre: Failing over lustre-OST0000 [ 3845.828483] Lustre: server umount lustre-OST0000 complete [ 3849.654162] LustreError: 35668:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.204.15@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3849.677909] LustreError: 35668:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 6 previous similar messages [ 3850.720315] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 3871.249654] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3881.031377] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 3882.456888] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 3954.830409] Lustre: DEBUG MARKER: == replay-single test 48: MDS->OSC failure during precreate cleanup (2824) ========================================================== 01:51:59 (1787118719) [ 3958.021584] LustreError: 103277:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 3958.030610] LustreError: 103277:0:(osd_handler.c:720:osd_ro()) Skipped 2 previous similar messages [ 3959.016426] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3961.338292] Lustre: Failing over lustre-MDT0000 [ 3961.698734] Lustre: server umount lustre-MDT0000 complete [ 3979.655693] LustreError: MGC192.168.204.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3979.662784] LustreError: Skipped 3 previous similar messages [ 3984.530815] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3989.539709] Lustre: *** cfs_fail_loc=216, val=0*** [ 3989.541766] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2998 to 0x280000400:3041) [ 3989.562445] LustreError: 103852:0:(osp_precreate.c:974:osp_precreate_cleanup_orphans()) lustre-OST0000-osc-MDT0000: cannot cleanup orphans: rc = -30 [ 3990.624676] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3030 to 0x240000400:3073) [ 4058.020370] Lustre: DEBUG MARKER: == replay-single test 50: Double OSC recovery, don't LASSERT (3812) ========================================================== 01:53:42 (1787118822) [ 4059.757537] Lustre: lustre-OST0000: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnecting [ 4059.768680] Lustre: Skipped 2 previous similar messages [ 4071.846904] Lustre: DEBUG MARKER: == replay-single test 52: time out lock replay (3764) ==== 01:53:56 (1787118836) [ 4074.909645] Lustre: Failing over lustre-MDT0000 [ 4075.397313] Lustre: server umount lustre-MDT0000 complete [ 4092.906491] LustreError: 105409: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. [ 4092.927950] LustreError: 105409:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 5 previous similar messages [ 4097.705451] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4102.548465] Lustre: *** cfs_fail_loc=157, val=2147483648*** [ 4102.551542] LustreError: 105445:0:(ldlm_lib.c:3345:target_send_reply_msg()) @@@ dropping reply req@ffff93d2ff791c00 x1873925705030784/t0(0) o101->4913e0be-d780-41d1-b675-48bb693774d0@192.168.204.15@tcp:660/0 lens 328/344 e 0 to 0 dl 1787118880 ref 1 fl Complete:/240/0 rc 0/0 job:'ldlm_lock_repla.0' uid:0 gid:0 projid:4294967295 [ 4117.894635] Lustre: lustre-MDT0000: Client 4913e0be-d780-41d1-b675-48bb693774d0 (at 192.168.204.15@tcp) reconnected, waiting for 1 clients in recovery for 1:25 [ 4118.126352] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3052 to 0x280000400:3073) [ 4118.126849] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3085 to 0x240000400:3105) [ 4124.639901] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4126.191833] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4134.617696] Lustre: DEBUG MARKER: == replay-single test 53a: |X| close request while two MDC requests in flight ========================================================== 01:54:59 (1787118899) [ 4136.730706] Lustre: *** cfs_fail_loc=115, val=2147483648*** [ 4141.178365] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4143.031566] Lustre: Failing over lustre-MDT0000 [ 4143.290220] Lustre: server umount lustre-MDT0000 complete [ 4170.207941] LustreError: 3278:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff93d2ed793b80 x1873925712170496/t0(0) o250->MGC192.168.204.115@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 0 ref 1 fl Rpc:NQU/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4174.864283] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4177.916748] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3075 to 0x280000400:3105) [ 4177.918522] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3085 to 0x240000400:3137) [ 4184.434528] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4186.090241] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4193.916446] Lustre: DEBUG MARKER: == replay-single test 53b: |X| open request while two MDC requests in flight ========================================================== 01:55:58 (1787118958) [ 4194.946805] Lustre: *** cfs_fail_loc=107, val=2147483648*** [ 4200.616233] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4202.487820] Lustre: Failing over lustre-MDT0000 [ 4202.906707] Lustre: server umount lustre-MDT0000 complete [ 4222.025769] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3139 to 0x240000400:3169) [ 4222.027755] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3075 to 0x280000400:3137) [ 4225.339788] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4235.077270] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4237.101170] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4247.120697] Lustre: DEBUG MARKER: == replay-single test 53c: |X| open request and close request while two MDC requests in flight ========================================================== 01:56:51 (1787119011) [ 4248.219567] Lustre: *** cfs_fail_loc=107, val=2147483648*** [ 4250.291319] Lustre: *** cfs_fail_loc=115, val=2147483648*** [ 4254.530029] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4256.736236] Lustre: Failing over lustre-MDT0000 [ 4257.120563] Lustre: server umount lustre-MDT0000 complete [ 4278.644460] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4289.325531] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3139 to 0x240000400:3201) [ 4289.327322] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3139 to 0x280000400:3169) [ 4300.069643] Lustre: DEBUG MARKER: == replay-single test 53d: close reply while two MDC requests in flight ========================================================== 01:57:44 (1787119064) [ 4302.161464] Lustre: *** cfs_fail_loc=13b, val=315*** [ 4302.163081] Lustre: *** cfs_fail_loc=13b, val=2147483648*** [ 4302.167910] LustreError: 110414:0:(ldlm_lib.c:3345:target_send_reply_msg()) @@@ dropping reply req@ffff93d1c2589c00 x1873925705081216/t257698037777(0) o35->4913e0be-d780-41d1-b675-48bb693774d0@192.168.204.15@tcp:104/0 lens 392/456 e 0 to 0 dl 1787119079 ref 1 fl Interpret:/600/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 4305.081639] Lustre: Failing over lustre-MDT0000 [ 4305.537641] Lustre: server umount lustre-MDT0000 complete [ 4334.459432] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4334.464562] Lustre: Skipped 8 previous similar messages [ 4334.523624] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4334.535415] Lustre: Skipped 10 previous similar messages [ 4338.608408] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4343.879672] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3139 to 0x280000400:3201) [ 4343.891438] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3203 to 0x240000400:3233) [ 4343.902124] Lustre: 111697:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff93d2ed289500 x1873925705081216/t257698037777(0) o35->4913e0be-d780-41d1-b675-48bb693774d0@192.168.204.15@tcp:146/0 lens 392/456 e 0 to 0 dl 1787119121 ref 1 fl Interpret:/602/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 4350.156375] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4351.924553] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4360.292188] Lustre: DEBUG MARKER: == replay-single test 53e: |X| open reply while two MDC requests in flight ========================================================== 01:58:45 (1787119125) [ 4361.468288] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 4361.473529] LustreError: 112345:0:(ldlm_lib.c:3345:target_send_reply_msg()) @@@ dropping reply req@ffff93d2c57e2d80 x1873925705096064/t261993005072(0) o36->4913e0be-d780-41d1-b675-48bb693774d0@192.168.204.15@tcp:164/0 lens 504/448 e 0 to 0 dl 1787119139 ref 1 fl Interpret:/200/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 4367.855234] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4369.647073] Lustre: Failing over lustre-MDT0000 [ 4369.867819] Lustre: server umount lustre-MDT0000 complete [ 4387.744960] 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 [ 4387.758953] Lustre: Skipped 17 previous similar messages [ 4390.880373] Lustre: 3280:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787119141/real 1787119141] req@ffff93d1c1e39500 x1873925712233344/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787119157 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4390.914634] Lustre: 3280:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 54 previous similar messages [ 4393.529547] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4402.600087] Lustre: 113329:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff93d2e58aea00 x1873925705096064/t261993005072(0) o36->4913e0be-d780-41d1-b675-48bb693774d0@192.168.204.15@tcp:205/0 lens 504/2880 e 0 to 0 dl 1787119180 ref 1 fl Interpret:/202/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 4402.606273] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3203 to 0x240000400:3265) [ 4402.606535] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3203 to 0x280000400:3233) [ 4408.840338] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4410.326436] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4418.471331] Lustre: DEBUG MARKER: == replay-single test 53f: |X| open reply and close reply while two MDC requests in flight ========================================================== 01:59:43 (1787119183) [ 4419.502348] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 4419.509339] LustreError: 113329:0:(ldlm_lib.c:3345:target_send_reply_msg()) @@@ dropping reply req@ffff93d2f5c97800 x1873925705110912/t266287972368(0) o36->4913e0be-d780-41d1-b675-48bb693774d0@192.168.204.15@tcp:222/0 lens 504/448 e 0 to 0 dl 1787119197 ref 1 fl Interpret:/200/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 4421.427550] Lustre: *** cfs_fail_loc=13b, val=315*** [ 4425.105569] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4427.386167] Lustre: Failing over lustre-MDT0000 [ 4427.688744] Lustre: server umount lustre-MDT0000 complete [ 4449.412930] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4449.416886] Lustre: Skipped 8 previous similar messages [ 4449.653537] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4449.667974] Lustre: Skipped 8 previous similar messages [ 4449.718379] Lustre: 114968:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff93d2ff785f80 x1873925705110912/t266287972368(0) o36->4913e0be-d780-41d1-b675-48bb693774d0@192.168.204.15@tcp:252/0 lens 504/2880 e 0 to 0 dl 1787119227 ref 1 fl Interpret:/202/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 4449.724854] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3267 to 0x240000400:3297) [ 4449.736227] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3203 to 0x280000400:3265) [ 4450.273664] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 4450.276513] Lustre: Skipped 18 previous similar messages [ 4451.352957] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4465.387691] Lustre: DEBUG MARKER: == replay-single test 53g: |X| drop open reply and close request while close and open are both in flight ========================================================== 02:00:29 (1787119229) [ 4466.679223] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 4466.682056] Lustre: Skipped 1 previous similar message [ 4466.689736] LustreError: 115622:0:(ldlm_lib.c:3345:target_send_reply_msg()) @@@ dropping reply req@ffff93d2ed802680 x1873925705123328/t270582939664(0) o36->4913e0be-d780-41d1-b675-48bb693774d0@192.168.204.15@tcp:269/0 lens 504/448 e 0 to 0 dl 1787119244 ref 1 fl Interpret:/200/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 4466.731140] LustreError: 115622:0:(ldlm_lib.c:3345:target_send_reply_msg()) Skipped 1 previous similar message [ 4468.664567] Lustre: *** cfs_fail_loc=115, val=2147483648*** [ 4473.728708] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4475.669935] Lustre: Failing over lustre-MDT0000 [ 4475.892388] LustreError: 114968: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. [ 4475.914745] LustreError: 114968:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 2 previous similar messages [ 4475.962751] Lustre: server umount lustre-MDT0000 complete [ 4501.599892] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4507.617676] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3267 to 0x280000400:3297) [ 4507.619693] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3267 to 0x240000400:3329) [ 4507.639696] Lustre: 116471:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff93d2c345fb80 x1873925705123328/t270582939664(0) o36->4913e0be-d780-41d1-b675-48bb693774d0@192.168.204.15@tcp:310/0 lens 504/2880 e 0 to 0 dl 1787119285 ref 1 fl Interpret:/202/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 4507.695466] Lustre: 116471:0:(mdt_recovery.c:102:mdt_req_from_lrd()) Skipped 1 previous similar message [ 4516.536742] Lustre: DEBUG MARKER: == replay-single test 53h: open request and close reply while two MDC requests in flight ========================================================== 02:01:21 (1787119281) [ 4517.616948] Lustre: *** cfs_fail_loc=107, val=2147483648*** [ 4519.520429] Lustre: *** cfs_fail_loc=13b, val=315*** [ 4519.525403] Lustre: *** cfs_fail_loc=13b, val=2147483648*** [ 4519.531105] LustreError: 116474:0:(ldlm_lib.c:3345:target_send_reply_msg()) @@@ dropping reply req@ffff93d2f6067480 x1873925705135744/t274877906960(0) o35->4913e0be-d780-41d1-b675-48bb693774d0@192.168.204.15@tcp:322/0 lens 392/456 e 0 to 0 dl 1787119297 ref 1 fl Interpret:/600/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 4524.267372] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4525.949864] Lustre: Failing over lustre-MDT0000 [ 4526.186897] Lustre: server umount lustre-MDT0000 complete [ 4544.872115] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3267 to 0x280000400:3329) [ 4544.879857] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3331 to 0x240000400:3361) [ 4544.889780] Lustre: 117872:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff93d2c345dc00 x1873925705135744/t274877906960(0) o35->4913e0be-d780-41d1-b675-48bb693774d0@192.168.204.15@tcp:347/0 lens 392/456 e 0 to 0 dl 1787119322 ref 1 fl Interpret:/602/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 4548.020540] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4560.711148] Lustre: DEBUG MARKER: == replay-single test 55: let MDS_CHECK_RESENT return the original return code instead of 0 ========================================================== 02:02:04 (1787119324) [ 4561.871228] Lustre: *** cfs_fail_loc=12b, val=2147483991*** [ 4561.884753] LustreError: 117871:0:(ldlm_lib.c:3345:target_send_reply_msg()) @@@ dropping reply req@ffff93d1c269a300 x1873925705145600/t279172874255(0) o101->4913e0be-d780-41d1-b675-48bb693774d0@192.168.204.15@tcp:364/0 lens 664/608 e 0 to 0 dl 1787119339 ref 1 fl Interpret:/600/0 rc 301/0 job:'touch.0' uid:0 gid:0 projid:0 [ 4577.163062] Lustre: lustre-MDT0000: Client 4913e0be-d780-41d1-b675-48bb693774d0 (at 192.168.204.15@tcp) reconnecting [ 4577.172132] Lustre: Skipped 1 previous similar message [ 4577.185701] Lustre: 117871:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff93d2f46ba300 x1873925705145600/t279172874255(0) o101->4913e0be-d780-41d1-b675-48bb693774d0@192.168.204.15@tcp:380/0 lens 664/3488 e 0 to 0 dl 1787119355 ref 1 fl Interpret:/602/0 rc 0/0 job:'touch.0' uid:0 gid:0 projid:0 [ 4583.463738] Lustre: DEBUG MARKER: == replay-single test 56: don't replay a symlink open request (3440) ========================================================== 02:02:28 (1787119348) [ 4586.094289] LustreError: 118964:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 4586.098355] LustreError: 118964:0:(osd_handler.c:720:osd_ro()) Skipped 7 previous similar messages [ 4586.959495] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4588.689437] Lustre: Failing over lustre-MDT0000 [ 4588.952741] Lustre: server umount lustre-MDT0000 complete [ 4605.920645] LustreError: MGC192.168.204.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4605.932432] LustreError: Skipped 9 previous similar messages [ 4616.161632] LustreError: 3278:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff93d2f5c92300 x1873925712299136/t0(0) o250->MGC192.168.204.115@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 0 ref 1 fl Rpc:NQU/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4618.395194] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3267 to 0x280000400:3361) [ 4618.395340] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3363 to 0x240000400:3393) [ 4621.670946] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4630.524428] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4632.170959] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4650.709963] Lustre: DEBUG MARKER: == replay-single test 57: test recovery from llog for setattr op ========================================================== 02:03:35 (1787119415) [ 4655.243413] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4656.974694] Lustre: Failing over lustre-MDT0000 [ 4657.291143] Lustre: server umount lustre-MDT0000 complete [ 4685.891505] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3363 to 0x240000400:3425) [ 4685.893349] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3363 to 0x280000400:3393) [ 4689.116405] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4699.699387] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4701.937460] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4707.395552] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 4719.999805] Lustre: DEBUG MARKER: == replay-single test 58a: test recovery from llog for setattr op (test llog_gen_rec) ========================================================== 02:04:44 (1787119484) [ 4764.405134] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4766.268216] Lustre: Failing over lustre-MDT0000 [ 4766.843672] Lustre: server umount lustre-MDT0000 complete [ 4790.232394] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4793.615447] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:4644 to 0x280000400:4673) [ 4793.615967] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:4676 to 0x240000400:4705) [ 4799.298595] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4800.761247] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4857.757833] Lustre: DEBUG MARKER: == replay-single test 58b: test replay of setxattr op ==== 02:07:02 (1787119622) [ 4862.215562] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4864.109495] Lustre: Failing over lustre-MDT0000 [ 4864.417172] Lustre: server umount lustre-MDT0000 complete [ 4885.795992] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4887.173847] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:4644 to 0x280000400:4705) [ 4887.184865] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:4707 to 0x240000400:4737) [ 4894.991302] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4896.604851] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4906.252326] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount FULL mgc.*.mgs_server_uuid 1475 0 [ 4907.789969] Lustre: DEBUG MARKER: mgc.*.mgs_server_uuid in FULL state after 0 sec [ 4913.947700] Lustre: DEBUG MARKER: == replay-single test 58c: resend/reconstruct setxattr op ========================================================== 02:07:58 (1787119678) [ 4920.726964] Lustre: *** cfs_fail_loc=123, val=2147483648*** [ 4938.554838] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 4938.574040] Lustre: Skipped 1 previous similar message [ 4938.578230] LustreError: 125080:0:(ldlm_lib.c:3345:target_send_reply_msg()) @@@ dropping reply req@ffff93d2c9302850 x1873925707929856/t296352743435(0) o36->4913e0be-d780-41d1-b675-48bb693774d0@192.168.204.15@tcp:741/0 lens 66040/440 e 0 to 0 dl 1787119716 ref 1 fl Interpret:/600/0 rc 0/0 job:'setfattr.0' uid:0 gid:0 projid:0 [ 4954.005678] Lustre: 125080:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff93d2ed7b6300 x1873925707929856/t296352743435(0) o36->4913e0be-d780-41d1-b675-48bb693774d0@192.168.204.15@tcp:1/0 lens 66040/440 e 0 to 0 dl 1787119731 ref 1 fl Interpret:/602/0 rc 0/0 job:'setfattr.0' uid:0 gid:0 projid:0 [ 4961.684829] Lustre: DEBUG MARKER: SKIP: replay-single test_59 skipping ALWAYS excluded test 59 [ 4963.239744] Lustre: DEBUG MARKER: == replay-single test 60: test llog post recovery init vs llog unlink ========================================================== 02:08:48 (1787119728) [ 4972.506618] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4975.250488] Lustre: Failing over lustre-MDT0000 [ 4975.385225] LustreError: 3281:0:(client.c:1381:ptlrpc_import_delay_req()) @@@ IMP_CLOSED req@ffff93d2f5c92300 x1873925713048704/t0(0) o6->lustre-OST0000-osc-MDT0000@0@lo:28/4 lens 544/432 e 0 to 0 dl 0 ref 1 fl Rpc:QU/200/ffffffff rc 0/-1 job:'osp-syn-0-0.0' uid:0 gid:0 projid:4294967295 [ 4975.571481] Lustre: server umount lustre-MDT0000 complete [ 4993.241727] 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 [ 4993.253106] Lustre: Skipped 16 previous similar messages [ 4993.445320] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4993.452812] Lustre: Skipped 8 previous similar messages [ 4993.553534] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4993.559142] Lustre: Skipped 8 previous similar messages [ 4995.296331] Lustre: 3282:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787119746/real 1787119746] req@ffff93d2c46c1c00 x1873925713050112/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787119762 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4995.322494] Lustre: 3282:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 50 previous similar messages [ 4996.132415] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:4806 to 0x280000400:4833) [ 4996.143220] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:4839 to 0x240000400:4865) [ 4998.739442] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5007.706966] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5009.049767] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5018.994290] Lustre: DEBUG MARKER: == replay-single test 61a: test race llog recovery vs llog cleanup ========================================================== 02:09:43 (1787119783) [ 5037.501080] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 5050.914387] Lustre: Failing over lustre-OST0000 [ 5051.135278] Lustre: server umount lustre-OST0000 complete [ 5051.290363] LustreError: 34082:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.204.15@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 5052.455746] LustreError: lustre-OST0000-osc-MDT0000: operation ost_destroy to node 0@lo failed: rc = -107 [ 5052.478709] LustreError: Skipped 4 previous similar messages [ 5070.178231] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 5070.184140] Lustre: Skipped 7 previous similar messages [ 5072.246303] Lustre: lustre-OST0000: Recovery over after 0:02, of 2 clients 2 recovered and 0 were evicted. [ 5072.253934] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 5072.257394] Lustre: Skipped 7 previous similar messages [ 5072.287458] Lustre: Skipped 15 previous similar messages [ 5075.730189] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5090.077136] Lustre: Failing over lustre-OST0000 [ 5090.159359] Lustre: server umount lustre-OST0000 complete [ 5092.832320] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 5092.853047] LustreError: Skipped 3 previous similar messages [ 5114.343326] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5123.819158] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 5125.589329] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 5166.651756] Lustre: DEBUG MARKER: == replay-single test 61b: test race mds llog sync vs llog cleanup ========================================================== 02:12:11 (1787119931) [ 5169.649521] Lustre: Failing over lustre-MDT0000 [ 5170.088974] Lustre: server umount lustre-MDT0000 complete [ 5188.697522] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5266 to 0x240000400:5281) [ 5188.699582] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5234 to 0x280000400:5249) [ 5192.982910] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5207.745787] Lustre: Failing over lustre-MDT0000 [ 5207.986403] Lustre: server umount lustre-MDT0000 complete [ 5224.415390] LustreError: MGC192.168.204.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5224.423965] LustreError: Skipped 5 previous similar messages [ 5235.744579] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5266 to 0x240000400:5313) [ 5235.749302] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5234 to 0x280000400:5281) [ 5239.707615] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5249.676806] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5251.605452] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5259.761768] Lustre: DEBUG MARKER: == replay-single test 61c: test race mds llog sync vs llog cleanup ========================================================== 02:13:44 (1787120024) [ 5273.388748] Lustre: Failing over lustre-OST0000 [ 5275.113145] Lustre: lustre-OST0000: Not available for connect from 0@lo (stopping) [ 5275.123250] Lustre: Skipped 3 previous similar messages [ 5275.548427] Lustre: server umount lustre-OST0000 complete [ 5299.638502] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5309.599305] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 5311.181348] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 5319.608234] Lustre: DEBUG MARKER: == replay-single test 61d: error in llog_setup should cleanup the llog context correctly ========================================================== 02:14:44 (1787120084) [ 5321.496447] Lustre: Failing over lustre-MDT0000 [ 5321.774217] Lustre: server umount lustre-MDT0000 complete [ 5329.267828] Lustre: *** cfs_fail_loc=605, val=0*** [ 5329.270912] LustreError: 135820:0:(llog_obd.c:192:llog_setup()) MGS: ctxt 0 lop_setup=ffffffffc1364320 failed: rc = -95 [ 5329.280857] LustreError: 135820:0:(obd_config.c:845:class_setup()) setup MGS failed (-95) [ 5329.287502] LustreError: 135820:0:(obd_mount.c:259:lustre_start_simple()) MGS setup error -95 [ 5329.293845] LustreError: 135820:0:(tgt_mount.c:116:server_deregister_mount()) MGS not registered [ 5329.300482] LustreError: Failed to start MGS 'MGS' (-95). Is the 'mgs' module loaded? [ 5329.309411] LustreError: 135820:0:(tgt_mount.c:2129:server_put_super()) no obd lustre-MDT0000 [ 5329.454651] Lustre: server umount lustre-MDT0000 complete [ 5329.456660] LustreError: 135820:0:(super25.c:178:lustre_fill_super()) llite: Unable to mount : rc = -95 [ 5338.165728] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5315 to 0x240000400:5345) [ 5338.166094] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5283 to 0x280000400:5313) [ 5340.565879] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5349.020546] Lustre: DEBUG MARKER: == replay-single test 62: don't mis-drop resent replay === 02:15:13 (1787120113) [ 5351.947653] LustreError: 136817:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 5351.951358] LustreError: 136817:0:(osd_handler.c:720:osd_ro()) Skipped 5 previous similar messages [ 5352.773787] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5355.881736] Lustre: Failing over lustre-MDT0000 [ 5356.002247] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5356.008653] Lustre: Skipped 1 previous similar message [ 5356.270567] Lustre: server umount lustre-MDT0000 complete [ 5375.532129] Lustre: *** cfs_fail_loc=707, val=0*** [ 5377.859091] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5391.773225] Lustre: lustre-MDT0000: Client 4913e0be-d780-41d1-b675-48bb693774d0 (at 192.168.204.15@tcp) reconnected, waiting for 1 clients in recovery for 0:53 [ 5392.272051] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5359 to 0x240000400:5377) [ 5392.272887] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5326 to 0x280000400:5345) [ 5397.830581] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5399.313279] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5408.976455] Lustre: DEBUG MARKER: == replay-single test 65a: AT: verify early replies ====== 02:16:13 (1787120173) [ 5438.475227] LustreError: 137824:0:(service.c:2558:ptlrpc_server_handle_request()) @@@ HIT req@ffff93d1c8f32300 x1873925708803712/t0(0) o101->4913e0be-d780-41d1-b675-48bb693774d0@192.168.204.15@tcp:486/0 lens 664/0 e 0 to 0 dl 1787120216 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 5438.491607] LustreError: 137824:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a sleeping for 11000ms [ 5449.527130] LustreError: 137824:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a awake [ 5449.567317] LustreError: 137424:0:(service.c:2558:ptlrpc_server_handle_request()) @@@ HIT req@ffff93d2c5757800 x1873925708804480/t0(0) o35->4913e0be-d780-41d1-b675-48bb693774d0@192.168.204.15@tcp:503/0 lens 392/0 e 0 to 0 dl 1787120233 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 5451.342050] LustreError: 137422:0:(service.c:2558:ptlrpc_server_handle_request()) @@@ HIT req@ffff93d2ed791180 x1873925708810368/t0(0) o101->4913e0be-d780-41d1-b675-48bb693774d0@192.168.204.15@tcp:538/0 lens 576/0 e 0 to 0 dl 1787120268 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'unlinkmany.0' uid:0 gid:0 projid:0 [ 5451.373186] LustreError: 137422:0:(service.c:2558:ptlrpc_server_handle_request()) Skipped 27 previous similar messages [ 5453.830711] LustreError: 35666:0:(service.c:2558:ptlrpc_server_handle_request()) @@@ HIT req@ffff93d1c430f800 x1873925713315456/t0(0) o6->lustre-MDT0000-mdtlov_UUID@0@lo:501/0 lens 544/0 e 0 to 0 dl 1787120231 ref 1 fl Interpret:/200/ffffffff rc 0/-1 job:'osp-syn-1-0.0' uid:0 gid:0 projid:4294967295 [ 5453.852767] LustreError: 35666:0:(service.c:2558:ptlrpc_server_handle_request()) Skipped 24 previous similar messages [ 5458.954941] LustreError: 35665:0:(service.c:2558:ptlrpc_server_handle_request()) @@@ HIT req@ffff93d2c691f800 x1873925713317248/t0(0) o6->lustre-MDT0000-mdtlov_UUID@0@lo:506/0 lens 544/0 e 0 to 0 dl 1787120236 ref 1 fl Interpret:/200/ffffffff rc 0/-1 job:'osp-syn-0-0.0' uid:0 gid:0 projid:4294967295 [ 5458.976067] LustreError: 35665:0:(service.c:2558:ptlrpc_server_handle_request()) Skipped 3 previous similar messages [ 5466.728475] Lustre: DEBUG MARKER: == replay-single test 65b: AT: verify early replies on packed reply / bulk ========================================================== 02:17:11 (1787120231) [ 5496.269439] LustreError: 6579:0:(tgt_handler.c:2830:tgt_brw_write()) cfs_fail_timeout id 224 sleeping for 11000ms [ 5507.319073] LustreError: 6579:0:(tgt_handler.c:2830:tgt_brw_write()) cfs_fail_timeout id 224 awake [ 5516.311953] Lustre: DEBUG MARKER: == replay-single test 66a: AT: verify MDT service time adjusts with no early replies ========================================================== 02:18:00 (1787120280) [ 5544.145108] LustreError: 137423:0:(service.c:2558:ptlrpc_server_handle_request()) @@@ HIT req@ffff93d1ca40ce00 x1873925708825984/t0(0) o101->4913e0be-d780-41d1-b675-48bb693774d0@192.168.204.15@tcp:591/0 lens 576/0 e 0 to 0 dl 1787120321 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 5544.163266] LustreError: 137423:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a sleeping for 5000ms [ 5549.263244] LustreError: 137423:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a awake [ 5561.735146] LustreError: 137824:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a awake [ 5561.749840] LustreError: 137420:0:(service.c:2558:ptlrpc_server_handle_request()) @@@ HIT req@ffff93d1c937b480 x1873925708847872/t0(0) o101->4913e0be-d780-41d1-b675-48bb693774d0@192.168.204.15@tcp:649/0 lens 664/0 e 0 to 0 dl 1787120379 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 5561.775598] LustreError: 137420:0:(service.c:2558:ptlrpc_server_handle_request()) Skipped 120 previous similar messages [ 5580.105410] Lustre: DEBUG MARKER: == replay-single test 66b: AT: verify net latency adjusts ========================================================== 02:19:05 (1787120345) [ 5682.431029] Lustre: DEBUG MARKER: == replay-single test 67a: AT: verify slow request processing doesn't induce reconnects ========================================================== 02:20:47 (1787120447) [ 5710.857909] LustreError: 140437:0:(service.c:2558:ptlrpc_server_handle_request()) @@@ HIT req@ffff93d1c90c8380 x1873925708901888/t0(0) o101->4913e0be-d780-41d1-b675-48bb693774d0@192.168.204.15@tcp:3/0 lens 576/0 e 0 to 0 dl 1787120488 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 5710.879552] LustreError: 140437:0:(service.c:2558:ptlrpc_server_handle_request()) Skipped 98 previous similar messages [ 5710.885810] LustreError: 140437:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a sleeping for 400ms [ 5710.899503] LustreError: 140437:0:(service.c:2559:ptlrpc_server_handle_request()) Skipped 1 previous similar message [ 5711.322034] LustreError: 140437:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a awake [ 5727.200428] LustreError: 137424:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a sleeping for 400ms [ 5727.215621] LustreError: 137424:0:(service.c:2559:ptlrpc_server_handle_request()) Skipped 37 previous similar messages [ 5727.644342] LustreError: 137424:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a awake [ 5727.649036] LustreError: 137424:0:(service.c:2559:ptlrpc_server_handle_request()) Skipped 37 previous similar messages [ 5761.046511] Lustre: DEBUG MARKER: == replay-single test 67b: AT: verify instant slowdown doesn't induce reconnects ========================================================== 02:22:05 (1787120525) [ 5794.061529] Lustre: DEBUG MARKER: phase 2 [ 5803.591704] Lustre: DEBUG MARKER: == replay-single test 68: AT: verify slowing locks ======= 02:22:48 (1787120568) [ 5884.611931] Lustre: DEBUG MARKER: == replay-single test 70a: check multi client t-f ======== 02:24:09 (1787120649) [ 5885.771965] Lustre: DEBUG MARKER: SKIP: replay-single test_70a Need two or more clients, have 1 [ 5887.170568] Lustre: DEBUG MARKER: == replay-single test 70b: dbench 1mdts recovery; 1 clients ========================================================== 02:24:12 (1787120652) [ 5891.147541] Lustre: DEBUG MARKER: Started rundbench load pid=128046 ... [ 5896.215202] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5898.875155] Lustre: DEBUG MARKER: test_70b fail mds1 1 times [ 5900.700525] Lustre: Failing over lustre-MDT0000 [ 5901.022148] Lustre: server umount lustre-MDT0000 complete [ 5918.532904] LustreError: MGC192.168.204.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5918.543310] LustreError: Skipped 2 previous similar messages [ 5918.694542] 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 [ 5918.712333] Lustre: Skipped 11 previous similar messages [ 5918.720121] LustreError: 144858: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. [ 5918.734470] LustreError: 144858:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 19 previous similar messages [ 5919.065087] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 5919.069347] Lustre: Skipped 7 previous similar messages [ 5919.170942] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 5919.180524] Lustre: Skipped 7 previous similar messages [ 5919.716035] Lustre: 3282:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787120670/real 1787120670] req@ffff93d1c937ad80 x1873925713449472/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787120686 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5919.749128] Lustre: 3282:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 25 previous similar messages [ 5923.461162] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5924.360796] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 5924.374833] Lustre: Skipped 10 previous similar messages [ 5937.097448] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 5937.125481] Lustre: Skipped 6 previous similar messages [ 5937.877943] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 5937.889644] Lustre: Skipped 6 previous similar messages [ 5937.928893] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5480 to 0x240000400:5505) [ 5937.930693] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5427 to 0x280000400:5473) [ 5944.370602] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5946.149930] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5952.181189] LustreError: 145687:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 5952.185863] LustreError: 145687:0:(osd_handler.c:720:osd_ro()) Skipped 1 previous similar message [ 5953.149592] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5956.174890] Lustre: DEBUG MARKER: test_70b fail mds1 2 times [ 5957.938990] Lustre: Failing over lustre-MDT0000 [ 5957.955769] Lustre: lustre-MDT0000: Not available for connect from 192.168.204.15@tcp (stopping) [ 5958.133732] Lustre: server umount lustre-MDT0000 complete [ 5978.387063] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5499 to 0x280000400:5537) [ 5978.389619] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5532 to 0x240000400:5569) [ 5981.226417] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5990.350724] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5991.850720] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5998.281491] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 6000.696660] Lustre: DEBUG MARKER: test_70b fail mds1 3 times [ 6002.346591] Lustre: Failing over lustre-MDT0000 [ 6002.610834] Lustre: server umount lustre-MDT0000 complete [ 6023.126484] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5617 to 0x240000400:5633) [ 6023.126583] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5586 to 0x280000400:5601) [ 6026.051442] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6034.787884] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6036.507933] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6043.579901] Lustre: DEBUG MARKER: == replay-single test 70c: tar 1mdts recovery ============ 02:26:48 (1787120808) [ 6168.550299] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 6181.105747] Lustre: DEBUG MARKER: test_70c fail mds1 1 times [ 6183.534178] Lustre: Failing over lustre-MDT0000 [ 6183.899788] Lustre: server umount lustre-MDT0000 complete [ 6216.596296] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6231.247580] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6262 to 0x280000400:6305) [ 6231.250627] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6295 to 0x240000400:6337) [ 6237.465506] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6239.234837] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6340.454350] Lustre: DEBUG MARKER: == replay-single test 70d: mkdir/rmdir striped dir 1mdts recovery ========================================================== 02:31:45 (1787121105) [ 6342.010397] Lustre: DEBUG MARKER: SKIP: replay-single test_70d needs >= 2 MDTs [ 6343.896582] Lustre: DEBUG MARKER: == replay-single test 70e: rename cross-MDT with random fails ========================================================== 02:31:48 (1787121108) [ 6345.584977] Lustre: DEBUG MARKER: SKIP: replay-single test_70e needs >= 2 MDTs [ 6347.484127] Lustre: DEBUG MARKER: == replay-single test 70f: OSS O_DIRECT recovery with 1 clients ========================================================== 02:31:52 (1787121112) [ 6355.947257] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 6358.900861] Lustre: DEBUG MARKER: test_70f failing OST 1 times [ 6361.254353] Lustre: Failing over lustre-OST0000 [ 6361.322700] Lustre: server umount lustre-OST0000 complete [ 6364.139156] LustreError: 11617: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. [ 6386.994893] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6397.402760] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 6399.681765] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 6410.667663] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 6413.464646] Lustre: DEBUG MARKER: test_70f failing OST 2 times [ 6415.284750] Lustre: Failing over lustre-OST0000 [ 6415.339951] Lustre: server umount lustre-OST0000 complete [ 6431.209706] LustreError: 35654: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. [ 6431.240588] LustreError: 35654:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 12 previous similar messages [ 6444.328260] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6455.259147] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 6457.514911] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 6469.418185] Lustre: DEBUG MARKER: == replay-single test 71a: mkdir/rmdir striped dir with 2 mdts recovery ========================================================== 02:33:53 (1787121233) [ 6471.322124] Lustre: DEBUG MARKER: SKIP: replay-single test_71a needs >= 2 MDTs [ 6473.794263] Lustre: DEBUG MARKER: == replay-single test 73a: open(O_CREAT), unlink, replay, reconnect before open replay, close ========================================================== 02:33:57 (1787121237) [ 6478.328520] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 6481.405776] Lustre: Failing over lustre-MDT0000 [ 6481.746324] Lustre: server umount lustre-MDT0000 complete [ 6506.787524] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6509.463246] Lustre: *** cfs_fail_loc=302, val=2147483648*** [ 6525.901833] Lustre: lustre-MDT0000: Client 4913e0be-d780-41d1-b675-48bb693774d0 (at 192.168.204.15@tcp) reconnected, waiting for 1 clients in recovery for 0:53 [ 6526.106889] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6581 to 0x280000400:6625) [ 6526.107662] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6614 to 0x240000400:6657) [ 6532.156287] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6534.002215] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6542.076478] Lustre: DEBUG MARKER: == replay-single test 73b: open(O_CREAT), unlink, replay, reconnect at open_replay reply, close ========================================================== 02:35:06 (1787121306) [ 6545.998558] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 6548.626175] Lustre: Failing over lustre-MDT0000 [ 6548.887818] Lustre: server umount lustre-MDT0000 complete [ 6566.753085] LustreError: MGC192.168.204.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 6566.769175] LustreError: Skipped 4 previous similar messages [ 6566.843173] LustreError: 156153:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.204.15@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 6566.867228] LustreError: 156153:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 1 previous similar message [ 6567.124935] 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 [ 6567.140180] Lustre: Skipped 11 previous similar messages [ 6567.295253] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 6567.299387] Lustre: Skipped 6 previous similar messages [ 6567.368186] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 6567.380490] Lustre: Skipped 6 previous similar messages [ 6567.972390] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 6567.983359] Lustre: Skipped 6 previous similar messages [ 6568.046290] Lustre: *** cfs_fail_loc=157, val=2147483648*** [ 6568.052555] LustreError: 156155:0:(ldlm_lib.c:3345:target_send_reply_msg()) @@@ dropping reply req@ffff93d2c46d1f80 x1873925717381376/t339302416387(339302416387) o101->4913e0be-d780-41d1-b675-48bb693774d0@192.168.204.15@tcp:105/0 lens 592/608 e 0 to 0 dl 1787121345 ref 1 fl Interpret:/604/0 rc 301/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 6568.159738] Lustre: 3282:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787121318/real 1787121318] req@ffff93d2d8275880 x1873925714539136/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787121334 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6568.189708] Lustre: 3282:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 37 previous similar messages [ 6571.408602] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6572.518654] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 6572.533138] Lustre: Skipped 11 previous similar messages [ 6584.242094] Lustre: lustre-MDT0000: Client 4913e0be-d780-41d1-b675-48bb693774d0 (at 192.168.204.15@tcp) reconnected, waiting for 1 clients in recovery for 0:53 [ 6584.271064] Lustre: 156155:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff93d2d8275500 x1873925717381376/t339302416387(339302416387) o101->4913e0be-d780-41d1-b675-48bb693774d0@192.168.204.15@tcp:122/0 lens 592/3488 e 0 to 0 dl 1787121362 ref 1 fl Interpret:/606/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 6584.430408] Lustre: lustre-MDT0000: Recovery over after 0:17, of 1 clients 1 recovered and 0 were evicted. [ 6584.443873] Lustre: Skipped 6 previous similar messages [ 6584.483341] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6581 to 0x280000400:6657) [ 6584.483913] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6659 to 0x240000400:6689) [ 6589.624524] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6590.963571] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6598.723882] Lustre: DEBUG MARKER: == replay-single test 74: Ensure applications don't fail waiting for OST recovery ========================================================== 02:36:03 (1787121363) [ 6602.031694] Lustre: Failing over lustre-OST0000 [ 6602.191182] Lustre: server umount lustre-OST0000 complete [ 6606.198479] Lustre: Failing over lustre-MDT0000 [ 6606.532332] Lustre: server umount lustre-MDT0000 complete [ 6624.640738] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6581 to 0x280000400:6689) [ 6628.937498] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6636.933745] Lustre: lustre-OST0000: Denying connection for new client 628771e9-df89-425d-b099-a1d7797efa1d (at 192.168.204.15@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:59 [ 6636.958582] Lustre: Skipped 11 previous similar messages [ 6641.775825] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6659 to 0x240000400:6721) [ 6642.628299] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6653.178783] Lustre: DEBUG MARKER: == replay-single test 80a: DNE: create remote dir, drop update rep from MDT0, fail MDT0 ========================================================== 02:36:57 (1787121417) [ 6654.728332] Lustre: DEBUG MARKER: SKIP: replay-single test_80a needs >= 2 MDTs [ 6656.213632] Lustre: DEBUG MARKER: == replay-single test 80b: DNE: create remote dir, drop update rep from MDT0, fail MDT1 ========================================================== 02:37:01 (1787121421) [ 6657.535919] Lustre: DEBUG MARKER: SKIP: replay-single test_80b needs >= 2 MDTs [ 6658.889684] Lustre: DEBUG MARKER: == replay-single test 80c: DNE: create remote dir, drop update rep from MDT1, fail MDT[0,1] ========================================================== 02:37:03 (1787121423) [ 6660.474725] Lustre: DEBUG MARKER: SKIP: replay-single test_80c needs >= 2 MDTs [ 6662.177784] Lustre: DEBUG MARKER: == replay-single test 80d: DNE: create remote dir, drop update rep from MDT1, fail 2 MDTs ========================================================== 02:37:06 (1787121426) [ 6663.842724] Lustre: DEBUG MARKER: SKIP: replay-single test_80d needs >= 2 MDTs [ 6666.004927] Lustre: DEBUG MARKER: == replay-single test 80e: DNE: create remote dir, drop MDT1 rep, fail MDT0 ========================================================== 02:37:10 (1787121430) [ 6667.473717] Lustre: DEBUG MARKER: SKIP: replay-single test_80e needs >= 2 MDTs [ 6669.221529] Lustre: DEBUG MARKER: == replay-single test 80f: DNE: create remote dir, drop MDT1 rep, fail MDT1 ========================================================== 02:37:13 (1787121433) [ 6671.034949] Lustre: DEBUG MARKER: SKIP: replay-single test_80f needs >= 2 MDTs [ 6673.267256] Lustre: DEBUG MARKER: == replay-single test 80g: DNE: create remote dir, drop MDT1 rep, fail MDT0, then MDT1 ========================================================== 02:37:17 (1787121437) [ 6675.149841] Lustre: DEBUG MARKER: SKIP: replay-single test_80g needs >= 2 MDTs [ 6676.964478] Lustre: DEBUG MARKER: == replay-single test 80h: DNE: create remote dir, drop MDT1 rep, fail 2 MDTs ========================================================== 02:37:21 (1787121441) [ 6679.176967] Lustre: DEBUG MARKER: SKIP: replay-single test_80h needs >= 2 MDTs [ 6680.752736] Lustre: DEBUG MARKER: == replay-single test 81a: DNE: unlink remote dir, drop MDT0 update rep, fail MDT1 ========================================================== 02:37:25 (1787121445) [ 6682.609652] Lustre: DEBUG MARKER: SKIP: replay-single test_81a needs >= 2 MDTs [ 6684.257396] Lustre: DEBUG MARKER: == replay-single test 81b: DNE: unlink remote dir, drop MDT0 update reply, fail MDT0 ========================================================== 02:37:29 (1787121449) [ 6685.904697] Lustre: DEBUG MARKER: SKIP: replay-single test_81b needs >= 2 MDTs [ 6688.005478] Lustre: DEBUG MARKER: == replay-single test 81c: DNE: unlink remote dir, drop MDT0 update reply, fail MDT0,MDT1 ========================================================== 02:37:32 (1787121452) [ 6689.588120] Lustre: DEBUG MARKER: SKIP: replay-single test_81c needs >= 2 MDTs [ 6691.922024] Lustre: DEBUG MARKER: == replay-single test 81d: DNE: unlink remote dir, drop MDT0 update reply, fail 2 MDTs ========================================================== 02:37:36 (1787121456) [ 6694.064630] Lustre: DEBUG MARKER: SKIP: replay-single test_81d needs >= 2 MDTs [ 6695.591599] Lustre: DEBUG MARKER: == replay-single test 81e: DNE: unlink remote dir, drop MDT1 req reply, fail MDT0 ========================================================== 02:37:40 (1787121460) [ 6696.647657] Lustre: DEBUG MARKER: SKIP: replay-single test_81e needs >= 2 MDTs [ 6698.071899] Lustre: DEBUG MARKER: == replay-single test 81f: DNE: unlink remote dir, drop MDT1 req reply, fail MDT1 ========================================================== 02:37:42 (1787121462) [ 6699.408539] Lustre: DEBUG MARKER: SKIP: replay-single test_81f needs >= 2 MDTs [ 6701.053643] Lustre: DEBUG MARKER: == replay-single test 81g: DNE: unlink remote dir, drop req reply, fail M0, then M1 ========================================================== 02:37:45 (1787121465) [ 6702.368839] Lustre: DEBUG MARKER: SKIP: replay-single test_81g needs >= 2 MDTs [ 6704.205571] Lustre: DEBUG MARKER: == replay-single test 81h: DNE: unlink remote dir, drop request reply, fail 2 MDTs ========================================================== 02:37:48 (1787121468) [ 6706.331518] Lustre: DEBUG MARKER: SKIP: replay-single test_81h needs >= 2 MDTs [ 6708.053126] Lustre: DEBUG MARKER: == replay-single test 84a: stale open during export disconnect ========================================================== 02:37:52 (1787121472) [ 6709.930927] Lustre: 160693:0:(genops.c:1795:obd_export_evict_by_uuid()) lustre-MDT0000: evicting 628771e9-df89-425d-b099-a1d7797efa1d at adminstrative request [ 6719.907632] Lustre: DEBUG MARKER: == replay-single test 85a: check the cancellation of unused locks during recovery(IBITS) ========================================================== 02:38:04 (1787121484) [ 6726.852479] Lustre: Failing over lustre-MDT0000 [ 6727.289237] Lustre: server umount lustre-MDT0000 complete [ 6754.272194] LustreError: 3278:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff93d2c8290e00 x1873925714589184/t0(0) o250->MGC192.168.204.115@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 0 ref 1 fl Rpc:NQU/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6756.996614] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6773 to 0x240000400:6817) [ 6756.999181] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6741 to 0x280000400:6785) [ 6759.512891] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6768.812497] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6770.595378] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6779.470736] Lustre: DEBUG MARKER: == replay-single test 85b: check the cancellation of unused locks during recovery(EXTENT) ========================================================== 02:39:04 (1787121544) [ 6796.149352] Lustre: Failing over lustre-OST0000 [ 6796.268962] Lustre: server umount lustre-OST0000 complete [ 6800.867284] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 6819.295627] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6828.158518] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 6829.494631] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 6839.086692] Lustre: DEBUG MARKER: == replay-single test 86: umount server after clear nid_stats should not hit LBUG ========================================================== 02:40:03 (1787121603) [ 6843.485483] Lustre: Failing over lustre-MDT0000 [ 6843.858962] Lustre: server umount lustre-MDT0000 complete [ 6850.914033] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6918 to 0x240000400:6945) [ 6850.914185] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6741 to 0x280000400:6817) [ 6856.244769] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6864.854071] Lustre: DEBUG MARKER: == replay-single test 87a: write replay ================== 02:40:29 (1787121629) [ 6868.670491] LustreError: 164989:0:(osd_handler.c:720:osd_ro()) lustre-OST0000: *** setting device osd-zfs read-only *** [ 6868.678495] LustreError: 164989:0:(osd_handler.c:720:osd_ro()) Skipped 6 previous similar messages [ 6869.503971] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 6872.294461] Lustre: Failing over lustre-OST0000 [ 6872.360982] Lustre: server umount lustre-OST0000 complete [ 6874.002368] LustreError: 35664:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.204.15@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 6874.013092] LustreError: 35664:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 12 previous similar messages [ 6876.127657] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 6897.441342] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6908.767926] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 6910.810173] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 6920.229253] Lustre: DEBUG MARKER: == replay-single test 87b: write replay with changed data (checksum resend) ========================================================== 02:41:24 (1787121684) [ 6925.355476] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 6929.062704] Lustre: Failing over lustre-OST0000 [ 6929.138045] Lustre: server umount lustre-OST0000 complete [ 6948.173362] LustreError: lustre-OST0000: BAD WRITE CHECKSUM: from 12345-192.168.204.15@tcp inode [0x200028c71:0x5:0x0] object 0x240000400:6947 extent [0-1048575]: client csum f2351cfa, server csum a7d99274 [ 6952.767140] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6962.040985] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 6963.597935] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 6972.091696] Lustre: DEBUG MARKER: == replay-single test 88: MDS should not assign same objid to different files ========================================================== 02:42:16 (1787121736) [ 6976.208180] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 6980.422707] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 6986.865041] Lustre: Failing over lustre-MDT0000 [ 6987.140658] Lustre: server umount lustre-MDT0000 complete [ 6990.866843] LustreError: 8277:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787121757 with bad export cookie 12070242935900519126 [ 7001.066160] Lustre: Failing over lustre-OST0000 [ 7001.159051] Lustre: server umount lustre-OST0000 complete [ 7040.591111] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7053.063591] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6856 to 0x280000400:6881) [ 7064.161106] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6948 to 0x240000400:6977) [ 7065.787424] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7081.814743] Lustre: DEBUG MARKER: == replay-single test 89: no disk space leak on late ost connection ========================================================== 02:44:06 (1787121846) [ 7098.904417] Lustre: Failing over lustre-OST0000 [ 7099.876515] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 7099.894161] Lustre: lustre-OST0000: Not available for connect from 0@lo (stopping) [ 7101.066489] Lustre: server umount lustre-OST0000 complete [ 7105.036896] Lustre: Failing over lustre-MDT0000 [ 7105.388801] Lustre: server umount lustre-MDT0000 complete [ 7128.600996] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7132.393170] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6856 to 0x280000400:6913) [ 7144.986456] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7147.309942] Lustre: lustre-OST0000: Denying connection for new client 19ed6851-0ae9-41b1-b440-394fedf7579e (at 192.168.204.15@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 1:05 [ 7147.355382] Lustre: Skipped 1 previous similar message [ 7167.877957] Lustre: lustre-OST0000: Denying connection for new client 19ed6851-0ae9-41b1-b440-394fedf7579e (at 192.168.204.15@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 0:44 [ 7167.901704] Lustre: Skipped 3 previous similar messages [ 7203.720444] Lustre: lustre-OST0000: Denying connection for new client 19ed6851-0ae9-41b1-b440-394fedf7579e (at 192.168.204.15@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 0:08 [ 7203.737166] Lustre: Skipped 6 previous similar messages [ 7212.500195] Lustre: lustre-OST0000: recovery is timed out, evict stale exports [ 7212.504878] Lustre: 172624:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-OST0000: disconnect stale client e43ec2f6-bc23-48b9-a0d9-08edca4f28f1@ [ 7212.531511] Lustre: lustre-OST0000: disconnecting 1 stale clients [ 7212.635647] Lustre: lustre-OST0000: Recovery over after 1:10, of 2 clients 1 recovered and 1 was evicted. [ 7212.639145] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 7212.653567] Lustre: Skipped 8 previous similar messages [ 7212.664824] Lustre: Skipped 13 previous similar messages [ 7212.691887] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6988 to 0x240000400:7009) [ 7216.514756] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 59 sec [ 7231.645658] Lustre: DEBUG MARKER: free_before: 7520256 free_after: 7520256 [ 7238.234963] Lustre: DEBUG MARKER: == replay-single test 90: lfs find identifies the missing striped file segments ========================================================== 02:46:42 (1787122002) [ 7242.451098] Lustre: Failing over lustre-OST0000 [ 7242.527266] Lustre: server umount lustre-OST0000 complete [ 7243.755105] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 7243.768642] 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 [ 7243.782290] Lustre: Skipped 13 previous similar messages [ 7260.701393] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 7260.707608] Lustre: Skipped 11 previous similar messages [ 7260.713379] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 7260.721587] Lustre: Skipped 9 previous similar messages [ 7262.499726] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 7262.507970] Lustre: Skipped 9 previous similar messages [ 7267.240601] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7277.792736] Lustre: DEBUG MARKER: == replay-single test 93a: replay + reconnect ============ 02:47:22 (1787122042) [ 7281.401708] Lustre: Failing over lustre-OST0000 [ 7281.564847] Lustre: server umount lustre-OST0000 complete [ 7283.680631] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 7301.532479] LustreError: 175609:0:(ldlm_lib.c:2904:target_recovery_thread()) cfs_fail_timeout id 715 sleeping for 40000ms [ 7301.540862] LustreError: 175609:0:(ldlm_lib.c:2904:target_recovery_thread()) Skipped 76 previous similar messages [ 7306.441785] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7307.233367] Lustre: *** cfs_fail_loc=715, val=40*** [ 7316.868805] Lustre: lustre-OST0000: Client 19ed6851-0ae9-41b1-b440-394fedf7579e (at 192.168.204.15@tcp) reconnected, waiting for 2 clients in recovery for 1:25 [ 7317.984554] Lustre: 3278:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787122068/real 1787122068] req@ffff93d2d698f100 x1873925714756352/t0(0) o400->lustre-OST0000-osc-MDT0000@0@lo:28/4 lens 224/224 e 0 to 1 dl 1787122084 ref 1 fl Rpc:XQr/2c0/ffffffff rc 0/-1 job:'ldlm_lock_repla.0' uid:0 gid:0 projid:4294967295 [ 7318.025153] Lustre: 3278:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 29 previous similar messages [ 7318.032482] Lustre: lustre-OST0000: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnected, waiting for 2 clients in recovery for 1:24 [ 7323.103612] Lustre: *** cfs_fail_loc=715, val=40*** [ 7323.111785] Lustre: Skipped 1 previous similar message [ 7324.127418] Lustre: *** cfs_fail_loc=715, val=40*** [ 7333.255382] Lustre: lustre-OST0000: Client 19ed6851-0ae9-41b1-b440-394fedf7579e (at 192.168.204.15@tcp) reconnected, waiting for 2 clients in recovery for 1:09 [ 7339.487379] Lustre: *** cfs_fail_loc=715, val=40*** [ 7341.623131] LustreError: 175609:0:(ldlm_lib.c:2904:target_recovery_thread()) cfs_fail_timeout id 715 awake [ 7341.634875] LustreError: 175609:0:(ldlm_lib.c:2904:target_recovery_thread()) Skipped 76 previous similar messages [ 7348.002458] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 7350.114717] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 7359.133211] Lustre: DEBUG MARKER: == replay-single test 93b: replay + reconnect on mds ===== 02:48:43 (1787122123) [ 7363.952878] Lustre: Failing over lustre-MDT0000 [ 7364.065334] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 7364.077027] Lustre: Skipped 1 previous similar message [ 7364.241789] Lustre: server umount lustre-MDT0000 complete [ 7381.435702] LustreError: MGC192.168.204.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 7381.440128] LustreError: Skipped 5 previous similar messages [ 7386.713853] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7391.137769] LustreError: 177178:0:(ldlm_lib.c:2904:target_recovery_thread()) cfs_fail_timeout id 715 sleeping for 80000ms [ 7397.343606] Lustre: *** cfs_fail_loc=715, val=80*** [ 7397.345044] Lustre: Skipped 1 previous similar message [ 7407.495081] Lustre: lustre-MDT0000: Client 19ed6851-0ae9-41b1-b440-394fedf7579e (at 192.168.204.15@tcp) reconnected, waiting for 1 clients in recovery for 0:54 [ 7407.506591] Lustre: Skipped 1 previous similar message [ 7413.727156] Lustre: *** cfs_fail_loc=715, val=80*** [ 7423.881447] Lustre: lustre-MDT0000: Client 19ed6851-0ae9-41b1-b440-394fedf7579e (at 192.168.204.15@tcp) reconnected, waiting for 1 clients in recovery for 0:37 [ 7430.114603] Lustre: *** cfs_fail_loc=715, val=80*** [ 7440.260547] Lustre: lustre-MDT0000: Client 19ed6851-0ae9-41b1-b440-394fedf7579e (at 192.168.204.15@tcp) reconnected, waiting for 1 clients in recovery for 0:21 [ 7456.646166] Lustre: lustre-MDT0000: Client 19ed6851-0ae9-41b1-b440-394fedf7579e (at 192.168.204.15@tcp) reconnected, waiting for 1 clients in recovery for 0:04 [ 7462.879238] Lustre: *** cfs_fail_loc=715, val=80*** [ 7462.888021] Lustre: Skipped 1 previous similar message [ 7471.188678] LustreError: 177178:0:(ldlm_lib.c:2904:target_recovery_thread()) cfs_fail_timeout id 715 awake [ 7471.302850] Lustre: 177178:0:(ldlm_lib.c:2950:target_recovery_thread()) too long recovery - read logs [ 7471.334104] LustreError: dumping log to /tmp/lustre-log.1787122238.177178 [ 7471.437579] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6926 to 0x280000400:6945) [ 7471.440189] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:7023 to 0x240000400:7041) [ 7479.155982] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 7481.474956] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7492.610759] Lustre: DEBUG MARKER: == replay-single test complete, duration 7271 sec ======== 02:50:57 (1787122257) [ 7494.410909] Lustre: DEBUG MARKER: === replay-single: start cleanup 02:50:58 (1787122258) === [ 7504.636215] Lustre: DEBUG MARKER: === replay-single: finish cleanup 02:51:09 (1787122269) === [ 7506.467290] Lustre: Failing over lustre-MDT0000 [ 7506.767798] Lustre: server umount lustre-MDT0000 complete [ 7533.544223] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xa7821dffd3053708 [ 7542.314535] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7548.906988] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:7023 to 0x240000400:7073) [ 7548.907274] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6926 to 0x280000400:6977) [ 7555.890944] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 7557.378316] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7563.751759] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 7565.527374] Lustre: server umount lustre-MDT0000 complete [ 7569.764912] LustreError: 8277:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787122336 with bad export cookie 12070242935900550920 [ 7569.780451] LustreError: 8277:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 7569.895301] Lustre: server umount lustre-OST0000 complete [ 7574.143501] Lustre: server umount lustre-OST0001 complete [ 7587.065976] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing unload_modules_local [ 7589.972439] Key type lgssc unregistered [ 7590.267874] LNet: 180419:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 7590.275925] LNetError: 180419:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 7590.297940] LNet: Removed LNI 192.168.204.115@tcp [ 7591.198345] Key type .llcrypt unregistered [ 7591.205072] Key type ._llcrypt unregistered