[ 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-8.fc42 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 486004074 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2399.998 MHz processor [ 0.000000] last_pfn = 0x146e00 max_arch_pfn = 0x400000000 [ 0.000000] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT [ 0.000000] last_pfn = 0xbffce max_arch_pfn = 0x400000000 [ 0.000000] found SMP MP-table at [mem 0x000f54b0-0x000f54bf] [ 0.000000] RAMDISK: [mem 0xbcc54000-0xbffbffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F52D0 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE2439 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE22D5 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 002295 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE2349 000090 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE23D9 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE2411 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe22d5-0xbffe2348] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe22d4] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe2349-0xbffe23d8] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe23d9-0xbffe2410] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe2411-0xbffe2438] [ 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, 524580K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] ftrace: allocating 41240 entries in 162 pages [ 0.000000] ftrace: allocated 162 pages with 3 groups [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] rcu: RCU event tracing is enabled. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ 0.000000] rcu: RCU callback double-/use-after-free debug enabled. [ 0.000000] Rude variant of Tasks RCU enabled. [ 0.000000] Tracing variant of Tasks RCU enabled. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 0.000000] NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16 [ 0.000000] random: get_random_bytes called from start_kernel+0x622/0x9a8 with crng_init=0 [ 0.001000] Console: colour *CGA 80x25 [ 0.001000] printk: console [ttyS1] enabled [ 0.001000] ACPI: Core revision 20220331 [ 0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.001013] APIC: Switch to symmetric I/O mode setup [ 0.003280] x2apic enabled [ 0.004007] Switched APIC routing to physical x2apic. [ 0.005013] kvm-guest: setup PV IPIs [ 0.008740] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.009000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.009044] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.010018] pid_max: default: 32768 minimum: 301 [ 0.011151] LSM: Security Framework initializing [ 0.012072] Yama: becoming mindful. [ 0.013046] SELinux: Initializing. [ 0.015008] *** VALIDATE selinux *** [ 0.024563] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.029735] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.030147] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.032038] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.033103] *** VALIDATE tmpfs *** [ 0.035266] *** VALIDATE proc *** [ 0.036224] *** VALIDATE cgroup *** [ 0.037006] *** VALIDATE cgroup2 *** [ 0.038265] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.039137] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.040006] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.041027] Spectre V2 : User space: Vulnerable [ 0.042006] Speculative Store Bypass: Vulnerable [ 0.045314] debug: unmapping init [mem 0xffffffff97859000-0xffffffff97860fff] [ 0.047000] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.047486] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.048023] ... version: 2 [ 0.049009] ... bit width: 48 [ 0.050007] ... generic registers: 4 [ 0.051006] ... value mask: 0000ffffffffffff [ 0.052008] ... max period: 00007fffffffffff [ 0.053017] ... fixed-purpose events: 3 [ 0.054012] ... event mask: 000000070000000f [ 0.055263] rcu: Hierarchical SRCU implementation. [ 0.057117] smp: Bringing up secondary CPUs ... [ 0.058525] x86: Booting SMP configuration: [ 0.059039] .... node #0, CPUs: #1 #2 #3 [ 0.062632] smp: Brought up 1 node, 4 CPUs [ 0.064009] smpboot: Max logical packages: 1 [ 0.065012] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.129652] node 0 deferred pages initialised in 62ms [ 0.136231] devtmpfs: initialized [ 0.161328] x86/mm: Memory block size: 128MB [ 0.162949] gcov: version magic: 0x41383552 [ 0.166594] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.169105] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.174025] pinctrl core: initialized pinctrl subsystem [ 0.177834] [ 0.179009] ************************************************************* [ 0.183014] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.187049] ** ** [ 0.190011] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.192011] ** ** [ 0.194019] ** This means that this kernel is built to expose internal ** [ 0.196028] ** IOMMU data structures, which may compromise security on ** [ 0.198018] ** your system. ** [ 0.201014] ** ** [ 0.204013] ** If you see this message and you are not debugging the ** [ 0.207009] ** kernel, report this immediately to your vendor! ** [ 0.210029] ** ** [ 0.213026] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.215008] ************************************************************* [ 0.217841] NET: Registered protocol family 16 [ 0.221509] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.227139] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.230091] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.234200] cpuidle: using governor menu [ 0.235715] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.239654] PCI: Using configuration type 1 for base access [ 0.244205] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.260349] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.262016] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.265547] cryptd: max_cpu_qlen set to 1000 [ 0.266458] ACPI: Added _OSI(Module Device) [ 0.267008] ACPI: Added _OSI(Processor Device) [ 0.268007] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.269009] ACPI: Added _OSI(Processor Aggregator Device) [ 0.275096] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.281191] ACPI: Interpreter enabled [ 0.282038] ACPI: PM: (supports S0 S3 S4 S5) [ 0.283006] ACPI: Using IOAPIC for interrupt routing [ 0.284059] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.286346] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.294586] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.296040] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.299017] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.302101] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.307574] acpiphp: Slot [2] registered [ 0.309077] acpiphp: Slot [5] registered [ 0.310091] acpiphp: Slot [6] registered [ 0.311122] acpiphp: Slot [7] registered [ 0.313153] acpiphp: Slot [8] registered [ 0.314109] acpiphp: Slot [9] registered [ 0.316085] acpiphp: Slot [10] registered [ 0.317100] acpiphp: Slot [3] registered [ 0.319091] acpiphp: Slot [4] registered [ 0.321116] acpiphp: Slot [11] registered [ 0.322098] acpiphp: Slot [12] registered [ 0.323081] acpiphp: Slot [13] registered [ 0.324149] acpiphp: Slot [14] registered [ 0.325069] acpiphp: Slot [15] registered [ 0.326056] acpiphp: Slot [16] registered [ 0.326982] acpiphp: Slot [17] registered [ 0.328066] acpiphp: Slot [18] registered [ 0.329047] acpiphp: Slot [19] registered [ 0.330063] acpiphp: Slot [20] registered [ 0.331040] acpiphp: Slot [21] registered [ 0.331947] acpiphp: Slot [22] registered [ 0.332048] acpiphp: Slot [23] registered [ 0.332874] acpiphp: Slot [24] registered [ 0.334067] acpiphp: Slot [25] registered [ 0.334987] acpiphp: Slot [26] registered [ 0.336056] acpiphp: Slot [27] registered [ 0.336999] acpiphp: Slot [28] registered [ 0.338008] acpiphp: Slot [29] registered [ 0.339050] acpiphp: Slot [30] registered [ 0.340062] acpiphp: Slot [31] registered [ 0.340974] PCI host bridge to bus 0000:00 [ 0.342011] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.343009] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.345009] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.347011] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.349035] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.351012] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.352150] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.354837] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.356960] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.363000] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.368033] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.370010] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.372011] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.374012] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.377556] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.379477] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.382032] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.384806] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.388013] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.399015] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.403009] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.407241] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.413020] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.420024] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.433019] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.442000] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.448018] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.456026] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.470035] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.482103] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.495024] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.502023] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.521026] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.534458] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.542025] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.549026] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.562000] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.562000] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.583026] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.590036] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.604019] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 0.615572] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.625024] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.634023] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.650020] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 0.663000] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.667415] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.668425] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.673603] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.674401] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.677052] iommu: Default domain type: Passthrough [ 0.678821] SCSI subsystem initialized [ 0.680112] ACPI: bus type USB registered [ 0.681041] usbcore: registered new interface driver usbfs [ 0.683089] usbcore: registered new interface driver hub [ 0.684067] usbcore: registered new device driver usb [ 0.685169] pps_core: LinuxPPS API ver. 1 registered [ 0.686008] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.688141] PTP clock support registered [ 0.690265] EDAC MC: Ver: 3.0.0 [ 0.691682] PCI: Using ACPI for IRQ routing [ 0.692689] NetLabel: Initializing [ 0.694012] NetLabel: domain hash size = 128 [ 0.695009] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.697106] NetLabel: unlabeled traffic allowed by default [ 0.699112] vgaarb: loaded [ 0.700306] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.703021] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.710820] clocksource: Switched to clocksource kvm-clock [ 0.865576] VFS: Disk quotas dquot_6.6.0 [ 0.867527] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.870516] *** VALIDATE ramfs *** [ 0.871939] *** VALIDATE hugetlbfs *** [ 0.874718] pnp: PnP ACPI init [ 0.877847] pnp: PnP ACPI: found 6 devices [ 0.896270] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.900327] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.902825] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.905575] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.908710] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.911831] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.915315] NET: Registered protocol family 2 [ 0.918342] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.923797] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.927970] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.934291] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.938513] TCP: Hash tables configured (established 65536 bind 65536) [ 0.942429] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.946638] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.949843] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.952898] NET: Registered protocol family 1 [ 0.956367] RPC: Registered named UNIX socket transport module. [ 0.958533] RPC: Registered udp transport module. [ 0.960072] RPC: Registered tcp transport module. [ 0.961840] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.964457] NET: Registered protocol family 44 [ 0.966752] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.969700] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.972625] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.975849] PCI: CLS 0 bytes, default 64 [ 0.978411] Unpacking initramfs... [ 2.588971] debug: unmapping init [mem 0xffff9b17bcc54000-0xffff9b17bffbffff] [ 2.597353] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.600180] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.609900] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 3.147046] Initialise system trusted keyrings [ 3.148571] Key type blacklist registered [ 3.150446] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 3.160244] zbud: loaded [ 3.163682] *** VALIDATE nfs *** [ 3.165817] *** VALIDATE nfs4 *** [ 3.168215] pstore: using deflate compression [ 3.172579] Platform Keyring initialized [ 3.309666] NET: Registered protocol family 38 [ 3.311906] Key type asymmetric registered [ 3.313358] Asymmetric key parser 'x509' registered [ 3.315560] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 3.320276] io scheduler mq-deadline registered [ 3.322438] io scheduler kyber registered [ 3.324763] io scheduler bfq registered [ 3.326880] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 3.330666] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 3.333770] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 3.336955] ACPI: Power Button [PWRF] [ 3.343937] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 3.385577] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 3.402862] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 3.411934] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 3.524312] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 3.662064] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.751150] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.765369] Non-volatile memory driver v1.3 [ 3.767478] Linux agpgart interface v0.103 [ 3.827669] virtio_blk virtio1: [vda] 134008 512-byte logical blocks (68.6 MB/65.4 MiB) [ 3.831462] vda: detected capacity change from 0 to 68612096 [ 3.947181] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.951216] vdb: detected capacity change from 0 to 1073741824 [ 3.984694] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.988284] vdc: detected capacity change from 0 to 2621440000 [ 4.014939] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 4.022656] vdd: detected capacity change from 0 to 2621440000 [ 4.054915] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 4.061059] vde: detected capacity change from 0 to 4294967296 [ 4.085682] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 4.089589] vdf: detected capacity change from 0 to 4294967296 [ 4.100360] libphy: Fixed MDIO Bus: probed [ 4.108263] usbcore: registered new interface driver usbserial_generic [ 4.110544] usbserial: USB Serial support registered for generic [ 4.113462] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 4.118783] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 4.121242] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 4.124540] mousedev: PS/2 mouse device common for all mice [ 4.127477] rtc_cmos 00:05: RTC can wake from S4 [ 4.130703] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 4.130765] rtc_cmos 00:05: registered as rtc0 [ 4.135846] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 4.138148] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 4.139681] intel_pstate: CPU model not supported [ 4.145398] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 4.149553] hid: raw HID events driver (C) Jiri Kosina [ 4.152087] usbcore: registered new interface driver usbhid [ 4.154526] usbhid: USB HID core driver [ 4.156396] drop_monitor: Initializing network drop monitor service [ 4.159293] Initializing XFRM netlink socket [ 4.161913] NET: Registered protocol family 10 [ 4.166053] Segment Routing with IPv6 [ 4.167559] NET: Registered protocol family 17 [ 4.170107] mpls_gso: MPLS GSO support [ 4.176476] RAS: Correctable Errors collector initialized. [ 4.178594] AVX version of gcm_enc/dec engaged. [ 4.180126] AES CTR mode by8 optimization enabled [ 4.324662] sched_clock: Marking stable (4324640758, 0)->(5217763424, -893122666) [ 4.330159] registered taskstats version 1 [ 4.333304] Loading compiled-in X.509 certificates [ 4.337099] zswap: loaded using pool lzo/zbud [ 4.541231] Key type big_key registered [ 4.573596] Key type encrypted registered [ 4.589769] ima: No TPM chip found, activating TPM-bypass! [ 4.599328] ima: Allocated hash algorithm: sha1 [ 4.606556] ima: No architecture policies found [ 4.615160] evm: Initialising EVM extended attributes: [ 4.621705] evm: security.selinux [ 4.627878] evm: security.ima [ 4.632249] evm: security.capability [ 4.634374] evm: HMAC attrs: 0x1 [ 4.638418] rtc_cmos 00:05: setting system clock to 2026-04-24 15:09:12 UTC (1777043352) [ 4.650200] debug: unmapping init [mem 0xffffffff98803000-0xffffffff989fffff] [ 4.653457] debug: unmapping init [mem 0xffffffff97582000-0xffffffff97858fff] [ 4.662171] Write protecting the kernel read-only data: 28672k [ 4.665846] debug: unmapping init [mem 0xffffffff95c03000-0xffffffff95dfffff] [ 4.669018] debug: unmapping init [mem 0xffffffff96514000-0xffffffff965fffff] [ 4.731932] 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) [ 4.746374] systemd[1]: Detected virtualization kvm. [ 4.749341] systemd[1]: Detected architecture x86-64. [ 4.753249] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 4.795240] systemd[1]: No hostname configured. [ 4.797963] systemd[1]: Set hostname to . [ 4.801952] random: systemd: uninitialized urandom read (16 bytes read) [ 4.807949] systemd[1]: Initializing machine ID from random generator. [ 4.932535] random: ln: uninitialized urandom read (6 bytes read) [ 5.131618] random: systemd: uninitialized urandom read (16 bytes read) [ 5.136405] systemd[1]: Reached target Swap. [ OK ] Reached target Swap. [ 5.148308] systemd[1]: Started Dispatch Password Requests to Console Directory Watch. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ 5.154757] systemd[1]: Reached target Timers. [ OK ] Reached target Timers. [ OK ] Listening on Journal Socket. [ OK ] Reached target Paths. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Started Memstrack Anylazing Service. Starting Setup Virtual Console... [ OK ] Reached target Slices. [ OK ] Reached target Initrd Root Device. [ OK ] Listening on udev Control Socket. [ OK ] Listening on udev Kernel Socket. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Listening on Journal Socket (/dev/log). Starting Journal Service... Starting Apply Kernel Variables... [ OK ] Reached target Local File Systems. Starting Create Volatile Files and Directories... [ OK ] Reached target Sockets. [ OK ] Started Setup Virtual Console. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Apply Kernel Variables. [ OK ] Started Create Volatile Files and Directories. Starting Create Static Device Nodes in /dev... Starting dracut cmdline hook... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started Journal Service. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 7.559322] device-mapper: uevent: version 1.0.3 [ 7.561689] 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. [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting dracut initqueue hook...[ 9.249632] random: fast init done [ 9.349857] virtio_net virtio0 ens2: renamed from eth0 [ 9.826048] scsi host0: ata_piix [ 10.002832] scsi host1: ata_piix [ 10.005970] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 10.014243] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 15.154931] random: crng init done [ 15.157117] random: 7 urandom warning(s) missed due to ratelimiting [ 17.081304] dracut-initqueue[594]: RTNETLINK answers: File exists 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... [ 18.519227] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped target Timers. [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Slices. [ OK ] Stopped target Paths. [ OK ] Stopped target Sockets. [ OK ] Stopped target System Initialization. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. Stopping udev Kernel Device Manager... [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Swap. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped target Local File Systems. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Closed udev Kernel Socket. [ OK ] Closed udev Control Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 20.997629] hrtimer: interrupt took 6885198 ns [ 21.483888] printk: systemd: 26 output lines suppressed due to ratelimiting [ 22.380588] SELinux: Disabled at runtime. [ 22.518100] 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) [ 22.557677] systemd[1]: Detected virtualization kvm. [ 22.566439] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 23.927490] systemd[1]: initrd-switch-root.service: Succeeded. [ 23.935652] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 23.951053] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 23.958522] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 23.970311] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 23.988382] systemd[1]: Starting Journal Service... Starting Journal Service... [ 24.014531] systemd[1]: Listening on Process Core Dump Socket. [ OK ] Listening on Process Core Dump Socket. [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd File Systems. [ OK ] Listening on udev Kernel Socket. Mounting Huge Pages File System... [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Stopped target Initrd Root File System. [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. Activating swap /dev/disk/by-label/SWAP... Starting Create list of required st…ce nodes for the current kernel... [ OK ] Listening on RPCbind Server Activation Socket. [ 24.203414] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS Mounting POSIX Message Queue File System... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Paths. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Created slice User and Session Slice. [ OK ] Reached target Slices. [ OK ] Reached target rpc_pipefs.target. [ OK ] Created slice system-serial\x2dgetty.slice. Starting Remount Root and Kernel File Systems... [ OK ] Reached target RPC Port Mapper. Mounting Kernel Debug File System... [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Created slice system-getty.slice. Starting Apply Kernel Variables... [ OK ] Listening on udev Control Socket. Starting udev Coldplug all Devices... [ OK ] Started Journal Service. [ OK ] Mounted Huge Pages File System. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ 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. Starting Configure read-only root support... Starting Create Static Device Nodes in /dev... [ OK ] Reached target Swap. Starting Flush Journal to Persistent Storage... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. Starting udev Kernel Device Manager... [ OK ] Reached target Local File Systems (Pre). Mounting /mnt... Mounting /home/green/git/lustre-release... [ OK ] Started udev Coldplug all Devices. [ OK ] Mounted /mnt. [ 25.418192] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 26.196943] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 26.234428] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 27.038468] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 27.119827] EDAC sbridge: Ver: 1.1.2 [* ] A start job is running for Configur…-only root support (7s / no limit) [** ] A start job is running for Configur…-only root support (7s / no limit) [*** ] A start job is running for Configur…-only root support (8s / no limit)[ 32.408485] Key type dns_resolver registered [ *** ] A start job is running for Configur…-only root support (8s / no limit) [ *** ] A start job is running for Configur…-only root support (9s / no limit)[ 33.407770] NFS: Registering the id_resolver key type [ 33.427216] Key type id_resolver registered [ 33.433272] Key type id_legacy registered [ ***] A start job is running for Configur…-only root support (9s / no limit) [ **] A start job is running for Configur…only root support (10s / no limit) [ OK ] Started Configure read-only root support. [ 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... Starting Load/Save Random Seed... [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Load/Save Random Seed. [ OK ] Started Create Volatile Files and Directories. Starting Update UTMP about System Boot/Shutdown... Starting RPC Bind... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting Restore /run/initramfs on shutdown... [ OK ] Reached target sshd-keygen.target. [ OK ] Started irqbalance daemon. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Started dnf makecache --timer. [ OK ] Reached target Timers. [ OK ] Started D-Bus System Message Bus. Starting Network Manager... Starting Login Service... [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Network Manager. [ OK ] Reached target Network. Starting OpenSSH server daemon... Starting GSSAPI Proxy Daemon... Starting Dynamic System Tuning Daemon... Starting Network Manager Wait Online... [ OK ] Started Login Service. Starting Hostname Service... [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Started OpenSSH server daemon. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... [ OK ] Started Permit User Sessions. [ OK ] Started Serial Getty on ttyS1. [ OK ] Started Getty on tty1. [ OK ] Started Serial Getty on ttyS0. [ OK ] Reached target Login Prompts. [ OK ] Started Command Scheduler. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting 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. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg216-server login: [ 73.063775] spl: loading out-of-tree module taints kernel. [ 76.942910] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 84.135644] Key type ._llcrypt registered [ 84.137902] Key type .llcrypt registered [ 84.238846] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_hostid [ 95.401412] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing load_modules_local [ 96.311066] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 96.317254] alg: No test for adler32 (adler32-zlib) [ 97.450107] Lustre: Lustre: Build Version: 2.17.52_54_g344a3c0 [ 97.992735] LNet: Added LNI 192.168.202.116@tcp [8/256/0/180] [ 99.663165] Key type lgssc registered [ 100.782674] Lustre: Echo OBD driver; http://www.lustre.org/ [ 107.322839] vdc: vdc1 vdc9 [ 113.820701] vde: vde1 vde9 [ 120.072360] vdf: vdf1 vdf9 [ 132.241749] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing load_modules_local [ 137.760970] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 138.929602] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 139.063879] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 139.117667] Lustre: lustre-MDT0000: new disk, initializing [ 139.367694] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 139.425049] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 142.156535] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 145.482393] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 149.001538] Lustre: lustre-OST0000: new disk, initializing [ 149.004473] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 149.008461] Lustre: Skipped 1 previous similar message [ 149.078509] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 153.362445] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 154.195539] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:0:ost [ 154.201940] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:0:ost] [ 154.276388] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x240000400 [ 160.481989] Lustre: lustre-OST0001: new disk, initializing [ 160.484922] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 160.563229] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 164.715948] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 170.556323] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:1:ost [ 170.559446] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:1:ost] [ 170.610856] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x280000400 [ 173.237425] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 177.738873] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 186.121833] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing check_logdir /tmp/testlogs/ [ 189.764390] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing yml_node [ 193.446279] Lustre: DEBUG MARKER: Client: 2.17.52.54 [ 195.489685] Lustre: DEBUG MARKER: MDS: 2.17.52.54 [ 197.315897] Lustre: DEBUG MARKER: OSS: 2.17.52.54 [ 198.464487] Lustre: DEBUG MARKER: -----============= acceptance-small: replay-single ============----- Fri Apr 24 11:12:24 EDT 2026 [ 210.120536] Lustre: DEBUG MARKER: excepting tests: 59 36 [ 211.322349] Lustre: DEBUG MARKER: === replay-single: start setup 11:12:37 (1777043557) === [ 213.738510] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing check_config_client /mnt/lustre [ 224.665211] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 226.988826] Lustre: 10998:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 229.153882] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 231.350471] Lustre: DEBUG MARKER: === replay-single: finish setup 11:12:57 (1777043577) === [ 232.300772] Lustre: DEBUG MARKER: == replay-single test 0a: empty replay =================== 11:12:58 (1777043578) [ 234.138685] LustreError: 11474:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 234.658274] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 235.878744] Lustre: Failing over lustre-MDT0000 [ 236.030904] Lustre: server umount lustre-MDT0000 complete [ 250.469499] LustreError: MGC192.168.202.116@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 250.646387] 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 [ 250.652655] Lustre: Skipped 1 previous similar message [ 250.696732] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 251.509145] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 251.546371] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 252.703079] Lustre: 3308:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1777043584/real 1777043584] req@ffff9b182494a300 x1863365107430528/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1777043600 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 252.703079] Lustre: 3306:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1777043584/real 1777043584] req@ffff9b182494b480 x1863365107430656/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1777043600 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 253.103908] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 255.973329] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 258.271342] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 258.911125] Lustre: 3308:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1777043590/real 1777043590] req@ffff9b183acef480 x1863365107431040/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1777043606 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 259.517922] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 264.095364] Lustre: 3305:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1777043595/real 1777043595] req@ffff9b18354ed180 x1863365107431296/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1777043611 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 264.115711] Lustre: 3305:0:(client.c:2479:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 265.777944] Lustre: DEBUG MARKER: == replay-single test 0b: ensure object created after recover exists. (3284) ========================================================== 11:13:31 (1777043611) [ 267.340600] Lustre: Failing over lustre-OST0000 [ 267.422145] Lustre: server umount lustre-OST0000 complete [ 271.330849] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 271.337427] 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 [ 276.447884] LustreError: 7985:0:(ldlm_lib.c:1180: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. [ 276.457346] LustreError: 7985:0:(ldlm_lib.c:1180:target_handle_connect()) Skipped 3 previous similar messages [ 277.055168] LustreError: 6548:0:(ldlm_lib.c:1180:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.202.16@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 281.494115] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 282.173818] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 283.364392] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 283.364646] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 283.373910] Lustre: Skipped 1 previous similar message [ 285.018920] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 289.898774] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 290.956418] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 297.037603] Lustre: DEBUG MARKER: == replay-single test 0c: check replay-barrier =========== 11:14:02 (1777043642) [ 298.709467] LustreError: 14173:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 299.205836] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 300.472432] Lustre: Failing over lustre-MDT0000 [ 300.663372] Lustre: server umount lustre-MDT0000 complete [ 314.760865] LustreError: MGC192.168.202.116@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 314.917159] 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 [ 314.925766] Lustre: Skipped 1 previous similar message [ 315.046689] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 317.190540] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 318.049862] Lustre: 3307:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1777043649/real 1777043649] req@ffff9b181134fb80 x1863365107453696/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1777043665 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 318.070294] Lustre: 3307:0:(client.c:2479:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 318.571139] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 318.574753] Lustre: lustre-MDT0000: Denying connection for new client 0e323c74-ff32-4911-992e-79c3c1368bde (at 192.168.202.16@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:59 [ 319.971436] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 323.647260] Lustre: lustre-MDT0000: Denying connection for new client 0e323c74-ff32-4911-992e-79c3c1368bde (at 192.168.202.16@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:54 [ 324.063435] Lustre: 3306:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1777043655/real 1777043655] req@ffff9b1837767800 x1863365107453952/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1777043671 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 324.085323] Lustre: 3306:0:(client.c:2479:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 328.765468] Lustre: lustre-MDT0000: Denying connection for new client 0e323c74-ff32-4911-992e-79c3c1368bde (at 192.168.202.16@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:49 [ 333.884450] Lustre: lustre-MDT0000: Denying connection for new client 0e323c74-ff32-4911-992e-79c3c1368bde (at 192.168.202.16@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:44 [ 339.001708] Lustre: lustre-MDT0000: Denying connection for new client 0e323c74-ff32-4911-992e-79c3c1368bde (at 192.168.202.16@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:39 [ 349.247531] Lustre: lustre-MDT0000: Denying connection for new client 0e323c74-ff32-4911-992e-79c3c1368bde (at 192.168.202.16@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:29 [ 349.258087] Lustre: Skipped 1 previous similar message [ 369.722136] Lustre: lustre-MDT0000: Denying connection for new client 0e323c74-ff32-4911-992e-79c3c1368bde (at 192.168.202.16@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:08 [ 369.738817] Lustre: Skipped 3 previous similar messages [ 378.500204] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 378.506362] Lustre: 14765:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 23db747b-0bbc-4184-bd16-fb2486cb9830@ [ 378.516967] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 378.555971] Lustre: lustre-MDT0000: Recovery over after 1:00, of 1 clients 0 recovered and 1 was evicted. [ 378.588594] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:44 to 0x240000400:65) [ 378.588759] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:44 to 0x280000400:65) [ 385.528293] Lustre: DEBUG MARKER: == replay-single test 0d: expired recovery with no clients ========================================================== 11:15:31 (1777043731) [ 387.176885] LustreError: 15484:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 387.701664] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 388.937632] Lustre: Failing over lustre-MDT0000 [ 389.108485] Lustre: server umount lustre-MDT0000 complete [ 403.565265] LustreError: MGC192.168.202.116@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 403.721022] 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 [ 403.729612] Lustre: Skipped 1 previous similar message [ 403.815816] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 405.854173] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 407.046405] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 407.061909] Lustre: lustre-MDT0000: Denying connection for new client f3a011ad-a4b5-42c3-9eae-7fc952216c95 (at 192.168.202.16@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 1:00 [ 407.067764] Lustre: Skipped 1 previous similar message [ 407.839140] Lustre: 3305:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1777043739/real 1777043739] req@ffff9b1824949f80 x1863365107477376/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1777043755 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 407.851284] Lustre: 3305:0:(client.c:2479:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 409.057429] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 409.066650] Lustre: Skipped 1 previous similar message [ 467.500164] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 467.504164] Lustre: 16076:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 0e323c74-ff32-4911-992e-79c3c1368bde@ [ 467.510897] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 467.535859] Lustre: lustre-MDT0000: Recovery over after 1:00, of 1 clients 0 recovered and 1 was evicted. [ 467.555883] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:44 to 0x240000400:97) [ 467.559673] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:44 to 0x280000400:97) [ 474.062627] Lustre: DEBUG MARKER: == replay-single test 1: simple create =================== 11:16:59 (1777043819) [ 475.967861] LustreError: 16796:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 476.485479] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 477.640696] Lustre: Failing over lustre-MDT0000 [ 477.807596] Lustre: server umount lustre-MDT0000 complete [ 492.157538] LustreError: MGC192.168.202.116@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 492.374629] 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 [ 492.387374] Lustre: Skipped 1 previous similar message [ 492.501484] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 494.174741] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 494.241749] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 494.278239] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:44 to 0x280000400:129) [ 494.281221] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:44 to 0x240000400:129) [ 495.029492] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 496.482279] Lustre: 3306:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1777043828/real 1777043828] req@ffff9b1808de9180 x1863365107498496/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1777043844 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 496.502480] Lustre: 3306:0:(client.c:2479:ptlrpc_expire_one_request()) Skipped 5 previous similar messages [ 497.633110] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 497.638703] Lustre: Skipped 1 previous similar message [ 499.954379] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 500.909996] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 506.463641] Lustre: DEBUG MARKER: == replay-single test 2a: touch ========================== 11:17:32 (1777043852) [ 508.228885] LustreError: 18209:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 508.773551] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 509.893923] Lustre: Failing over lustre-MDT0000 [ 510.117879] Lustre: server umount lustre-MDT0000 complete [ 524.527442] LustreError: MGC192.168.202.116@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 524.680405] 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 [ 524.883750] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 525.051737] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 525.092551] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:44 to 0x240000400:161) [ 525.092644] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:131 to 0x280000400:161) [ 527.081955] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 528.799154] Lustre: 3305:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1777043860/real 1777043860] req@ffff9b181f7b1500 x1863365107511168/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1777043876 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 528.826286] Lustre: 3305:0:(client.c:2479:ptlrpc_expire_one_request()) Skipped 5 previous similar messages [ 529.891850] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 529.897709] Lustre: Skipped 1 previous similar message [ 532.234575] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 533.563356] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 539.044875] Lustre: DEBUG MARKER: == replay-single test 2b: touch ========================== 11:18:04 (1777043884) [ 540.674803] LustreError: 19630:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 541.172801] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 542.264203] Lustre: Failing over lustre-MDT0000 [ 542.412331] Lustre: server umount lustre-MDT0000 complete [ 556.433292] LustreError: MGC192.168.202.116@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 556.652659] 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 [ 556.660124] Lustre: Skipped 2 previous similar messages [ 556.752132] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 556.755639] Lustre: Skipped 1 previous similar message [ 559.239831] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 560.721562] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 560.785037] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 560.807333] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:44 to 0x240000400:193) [ 560.807503] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:163 to 0x280000400:193) [ 562.145656] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 562.157240] Lustre: Skipped 1 previous similar message [ 564.562977] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 565.667481] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 571.671510] Lustre: DEBUG MARKER: == replay-single test 2c: setstripe replay =============== 11:18:37 (1777043917) [ 573.732344] LustreError: 21043:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 574.351635] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 575.691378] Lustre: Failing over lustre-MDT0000 [ 575.963124] Lustre: server umount lustre-MDT0000 complete [ 590.625458] LustreError: MGC192.168.202.116@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 590.841884] 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 [ 591.614106] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:225) [ 591.614173] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:225) [ 593.951097] Lustre: 3306:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1777043925/real 1777043925] req@ffff9b1841335c00 x1863365107537280/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1777043941 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 593.961266] Lustre: 3306:0:(client.c:2479:ptlrpc_expire_one_request()) Skipped 11 previous similar messages [ 594.193577] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 595.940509] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 595.947054] Lustre: Skipped 1 previous similar message [ 599.562898] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 600.762561] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 606.509370] Lustre: DEBUG MARKER: == replay-single test 2d: setdirstripe replay ============ 11:19:12 (1777043952) [ 608.285186] LustreError: 22464:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 608.855278] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 610.134486] Lustre: Failing over lustre-MDT0000 [ 610.340940] Lustre: server umount lustre-MDT0000 complete [ 625.089693] LustreError: MGC192.168.202.116@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 625.475504] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 627.298549] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 627.301565] Lustre: Skipped 1 previous similar message [ 627.372364] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 627.383032] Lustre: Skipped 1 previous similar message [ 627.413890] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:257) [ 627.414256] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:257) [ 627.968209] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 632.758587] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 633.785412] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 639.246723] Lustre: DEBUG MARKER: == replay-single test 2e: O_CREAT|O_EXCL create replay === 11:19:45 (1777043985) [ 639.826240] Lustre: *** cfs_fail_loc=13b, val=315*** [ 639.830277] Lustre: *** cfs_fail_loc=13b, val=2147483648*** [ 639.832317] LustreError: 23014:0:(ldlm_lib.c:3328:target_send_reply_msg()) @@@ dropping reply req@ffff9b1841334380 x1863365094906880/t38654705666(0) o35->f3a011ad-a4b5-42c3-9eae-7fc952216c95@192.168.202.16@tcp:504/0 lens 392/456 e 0 to 0 dl 1777044004 ref 1 fl Interpret:/600/0 rc 0/0 job:'openfile.0' uid:0 gid:0 projid:0 [ 642.877207] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 643.986741] Lustre: Failing over lustre-MDT0000 [ 644.161557] Lustre: server umount lustre-MDT0000 complete [ 657.989281] LustreError: 24478:0:(ldlm_lib.c:1180:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.202.16@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 658.099980] 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 [ 658.110656] Lustre: Skipped 3 previous similar messages [ 658.216813] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 659.990332] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:289) [ 659.996137] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:289) [ 660.004054] Lustre: 24479:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9b1837456a00 x1863365094906880/t38654705666(0) o35->f3a011ad-a4b5-42c3-9eae-7fc952216c95@192.168.202.16@tcp:524/0 lens 392/456 e 0 to 0 dl 1777044024 ref 1 fl Interpret:/602/0 rc 0/0 job:'openfile.0' uid:0 gid:0 projid:0 [ 660.327322] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 663.528709] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 663.533055] Lustre: Skipped 3 previous similar messages [ 665.144298] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 666.134629] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 671.336375] Lustre: DEBUG MARKER: == replay-single test 3a: replay failed open(O_DIRECTORY) ========================================================== 11:20:17 (1777044017) [ 673.116655] LustreError: 25341:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 673.120390] LustreError: 25341:0:(osd_handler.c:720:osd_ro()) Skipped 1 previous similar message [ 673.622948] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 674.876293] Lustre: Failing over lustre-MDT0000 [ 675.193535] Lustre: server umount lustre-MDT0000 complete [ 689.122127] Lustre: lustre-MDT0000: Not available for connect from 0@lo (not set up) [ 689.215547] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 689.218198] Lustre: Skipped 3 previous similar messages [ 689.263939] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 691.194663] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 693.729412] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 693.732824] Lustre: Skipped 1 previous similar message [ 693.782128] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 693.791352] Lustre: Skipped 1 previous similar message [ 693.812580] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:321) [ 693.812810] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:321) [ 695.706538] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 696.618588] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 701.620446] Lustre: DEBUG MARKER: == replay-single test 3b: replay failed open -ENOMEM ===== 11:20:47 (1777044047) [ 703.917463] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 704.425219] Lustre: *** cfs_fail_loc=114, val=0*** [ 705.774531] Lustre: Failing over lustre-MDT0000 [ 705.951393] Lustre: server umount lustre-MDT0000 complete [ 719.733821] LustreError: MGC192.168.202.116@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 719.737735] LustreError: Skipped 2 previous similar messages [ 719.845846] Lustre: lustre-MDT0000: Not available for connect from 0@lo (not set up) [ 719.850985] Lustre: Skipped 1 previous similar message [ 720.011577] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 721.896666] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 724.598450] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:353) [ 724.598567] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:353) [ 725.983241] Lustre: 3306:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1777044057/real 1777044057] req@ffff9b1810885880 x1863365107587840/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1777044073 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 726.011471] Lustre: 3306:0:(client.c:2479:ptlrpc_expire_one_request()) Skipped 20 previous similar messages [ 726.426676] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 727.385895] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 732.168401] Lustre: DEBUG MARKER: == replay-single test 3c: replay failed open -ENOMEM ===== 11:21:18 (1777044078) [ 734.374864] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 734.900922] Lustre: *** cfs_fail_loc=128, val=0*** [ 736.466492] Lustre: Failing over lustre-MDT0000 [ 736.652146] Lustre: server umount lustre-MDT0000 complete [ 750.560892] LustreError: 28919:0:(ldlm_lib.c:1180: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. [ 750.812526] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 752.569798] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 755.107840] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:385) [ 755.111660] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:385) [ 756.984157] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 757.713920] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 762.166740] Lustre: DEBUG MARKER: == replay-single test 4a: |x| 10 open(O_CREAT)s ========== 11:21:48 (1777044108) [ 763.838397] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 764.872794] Lustre: Failing over lustre-MDT0000 [ 765.016878] Lustre: server umount lustre-MDT0000 complete [ 778.770517] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 780.675587] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 781.077573] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:391 to 0x280000400:417) [ 781.078887] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:391 to 0x240000400:417) [ 784.896151] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 785.790887] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 790.571970] Lustre: DEBUG MARKER: == replay-single test 4b: |x| rm 10 files ================ 11:22:16 (1777044136) [ 792.329400] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 793.297096] Lustre: Failing over lustre-MDT0000 [ 793.451587] Lustre: server umount lustre-MDT0000 complete [ 807.387789] 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 [ 807.396678] Lustre: Skipped 9 previous similar messages [ 807.487124] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 809.327061] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 811.709578] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:423 to 0x280000400:449) [ 811.709867] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:423 to 0x240000400:449) [ 812.513067] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 812.516809] Lustre: Skipped 9 previous similar messages [ 813.285646] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 814.066431] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 818.461405] Lustre: DEBUG MARKER: == replay-single test 5: |x| 220 open(O_CREAT) =========== 11:22:44 (1777044164) [ 819.667478] LustreError: 32629:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 819.671246] LustreError: 32629:0:(osd_handler.c:720:osd_ro()) Skipped 4 previous similar messages [ 820.020656] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 823.684272] Lustre: Failing over lustre-MDT0000 [ 823.844482] Lustre: server umount lustre-MDT0000 complete [ 837.180095] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 837.188365] Lustre: Skipped 4 previous similar messages [ 838.678362] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 838.735855] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 838.739260] Lustre: Skipped 4 previous similar messages [ 838.756439] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:577) [ 838.756649] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:577) [ 842.559309] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 843.306943] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 856.443293] Lustre: DEBUG MARKER: == replay-single test 6a: mkdir + contained create ======= 11:23:22 (1777044202) [ 857.985855] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 858.782945] Lustre: Failing over lustre-MDT0000 [ 858.945125] Lustre: server umount lustre-MDT0000 complete [ 872.213153] LustreError: MGC192.168.202.116@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 872.217442] LustreError: Skipped 4 previous similar messages [ 872.515969] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 872.519092] Lustre: Skipped 1 previous similar message [ 873.099313] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:609) [ 873.099313] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:609) [ 874.167125] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 878.427524] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 879.282899] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 885.657708] Lustre: DEBUG MARKER: == replay-single test 6b: |X| rmdir ====================== 11:23:51 (1777044231) [ 887.375609] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 888.157175] Lustre: Failing over lustre-MDT0000 [ 888.324515] Lustre: server umount lustre-MDT0000 complete [ 903.818091] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:641) [ 903.819402] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:641) [ 903.955599] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 907.957071] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 908.756219] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 913.436501] Lustre: DEBUG MARKER: == replay-single test 7: mkdir |X| contained create ====== 11:24:19 (1777044259) [ 915.395704] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 916.271949] Lustre: Failing over lustre-MDT0000 [ 916.464966] Lustre: server umount lustre-MDT0000 complete [ 932.080283] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 934.568319] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:673) [ 934.571793] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:673) [ 936.650350] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 937.484410] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 942.185108] Lustre: DEBUG MARKER: == replay-single test 8: creat open |X| close ============ 11:24:48 (1777044288) [ 944.094653] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 945.034477] Lustre: Failing over lustre-MDT0000 [ 945.198887] Lustre: server umount lustre-MDT0000 complete [ 958.570420] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 958.573704] Lustre: Skipped 8 previous similar messages [ 958.612972] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 958.616671] Lustre: Skipped 2 previous similar messages [ 960.180335] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:705) [ 960.180680] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:705) [ 960.219532] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 964.051974] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 964.782486] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 969.229877] Lustre: DEBUG MARKER: == replay-single test 9: |X| create (same inum/gen) ====== 11:25:15 (1777044315) [ 970.922517] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 971.740563] Lustre: Failing over lustre-MDT0000 [ 971.996872] Lustre: server umount lustre-MDT0000 complete [ 985.730231] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:737) [ 985.730905] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:737) [ 987.026954] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 989.407298] Lustre: 3308:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1777044321/real 1777044321] req@ffff9b1837c78000 x1863365107784960/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1777044337 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 989.420480] Lustre: 3308:0:(client.c:2479:ptlrpc_expire_one_request()) Skipped 43 previous similar messages [ 991.063995] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 991.870053] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 996.482977] Lustre: DEBUG MARKER: == replay-single test 10: create |X| rename unlink ======= 11:25:42 (1777044342) [ 998.294103] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 999.181209] Lustre: Failing over lustre-MDT0000 [ 999.383459] Lustre: server umount lustre-MDT0000 complete [ 1014.549141] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1016.446676] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:769) [ 1016.446894] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:769) [ 1018.271634] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1019.070863] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1023.830992] Lustre: DEBUG MARKER: == replay-single test 11: create open write rename |X| create-old-name read ========================================================== 11:26:09 (1777044369) [ 1025.702888] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1026.696072] Lustre: Failing over lustre-MDT0000 [ 1026.902232] Lustre: server umount lustre-MDT0000 complete [ 1041.737058] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1042.054465] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:771 to 0x280000400:801) [ 1042.054776] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:771 to 0x240000400:801) [ 1045.811601] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1046.567804] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1051.099812] Lustre: DEBUG MARKER: == replay-single test 12: open, unlink |X| close ========= 11:26:37 (1777044397) [ 1052.752324] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1053.534946] Lustre: Failing over lustre-MDT0000 [ 1053.723698] Lustre: server umount lustre-MDT0000 complete [ 1066.798198] 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 [ 1066.805505] Lustre: Skipped 17 previous similar messages [ 1067.634519] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:771 to 0x280000400:833) [ 1067.634817] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:771 to 0x240000400:833) [ 1068.363348] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1071.858487] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1072.098689] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 1072.100916] Lustre: Skipped 17 previous similar messages [ 1072.495975] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1076.518743] Lustre: DEBUG MARKER: == replay-single test 13: open chmod 0 |x| write close === 11:27:02 (1777044422) [ 1077.735805] LustreError: 45433:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 1077.740719] LustreError: 45433:0:(osd_handler.c:720:osd_ro()) Skipped 8 previous similar messages [ 1078.159428] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1079.095686] Lustre: Failing over lustre-MDT0000 [ 1079.274238] Lustre: server umount lustre-MDT0000 complete [ 1092.444638] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1092.447210] Lustre: Skipped 4 previous similar messages [ 1093.185158] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1093.189350] Lustre: Skipped 8 previous similar messages [ 1093.281735] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:835 to 0x280000400:865) [ 1093.282990] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:771 to 0x240000400:865) [ 1094.046432] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1097.648684] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1098.375276] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1102.160353] Lustre: DEBUG MARKER: == replay-single test 14: open(O_CREAT), unlink |X| close ========================================================== 11:27:28 (1777044448) [ 1103.718513] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1104.511697] Lustre: Failing over lustre-MDT0000 [ 1104.668379] Lustre: server umount lustre-MDT0000 complete [ 1118.824203] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1118.829413] Lustre: Skipped 9 previous similar messages [ 1118.844864] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:835 to 0x280000400:897) [ 1118.844880] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:867 to 0x240000400:897) [ 1119.062632] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1122.771133] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1123.501329] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1127.481949] Lustre: DEBUG MARKER: == replay-single test 15: open(O_CREAT), unlink |X| touch new, close ========================================================== 11:27:53 (1777044473) [ 1129.128953] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1130.187277] Lustre: Failing over lustre-MDT0000 [ 1130.365406] Lustre: server umount lustre-MDT0000 complete [ 1143.472275] LustreError: MGC192.168.202.116@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1143.475639] LustreError: Skipped 9 previous similar messages [ 1144.511633] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:899 to 0x280000400:929) [ 1144.512301] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:899 to 0x240000400:929) [ 1145.523729] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1149.230972] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1150.007134] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1154.686254] Lustre: DEBUG MARKER: == replay-single test 16: |X| open(O_CREAT), unlink, touch new, unlink new ========================================================== 11:28:20 (1777044500) [ 1156.462758] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1157.400402] Lustre: Failing over lustre-MDT0000 [ 1157.599856] Lustre: server umount lustre-MDT0000 complete [ 1172.382682] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1174.729754] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:899 to 0x240000400:961) [ 1174.730066] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:931 to 0x280000400:961) [ 1176.438240] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1177.112662] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1180.994289] Lustre: DEBUG MARKER: == replay-single test 17: |X| open(O_CREAT), |replay| close ========================================================== 11:28:47 (1777044527) [ 1182.725488] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1183.557240] Lustre: Failing over lustre-MDT0000 [ 1183.752941] Lustre: server umount lustre-MDT0000 complete [ 1198.182814] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1200.283515] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:931 to 0x280000400:993) [ 1200.283553] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:963 to 0x240000400:993) [ 1201.653454] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1202.291657] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1205.880429] Lustre: DEBUG MARKER: == replay-single test 18: open(O_CREAT), unlink, touch new, close, touch, unlink ========================================================== 11:29:12 (1777044552) [ 1207.277343] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1207.995275] Lustre: Failing over lustre-MDT0000 [ 1208.248817] Lustre: server umount lustre-MDT0000 complete [ 1221.238708] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:995 to 0x280000400:1025) [ 1221.238708] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:995 to 0x240000400:1025) [ 1222.224652] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1225.607846] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1226.241069] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1230.045508] Lustre: DEBUG MARKER: == replay-single test 19: mcreate, open, write, rename === 11:29:36 (1777044576) [ 1231.463855] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1232.270093] Lustre: Failing over lustre-MDT0000 [ 1232.490454] Lustre: server umount lustre-MDT0000 complete [ 1246.798502] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1246.849746] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1027 to 0x240000400:1057) [ 1246.849755] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1027 to 0x280000400:1057) [ 1250.337791] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1250.987609] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1254.995661] Lustre: DEBUG MARKER: == replay-single test 20a: |X| open(O_CREAT), unlink, replay, close (test mds_cleanup_orphans) ========================================================== 11:30:01 (1777044601) [ 1256.665148] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1257.556307] Lustre: Failing over lustre-MDT0000 [ 1257.753229] Lustre: server umount lustre-MDT0000 complete [ 1272.404955] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1272.438678] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1059 to 0x240000400:1089) [ 1272.438678] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1027 to 0x280000400:1089) [ 1276.298529] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1276.951780] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1280.631269] Lustre: DEBUG MARKER: == replay-single test 20b: write, unlink, eviction, replay (test mds_cleanup_orphans) ========================================================== 11:30:26 (1777044626) [ 1282.499777] Lustre: 56802:0:(genops.c:1795:obd_export_evict_by_uuid()) lustre-MDT0000: evicting f3a011ad-a4b5-42c3-9eae-7fc952216c95 at adminstrative request [ 1284.742951] Lustre: Failing over lustre-MDT0000 [ 1284.938684] Lustre: server umount lustre-MDT0000 complete [ 1298.004980] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1027 to 0x280000400:1121) [ 1298.005032] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1091 to 0x240000400:1121) [ 1298.667409] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1301.743369] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1302.279834] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1304.713166] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 1312.355895] Lustre: DEBUG MARKER: before 4096, after 4096 [ 1314.413164] Lustre: DEBUG MARKER: == replay-single test 20c: check that client eviction does not affect file content ========================================================== 11:31:00 (1777044660) [ 1314.750841] Lustre: 58588:0:(genops.c:1795:obd_export_evict_by_uuid()) lustre-MDT0000: evicting f3a011ad-a4b5-42c3-9eae-7fc952216c95 at adminstrative request [ 1319.578866] Lustre: DEBUG MARKER: == replay-single test 21: |X| open(O_CREAT), unlink touch new, replay, close (test mds_cleanup_orphans) ========================================================== 11:31:05 (1777044665) [ 1320.941474] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1321.628421] Lustre: Failing over lustre-MDT0000 [ 1321.779757] Lustre: server umount lustre-MDT0000 complete [ 1335.731569] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1337.774112] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1123 to 0x240000400:1153) [ 1337.774329] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1124 to 0x280000400:1153) [ 1338.965783] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1339.536318] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1342.892569] Lustre: DEBUG MARKER: == replay-single test 22: open(O_CREAT), |X| unlink, replay, close (test mds_cleanup_orphans) ========================================================== 11:31:29 (1777044689) [ 1344.201535] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1344.858030] Lustre: Failing over lustre-MDT0000 [ 1345.095665] Lustre: server umount lustre-MDT0000 complete [ 1357.995199] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1357.999493] Lustre: Skipped 9 previous similar messages [ 1359.495116] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1155 to 0x240000400:1185) [ 1359.495178] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1155 to 0x280000400:1185) [ 1359.561122] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1362.857700] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1363.402664] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1366.849146] Lustre: DEBUG MARKER: == replay-single test 23: open(O_CREAT), |X| unlink touch new, replay, close (test mds_cleanup_orphans) ========================================================== 11:31:53 (1777044713) [ 1368.146304] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1368.832049] Lustre: Failing over lustre-MDT0000 [ 1369.017431] Lustre: server umount lustre-MDT0000 complete [ 1383.030861] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1385.112457] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1187 to 0x240000400:1217) [ 1385.112611] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1187 to 0x280000400:1217) [ 1386.427347] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1387.039703] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1391.038144] Lustre: DEBUG MARKER: == replay-single test 24: open(O_CREAT), replay, unlink, close (test mds_cleanup_orphans) ========================================================== 11:32:17 (1777044737) [ 1392.405385] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1393.047573] Lustre: Failing over lustre-MDT0000 [ 1393.301251] Lustre: server umount lustre-MDT0000 complete [ 1407.275884] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1409.310953] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1219 to 0x240000400:1249) [ 1409.310953] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1219 to 0x280000400:1249) [ 1410.551300] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1411.201908] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1414.686312] Lustre: DEBUG MARKER: == replay-single test 25: open(O_CREAT), unlink, replay, close (test mds_cleanup_orphans) ========================================================== 11:32:40 (1777044760) [ 1416.127423] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1416.832256] Lustre: Failing over lustre-MDT0000 [ 1416.999545] Lustre: server umount lustre-MDT0000 complete [ 1430.778215] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1431.136584] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1251 to 0x280000400:1281) [ 1431.136834] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1219 to 0x240000400:1281) [ 1433.975453] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1434.524329] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1438.012165] Lustre: DEBUG MARKER: == replay-single test 26: |X| open(O_CREAT), unlink two, close one, replay, close one (test mds_cleanup_orphans) ========================================================== 11:33:04 (1777044784) [ 1439.442151] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1440.207073] Lustre: Failing over lustre-MDT0000 [ 1440.411452] Lustre: server umount lustre-MDT0000 complete [ 1454.209731] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1456.211754] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1283 to 0x280000400:1313) [ 1456.211754] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1283 to 0x240000400:1313) [ 1457.463738] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1458.026173] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1461.543792] Lustre: DEBUG MARKER: == replay-single test 27: |X| open(O_CREAT), unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 11:33:27 (1777044807) [ 1462.853372] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1463.554932] Lustre: Failing over lustre-MDT0000 [ 1463.718374] Lustre: server umount lustre-MDT0000 complete [ 1476.408808] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1476.411931] Lustre: Skipped 19 previous similar messages [ 1477.251850] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1315 to 0x280000400:1345) [ 1477.251850] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1315 to 0x240000400:1345) [ 1477.830136] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1481.178843] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1481.797439] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1485.577168] Lustre: DEBUG MARKER: == replay-single test 28: open(O_CREAT), |X| unlink two, close one, replay, close one (test mds_cleanup_orphans) ========================================================== 11:33:51 (1777044831) [ 1486.951888] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1487.652465] Lustre: Failing over lustre-MDT0000 [ 1487.854835] Lustre: server umount lustre-MDT0000 complete [ 1502.028861] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1502.836104] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1347 to 0x280000400:1377) [ 1502.836122] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1347 to 0x240000400:1377) [ 1505.356180] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1505.995199] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1507.616103] Lustre: 3306:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1777044839/real 1777044839] req@ffff9b1809233480 x1863365108025984/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1777044855 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1507.623867] Lustre: 3306:0:(client.c:2479:ptlrpc_expire_one_request()) Skipped 97 previous similar messages [ 1509.449475] Lustre: DEBUG MARKER: == replay-single test 29: open(O_CREAT), |X| unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 11:34:15 (1777044855) [ 1510.844666] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1511.550172] Lustre: Failing over lustre-MDT0000 [ 1511.740821] Lustre: server umount lustre-MDT0000 complete [ 1525.547955] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1527.615383] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1379 to 0x280000400:1409) [ 1527.616074] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1379 to 0x240000400:1409) [ 1528.961723] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1529.528610] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1533.242960] Lustre: DEBUG MARKER: == replay-single test 30: open(O_CREAT) two, unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 11:34:39 (1777044879) [ 1534.693336] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1535.358083] Lustre: Failing over lustre-MDT0000 [ 1535.527634] Lustre: server umount lustre-MDT0000 complete [ 1548.898991] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1411 to 0x240000400:1441) [ 1548.902783] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1411 to 0x280000400:1441) [ 1549.615343] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1552.765064] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1553.313839] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1556.847914] Lustre: DEBUG MARKER: == replay-single test 31: open(O_CREAT) two, unlink one, |X| unlink one, close two (test mds_cleanup_orphans) ========================================================== 11:35:03 (1777044903) [ 1558.302729] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1559.001087] Lustre: Failing over lustre-MDT0000 [ 1559.100822] Lustre: lustre-MDT0000: Not available for connect from 192.168.202.16@tcp (stopping) [ 1559.107541] Lustre: Skipped 1 previous similar message [ 1559.180925] Lustre: server umount lustre-MDT0000 complete [ 1573.103982] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1578.601792] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1443 to 0x240000400:1473) [ 1578.601813] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1443 to 0x280000400:1473) [ 1579.890766] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1580.427683] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1583.733814] Lustre: DEBUG MARKER: == replay-single test 32: close() notices client eviction; close() after client eviction ========================================================== 11:35:29 (1777044929) [ 1584.092535] Lustre: 74413:0:(genops.c:1795:obd_export_evict_by_uuid()) lustre-MDT0000: evicting f3a011ad-a4b5-42c3-9eae-7fc952216c95 at adminstrative request [ 1588.768382] Lustre: DEBUG MARKER: == replay-single test 33a: fid seq shouldn't be reused after abort recovery ========================================================== 11:35:34 (1777044934) [ 1589.811798] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1590.427130] Lustre: Failing over lustre-MDT0000 [ 1590.607341] Lustre: server umount lustre-MDT0000 complete [ 1593.019498] Lustre: lustre-MDT0000: Aborting client recovery [ 1593.021687] LustreError: 75267:0:(ldlm_lib.c:2986:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 1593.024394] Lustre: 75312:0:(ldlm_lib.c:2389:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 1593.026830] Lustre: 75312:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client f3a011ad-a4b5-42c3-9eae-7fc952216c95@ [ 1593.029836] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 1593.038966] Lustre: lustre-MDT0000-osd: cancel update llog [0x200000400:0x1:0x0] [ 1593.071826] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1479 to 0x280000400:1505) [ 1593.076422] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1480 to 0x240000400:1505) [ 1594.288830] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1598.432456] 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 [ 1598.433962] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 1598.438237] Lustre: Skipped 42 previous similar messages [ 1598.440872] Lustre: Skipped 41 previous similar messages [ 1599.605489] Lustre: DEBUG MARKER: == replay-single test 33b: test fid seq allocation ======= 11:35:45 (1777044945) [ 1600.509539] LustreError: 75992:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 1600.512165] LustreError: 75992:0:(osd_handler.c:720:osd_ro()) Skipped 19 previous similar messages [ 1600.791671] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1601.383640] Lustre: Failing over lustre-MDT0000 [ 1601.526230] Lustre: server umount lustre-MDT0000 complete [ 1604.001938] Lustre: *** cfs_fail_loc=1311, val=0*** [ 1604.013869] Lustre: lustre-MDT0000: Aborting client recovery [ 1604.015618] LustreError: 76563:0:(ldlm_lib.c:2986:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 1604.019169] Lustre: 76611:0:(ldlm_lib.c:2389:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 1604.022205] Lustre: 76611:0:(ldlm_lib.c:2389:target_recovery_overseer()) Skipped 2 previous similar messages [ 1604.024269] Lustre: 76611:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client f3a011ad-a4b5-42c3-9eae-7fc952216c95@ [ 1604.027205] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 1604.037922] Lustre: lustre-MDT0000-osd: cancel update llog [0x200015bc0:0x1:0x0] [ 1604.069351] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1516 to 0x280000400:1537) [ 1604.069528] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1516 to 0x240000400:1537) [ 1605.266252] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1608.514979] Lustre: *** cfs_fail_loc=1311, val=0*** [ 1610.746171] Lustre: DEBUG MARKER: == replay-single test 34: abort recovery before client does replay (test mds_cleanup_orphans) ========================================================== 11:35:56 (1777044956) [ 1612.098817] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1612.782325] Lustre: Failing over lustre-MDT0000 [ 1612.881665] Lustre: server umount lustre-MDT0000 complete [ 1615.519205] Lustre: lustre-MDT0000: Aborting client recovery [ 1615.521119] LustreError: 77859:0:(ldlm_lib.c:2986:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 1615.524764] Lustre: 77904:0:(ldlm_lib.c:2389:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 1615.527206] Lustre: 77904:0:(ldlm_lib.c:2389:target_recovery_overseer()) Skipped 2 previous similar messages [ 1615.530444] Lustre: 77904:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client f3a011ad-a4b5-42c3-9eae-7fc952216c95@ [ 1615.533729] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 1615.545604] Lustre: lustre-MDT0000-osd: cancel update llog [0x200016778:0x1:0x0] [ 1615.575877] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1543 to 0x240000400:1569) [ 1615.576138] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1544 to 0x280000400:1569) [ 1616.820113] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1621.906558] Lustre: DEBUG MARKER: == replay-single test 35: test recovery from llog for unlink op ========================================================== 11:36:08 (1777044968) [ 1622.227206] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 1622.228546] LustreError: 78440:0:(ldlm_lib.c:3328:target_send_reply_msg()) @@@ dropping reply req@ffff9b1703de1180 x1863365095779456/t201863462916(0) o36->f3a011ad-a4b5-42c3-9eae-7fc952216c95@192.168.202.16@tcp:726/0 lens 512/456 e 0 to 0 dl 1777044981 ref 1 fl Interpret:/200/0 rc 0/0 job:'rm.0' uid:0 gid:0 projid:4294967295 [ 1624.791738] Lustre: Failing over lustre-MDT0000 [ 1624.890874] Lustre: server umount lustre-MDT0000 complete [ 1627.402330] Lustre: lustre-MDT0000: Aborting client recovery [ 1627.404038] LustreError: 79003:0:(ldlm_lib.c:2986:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 1627.405802] Lustre: 79049:0:(ldlm_lib.c:2389:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 1627.409754] Lustre: 79049:0:(ldlm_lib.c:2389:target_recovery_overseer()) Skipped 2 previous similar messages [ 1627.412887] Lustre: 79049:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client f3a011ad-a4b5-42c3-9eae-7fc952216c95@ [ 1627.417292] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 1627.431952] Lustre: lustre-MDT0000-osd: cancel update llog [0x200017330:0x1:0x0] [ 1627.470284] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1571 to 0x280000400:1601) [ 1627.470285] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1543 to 0x240000400:1601) [ 1628.771536] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1634.262342] Lustre: DEBUG MARKER: SKIP: replay-single test_36 skipping ALWAYS excluded test 36 [ 1634.830070] Lustre: DEBUG MARKER: == replay-single test 37: abort recovery before client does replay (test mds_cleanup_orphans for directories) ========================================================== 11:36:21 (1777044981) [ 1636.169209] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1637.144310] Lustre: Failing over lustre-MDT0000 [ 1637.386838] Lustre: server umount lustre-MDT0000 complete [ 1640.037348] Lustre: lustre-MDT0000: Aborting client recovery [ 1640.038942] LustreError: 80395:0:(ldlm_lib.c:2986:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 1640.041520] Lustre: 80440:0:(ldlm_lib.c:2389:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 1640.044730] Lustre: 80440:0:(ldlm_lib.c:2389:target_recovery_overseer()) Skipped 2 previous similar messages [ 1640.047874] Lustre: 80440:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client f3a011ad-a4b5-42c3-9eae-7fc952216c95@ [ 1640.051952] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 1640.067039] Lustre: lustre-MDT0000-osd: cancel update llog [0x200017b00:0x1:0x0] [ 1640.107638] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1543 to 0x240000400:1633) [ 1640.113338] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1571 to 0x280000400:1633) [ 1641.431033] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1652.893389] Lustre: DEBUG MARKER: == replay-single test 38: test recovery from unlink llog (test llog_gen_rec) ========================================================== 11:36:39 (1777044999) [ 1660.443910] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1661.089876] Lustre: Failing over lustre-MDT0000 [ 1661.260352] Lustre: server umount lustre-MDT0000 complete [ 1673.738744] LustreError: MGC192.168.202.116@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1673.741683] LustreError: Skipped 22 previous similar messages [ 1674.815185] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1674.818116] Lustre: Skipped 19 previous similar messages [ 1674.853835] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1674.856729] Lustre: Skipped 18 previous similar messages [ 1674.872533] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2034 to 0x240000400:2049) [ 1674.872633] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2034 to 0x280000400:2049) [ 1675.359510] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1678.627452] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1679.220935] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1688.297386] Lustre: DEBUG MARKER: == replay-single test 39: test recovery from unlink llog (test llog_gen_rec) ========================================================== 11:37:14 (1777045034) [ 1694.964850] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1698.112744] Lustre: Failing over lustre-MDT0000 [ 1698.421633] Lustre: server umount lustre-MDT0000 complete [ 1712.346514] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1715.000329] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2450 to 0x240000400:2465) [ 1715.001257] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2450 to 0x280000400:2465) [ 1716.043704] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1716.553797] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1724.167805] Lustre: DEBUG MARKER: == replay-single test 41: read from a valid osc while other oscs are invalid ========================================================== 11:37:50 (1777045070) [ 1724.824198] Lustre: setting import lustre-OST0001_UUID INACTIVE by administrator request [ 1725.146790] Lustre: lustre-OST0001: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnecting [ 1725.149961] LustreError: lustre-OST0001-osc-MDT0000: This client was evicted by lustre-OST0001; in progress operations using this service will fail. [ 1727.176964] Lustre: DEBUG MARKER: == replay-single test 42: recovery after ost failure ===== 11:37:53 (1777045073) [ 1732.426450] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 1735.627781] Lustre: Failing over lustre-OST0000 [ 1735.681472] LustreError: lustre-OST0000-osc-MDT0000: operation ost_destroy to node 0@lo failed: rc = -107 [ 1735.681808] LustreError: 6548:0:(ldlm_lib.c:1180: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. [ 1735.684490] LustreError: Skipped 4 previous similar messages [ 1735.684663] Lustre: server umount lustre-OST0000 complete [ 1735.690199] LustreError: 6548:0:(ldlm_lib.c:1180:target_handle_connect()) Skipped 1 previous similar message [ 1736.252360] LustreError: 33770:0:(ldlm_lib.c:1180:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.202.16@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1741.369509] LustreError: 82054:0:(ldlm_lib.c:1180:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.202.16@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1741.375532] LustreError: 82054:0:(ldlm_lib.c:1180:target_handle_connect()) Skipped 1 previous similar message [ 1746.490267] LustreError: 7985:0:(ldlm_lib.c:1180:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.202.16@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1746.495440] LustreError: 7985:0:(ldlm_lib.c:1180:target_handle_connect()) Skipped 1 previous similar message [ 1749.963641] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1795.532127] Lustre: DEBUG MARKER: == replay-single test 43: mds osc import failure during recovery; don't LBUG ========================================================== 11:39:01 (1777045141) [ 1796.934487] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1797.887141] Lustre: Failing over lustre-MDT0000 [ 1798.085870] Lustre: server umount lustre-MDT0000 complete [ 1812.121892] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1813.073804] Lustre: *** cfs_fail_loc=204, val=2147483648*** [ 1813.073868] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2866 to 0x280000400:2881) [ 1815.169429] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1815.694835] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1828.319267] LustreError: 87765:0:(osp_precreate.c:969:osp_precreate_cleanup_orphans()) lustre-OST0000-osc-MDT0000: cannot cleanup orphans: rc = -11 [ 1828.319965] Lustre: lustre-OST0000: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnecting [ 1829.133879] Lustre: DEBUG MARKER: == replay-single test 44a: race in target handle connect ========================================================== 11:39:35 (1777045175) [ 1829.343357] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2867 to 0x240000400:2913) [ 1830.714443] LustreError: 87743:0:(ldlm_lib.c:1166:target_handle_connect()) cfs_race id 701 sleeping [ 1835.999094] LustreError: 87743:0:(ldlm_lib.c:1166:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 1836.002169] Lustre: lustre-MDT0000: Client f3a011ad-a4b5-42c3-9eae-7fc952216c95 (at 192.168.202.16@tcp) reconnecting [ 1836.652609] LustreError: 87742:0:(ldlm_lib.c:1166:target_handle_connect()) cfs_race id 701 sleeping [ 1842.143131] LustreError: 87742:0:(ldlm_lib.c:1166:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 1842.146193] Lustre: lustre-MDT0000: Client f3a011ad-a4b5-42c3-9eae-7fc952216c95 (at 192.168.202.16@tcp) reconnecting [ 1842.780057] LustreError: 88279:0:(ldlm_lib.c:1166:target_handle_connect()) cfs_race id 701 sleeping [ 1848.287136] LustreError: 88279:0:(ldlm_lib.c:1166:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 1848.290073] Lustre: lustre-MDT0000: Client f3a011ad-a4b5-42c3-9eae-7fc952216c95 (at 192.168.202.16@tcp) reconnecting [ 1848.988899] LustreError: 87744:0:(ldlm_lib.c:1166:target_handle_connect()) cfs_race id 701 sleeping [ 1854.431138] LustreError: 87744:0:(ldlm_lib.c:1166:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 1855.049929] LustreError: 88842:0:(ldlm_lib.c:1166:target_handle_connect()) cfs_race id 701 sleeping [ 1860.063096] LustreError: 88842:0:(ldlm_lib.c:1166:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 1860.065558] Lustre: lustre-MDT0000: Client f3a011ad-a4b5-42c3-9eae-7fc952216c95 (at 192.168.202.16@tcp) reconnecting [ 1860.067838] Lustre: Skipped 1 previous similar message [ 1866.338172] LustreError: 87742:0:(ldlm_lib.c:1166:target_handle_connect()) cfs_race id 701 sleeping [ 1866.342860] LustreError: 87742:0:(ldlm_lib.c:1166:target_handle_connect()) Skipped 1 previous similar message [ 1871.839142] LustreError: 87742:0:(ldlm_lib.c:1166:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 1871.841546] LustreError: 87742:0:(ldlm_lib.c:1166:target_handle_connect()) Skipped 1 previous similar message [ 1877.983120] Lustre: lustre-MDT0000: Client f3a011ad-a4b5-42c3-9eae-7fc952216c95 (at 192.168.202.16@tcp) reconnecting [ 1877.986815] Lustre: Skipped 2 previous similar messages [ 1884.732146] LustreError: 88279:0:(ldlm_lib.c:1166:target_handle_connect()) cfs_race id 701 sleeping [ 1884.734845] LustreError: 88279:0:(ldlm_lib.c:1166:target_handle_connect()) Skipped 2 previous similar messages [ 1889.759142] LustreError: 88279:0:(ldlm_lib.c:1166:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 1889.762239] LustreError: 88279:0:(ldlm_lib.c:1166:target_handle_connect()) Skipped 2 previous similar messages [ 1892.382608] Lustre: DEBUG MARKER: == replay-single test 44b: race in target handle connect ========================================================== 11:40:38 (1777045238) [ 1893.043307] LustreError: 87743:0:(ldlm_lib.c:1421:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 1902.649525] Lustre: lustre-MDT0000: Export ffff9b170191e800 already connecting from 192.168.202.16@tcp [ 1907.769563] Lustre: lustre-MDT0000: Export ffff9b170191e800 already connecting from 192.168.202.16@tcp [ 1912.889068] Lustre: lustre-MDT0000: Export ffff9b170191e800 already connecting from 192.168.202.16@tcp [ 1918.008939] Lustre: lustre-MDT0000: Export ffff9b170191e800 already connecting from 192.168.202.16@tcp [ 1918.011183] Lustre: Skipped 1 previous similar message [ 1923.129042] Lustre: lustre-MDT0000: Export ffff9b170191e800 already connecting from 192.168.202.16@tcp [ 1933.087148] LustreError: 87743:0:(ldlm_lib.c:1421:target_handle_connect()) cfs_fail_timeout id 704 awake [ 1933.090531] Lustre: 87743:0:(service.c:2561:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/20s); client may timeout req@ffff9b1833bcd180 x1863365098396288/t0(0) o38->f3a011ad-a4b5-42c3-9eae-7fc952216c95@192.168.202.16@tcp:0/0 lens 520/416 e 0 to 0 dl 1777045260 ref 1 fl Complete:H/200/0 rc 0/0 job:'lctl.0' uid:0 gid:0 projid:4294967295 [ 1933.369526] Lustre: lustre-MDT0000: Client f3a011ad-a4b5-42c3-9eae-7fc952216c95 (at 192.168.202.16@tcp) reconnecting [ 1933.373193] Lustre: Skipped 3 previous similar messages [ 1933.374746] LustreError: 87742:0:(ldlm_lib.c:1421:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 1958.969225] Lustre: lustre-MDT0000: Export ffff9b170191e800 already connecting from 192.168.202.16@tcp [ 1958.972642] Lustre: Skipped 1 previous similar message [ 1973.415096] LustreError: 87742:0:(ldlm_lib.c:1421:target_handle_connect()) cfs_fail_timeout id 704 awake [ 1973.417216] Lustre: 87742:0:(service.c:2561:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/20s); client may timeout req@ffff9b1841789c00 x1863365098400256/t0(0) o38->f3a011ad-a4b5-42c3-9eae-7fc952216c95@192.168.202.16@tcp:0/0 lens 520/416 e 0 to 0 dl 1777045301 ref 1 fl Complete:H/200/0 rc 0/0 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1974.329146] LustreError: 87743:0:(ldlm_lib.c:1421:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 1998.905271] Lustre: lustre-MDT0000: Export ffff9b170191e800 already connecting from 192.168.202.16@tcp [ 1998.909847] Lustre: Skipped 2 previous similar messages [ 2014.383145] LustreError: 87743:0:(ldlm_lib.c:1421:target_handle_connect()) cfs_fail_timeout id 704 awake [ 2014.386235] Lustre: 87743:0:(service.c:2561:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/20s); client may timeout req@ffff9b183781f800 x1863365098402048/t0(0) o38->f3a011ad-a4b5-42c3-9eae-7fc952216c95@192.168.202.16@tcp:0/0 lens 520/416 e 0 to 0 dl 1777045342 ref 1 fl Complete:H/200/0 rc 0/0 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2019.147538] Lustre: lustre-MDT0000: Client f3a011ad-a4b5-42c3-9eae-7fc952216c95 (at 192.168.202.16@tcp) reconnecting [ 2019.150566] Lustre: Skipped 1 previous similar message [ 2019.152136] LustreError: 87743:0:(ldlm_lib.c:1421:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 2043.961176] Lustre: lustre-MDT0000: Export ffff9b170191e800 already connecting from 192.168.202.16@tcp [ 2043.963891] Lustre: Skipped 3 previous similar messages [ 2059.199108] LustreError: 87743:0:(ldlm_lib.c:1421:target_handle_connect()) cfs_fail_timeout id 704 awake [ 2059.202871] Lustre: 87743:0:(service.c:2561:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/20s); client may timeout req@ffff9b1811a9d500 x1863365098404096/t0(0) o38->f3a011ad-a4b5-42c3-9eae-7fc952216c95@192.168.202.16@tcp:0/0 lens 520/416 e 0 to 0 dl 1777045387 ref 1 fl Complete:H/200/0 rc 0/0 job:'lctl.0' uid:0 gid:0 projid:4294967295 [ 2059.321168] LustreError: 88279:0:(ldlm_lib.c:1421:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 2099.367102] LustreError: 88279:0:(ldlm_lib.c:1421:target_handle_connect()) cfs_fail_timeout id 704 awake [ 2099.369244] Lustre: 88279:0:(service.c:2561:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/20s); client may timeout req@ffff9b1804499180 x1863365098405888/t0(0) o38->f3a011ad-a4b5-42c3-9eae-7fc952216c95@192.168.202.16@tcp:0/0 lens 520/416 e 0 to 0 dl 1777045427 ref 1 fl Complete:H/200/0 rc 0/0 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2104.613336] Lustre: DEBUG MARKER: == replay-single test 44c: race in target handle connect ========================================================== 11:44:10 (1777045450) [ 2105.909809] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2107.095928] Lustre: Failing over lustre-MDT0000 [ 2107.211214] Lustre: server umount lustre-MDT0000 complete [ 2109.498632] LustreError: 92101:0:(ldlm_lib.c:1180:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.202.16@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 2109.506584] LustreError: 92101:0:(ldlm_lib.c:1180:target_handle_connect()) Skipped 1 previous similar message [ 2109.558399] Lustre: *** cfs_fail_loc=712, val=0*** [ 2109.560166] LustreError: 32630:0:(service.c:1390:ptlrpc_check_req()) @@@ Invalid replay without recovery req@ffff9b1703de4a80 x1863365108649728/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 [ 2109.591738] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 2109.593661] Lustre: Skipped 13 previous similar messages [ 2109.613378] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 2109.613447] Lustre: lustre-MDT0000: Aborting client recovery [ 2109.614994] Lustre: Skipped 28 previous similar messages [ 2109.616498] LustreError: 92090:0:(ldlm_lib.c:2986:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 2109.618152] Lustre: 92136:0:(ldlm_lib.c:2389:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 2109.622111] Lustre: 92136:0:(ldlm_lib.c:2389:target_recovery_overseer()) Skipped 2 previous similar messages [ 2109.623990] Lustre: 92136:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client f3a011ad-a4b5-42c3-9eae-7fc952216c95@ [ 2109.626710] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 2109.637804] Lustre: lustre-MDT0000-osd: cancel update llog [0x2000182d0:0x1:0x0] [ 2109.671487] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2867 to 0x240000400:2945) [ 2109.671491] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2866 to 0x280000400:2913) [ 2110.820190] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2114.634632] Lustre: Failing over lustre-MDT0000 [ 2114.803206] Lustre: server umount lustre-MDT0000 complete [ 2128.692163] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2130.003883] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2866 to 0x280000400:2945) [ 2130.003888] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2867 to 0x240000400:2977) [ 2131.741637] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2132.211904] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2135.328589] Lustre: DEBUG MARKER: == replay-single test 45: Handle failed close ============ 11:44:41 (1777045481) [ 2138.542443] Lustre: DEBUG MARKER: == replay-single test 46: Don't leak file handle after open resend (3325) ========================================================== 11:44:44 (1777045484) [ 2138.866369] Lustre: *** cfs_fail_loc=122, val=2147483648*** [ 2138.868769] LustreError: 92994:0:(ldlm_lib.c:3328:target_send_reply_msg()) @@@ dropping reply req@ffff9b181f57d500 x1863365098457216/t0(0) o700->f3a011ad-a4b5-42c3-9eae-7fc952216c95@192.168.202.16@tcp:487/0 lens 264/248 e 0 to 0 dl 1777045497 ref 1 fl Interpret:/200/0 rc 0/0 job:'touch.0' uid:0 gid:0 projid:4294967295 [ 2155.065375] Lustre: lustre-MDT0000: Client f3a011ad-a4b5-42c3-9eae-7fc952216c95 (at 192.168.202.16@tcp) reconnecting [ 2155.068166] Lustre: Skipped 4 previous similar messages [ 2156.163467] Lustre: Failing over lustre-MDT0000 [ 2156.375431] Lustre: server umount lustre-MDT0000 complete [ 2170.298843] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2170.457375] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2979 to 0x240000400:3009) [ 2170.457375] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2947 to 0x280000400:2977) [ 2173.437823] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2173.987847] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2175.967162] Lustre: 3308:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1777045507/real 1777045507] req@ffff9b183b799f80 x1863365108671872/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1777045523 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2175.974319] Lustre: 3308:0:(client.c:2479:ptlrpc_expire_one_request()) Skipped 43 previous similar messages [ 2177.903591] Lustre: DEBUG MARKER: == replay-single test 47: MDS->OSC failure during precreate cleanup (2824) ========================================================== 11:45:24 (1777045524) [ 2178.729917] Lustre: Failing over lustre-OST0000 [ 2178.763536] Lustre: server umount lustre-OST0000 complete [ 2179.039833] LustreError: 33765:0:(ldlm_lib.c:1180: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. [ 2192.926484] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2195.954049] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 2196.461136] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 2261.652133] Lustre: DEBUG MARKER: == replay-single test 48: MDS->OSC failure during precreate cleanup (2824) ========================================================== 11:46:47 (1777045607) [ 2262.712468] LustreError: 96737:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 2262.715785] LustreError: 96737:0:(osd_handler.c:720:osd_ro()) Skipped 7 previous similar messages [ 2263.021707] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2263.756586] Lustre: Failing over lustre-MDT0000 [ 2263.946615] Lustre: server umount lustre-MDT0000 complete [ 2276.311966] LustreError: MGC192.168.202.116@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2276.315435] LustreError: Skipped 5 previous similar messages [ 2276.420704] 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 [ 2276.427463] Lustre: Skipped 23 previous similar messages [ 2277.745538] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2277.946319] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 2277.948839] Lustre: Skipped 6 previous similar messages [ 2278.040071] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 2278.042529] Lustre: Skipped 6 previous similar messages [ 2278.057361] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2998 to 0x280000400:3041) [ 2278.057386] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3030 to 0x240000400:3073) [ 2281.952708] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 2281.956080] Lustre: Skipped 23 previous similar messages [ 2342.341110] Lustre: DEBUG MARKER: == replay-single test 50: Double OSC recovery, don't LASSERT (3812) ========================================================== 11:48:08 (1777045688) [ 2350.199397] Lustre: DEBUG MARKER: == replay-single test 52: time out lock replay (3764) ==== 11:48:16 (1777045696) [ 2351.168694] Lustre: Failing over lustre-MDT0000 [ 2351.343824] Lustre: server umount lustre-MDT0000 complete [ 2365.003274] Lustre: *** cfs_fail_loc=157, val=2147483648*** [ 2365.004768] LustreError: 98884:0:(ldlm_lib.c:3328:target_send_reply_msg()) @@@ dropping reply req@ffff9b18361dce00 x1863365098567168/t0(0) o101->f3a011ad-a4b5-42c3-9eae-7fc952216c95@192.168.202.16@tcp:713/0 lens 328/344 e 0 to 0 dl 1777045723 ref 1 fl Complete:/240/0 rc 0/0 job:'ldlm_lock_repla.0' uid:0 gid:0 projid:4294967295 [ 2365.078134] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2380.345492] Lustre: lustre-MDT0000: Client f3a011ad-a4b5-42c3-9eae-7fc952216c95 (at 192.168.202.16@tcp) reconnected, waiting for 1 clients in recovery for 1:25 [ 2380.386629] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3053 to 0x280000400:3073) [ 2380.386648] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3084 to 0x240000400:3105) [ 2381.766138] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2382.315975] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2386.009227] Lustre: DEBUG MARKER: == replay-single test 53a: |X| close request while two MDC requests in flight ========================================================== 11:48:52 (1777045732) [ 2387.363722] Lustre: *** cfs_fail_loc=115, val=2147483648*** [ 2388.808278] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2389.410803] Lustre: Failing over lustre-MDT0000 [ 2389.472448] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2389.478645] Lustre: Skipped 1 previous similar message [ 2389.627296] Lustre: server umount lustre-MDT0000 complete [ 2403.502772] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2403.924850] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3053 to 0x280000400:3105) [ 2403.924851] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3107 to 0x240000400:3137) [ 2406.637275] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2407.178506] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2410.639791] Lustre: DEBUG MARKER: == replay-single test 53b: |X| open request while two MDC requests in flight ========================================================== 11:49:16 (1777045756) [ 2411.036841] Lustre: *** cfs_fail_loc=107, val=2147483648*** [ 2413.567372] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2414.200450] Lustre: Failing over lustre-MDT0000 [ 2414.293105] Lustre: server umount lustre-MDT0000 complete [ 2428.180624] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2436.690572] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3139 to 0x240000400:3169) [ 2436.690869] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3053 to 0x280000400:3137) [ 2437.897479] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2438.521564] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2442.214424] Lustre: DEBUG MARKER: == replay-single test 53c: |X| open request and close request while two MDC requests in flight ========================================================== 11:49:48 (1777045788) [ 2442.598024] Lustre: *** cfs_fail_loc=107, val=2147483648*** [ 2445.136156] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2445.765979] Lustre: Failing over lustre-MDT0000 [ 2445.860321] Lustre: server umount lustre-MDT0000 complete [ 2459.218990] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3139 to 0x240000400:3201) [ 2459.218990] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3139 to 0x280000400:3169) [ 2459.684061] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2464.660497] Lustre: DEBUG MARKER: == replay-single test 53d: close reply while two MDC requests in flight ========================================================== 11:50:10 (1777045810) [ 2466.041505] Lustre: *** cfs_fail_loc=13b, val=315*** [ 2466.043460] Lustre: *** cfs_fail_loc=13b, val=2147483648*** [ 2466.045498] LustreError: 103478:0:(ldlm_lib.c:3328:target_send_reply_msg()) @@@ dropping reply req@ffff9b1811a9c700 x1863365098609536/t257698037777(0) o35->f3a011ad-a4b5-42c3-9eae-7fc952216c95@192.168.202.16@tcp:59/0 lens 392/456 e 0 to 0 dl 1777045824 ref 1 fl Interpret:/600/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 2466.941253] Lustre: Failing over lustre-MDT0000 [ 2467.197589] Lustre: server umount lustre-MDT0000 complete [ 2479.704763] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3171 to 0x280000400:3201) [ 2479.707258] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3139 to 0x240000400:3233) [ 2479.715765] Lustre: 104699:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9b1703db2a00 x1863365098609536/t257698037777(0) o35->f3a011ad-a4b5-42c3-9eae-7fc952216c95@192.168.202.16@tcp:73/0 lens 392/456 e 0 to 0 dl 1777045838 ref 1 fl Interpret:/602/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 2480.929772] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2483.959600] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2484.501438] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2487.889640] Lustre: DEBUG MARKER: == replay-single test 53e: |X| open reply while two MDC requests in flight ========================================================== 11:50:34 (1777045834) [ 2488.237854] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 2488.239193] LustreError: 104728:0:(ldlm_lib.c:3328:target_send_reply_msg()) @@@ dropping reply req@ffff9b184178b100 x1863365098621056/t261993005072(0) o36->f3a011ad-a4b5-42c3-9eae-7fc952216c95@192.168.202.16@tcp:82/0 lens 504/448 e 0 to 0 dl 1777045847 ref 1 fl Interpret:/200/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 2490.639659] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2491.260261] Lustre: Failing over lustre-MDT0000 [ 2491.368184] Lustre: server umount lustre-MDT0000 complete [ 2503.737303] Lustre: lustre-MDT0000: Not available for connect from 192.168.202.16@tcp (not set up) [ 2505.064819] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2505.430873] Lustre: 106213:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9b184178b480 x1863365098621056/t261993005072(0) o36->f3a011ad-a4b5-42c3-9eae-7fc952216c95@192.168.202.16@tcp:99/0 lens 504/2880 e 0 to 0 dl 1777045864 ref 1 fl Interpret:/202/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 2505.436858] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3139 to 0x240000400:3265) [ 2505.437121] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3203 to 0x280000400:3233) [ 2508.223725] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2508.772297] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2512.171612] Lustre: DEBUG MARKER: == replay-single test 53f: |X| open reply and close reply while two MDC requests in flight ========================================================== 11:50:58 (1777045858) [ 2512.520065] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 2512.521634] LustreError: 106212:0:(ldlm_lib.c:3328:target_send_reply_msg()) @@@ dropping reply req@ffff9b1804499880 x1863365098633216/t266287972368(0) o36->f3a011ad-a4b5-42c3-9eae-7fc952216c95@192.168.202.16@tcp:106/0 lens 504/448 e 0 to 0 dl 1777045871 ref 1 fl Interpret:/200/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 2513.803780] Lustre: *** cfs_fail_loc=13b, val=315*** [ 2514.948142] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2515.538973] Lustre: Failing over lustre-MDT0000 [ 2515.630705] Lustre: server umount lustre-MDT0000 complete [ 2528.852756] Lustre: 107726:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9b1804735c00 x1863365098633472/t266287972369(0) o35->f3a011ad-a4b5-42c3-9eae-7fc952216c95@192.168.202.16@tcp:122/0 lens 392/456 e 0 to 0 dl 1777045887 ref 1 fl Interpret:/602/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 2528.856703] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3139 to 0x240000400:3297) [ 2528.856720] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3235 to 0x280000400:3265) [ 2528.861370] Lustre: 107726:0:(mdt_recovery.c:102:mdt_req_from_lrd()) Skipped 1 previous similar message [ 2529.251063] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2534.137261] Lustre: DEBUG MARKER: == replay-single test 53g: |X| drop open reply and close request while close and open are both in flight ========================================================== 11:51:20 (1777045880) [ 2534.480377] LustreError: 107723:0:(ldlm_lib.c:3328:target_send_reply_msg()) @@@ dropping reply req@ffff9b1804498380 x1863365098644608/t270582939664(0) o36->f3a011ad-a4b5-42c3-9eae-7fc952216c95@192.168.202.16@tcp:128/0 lens 504/448 e 0 to 0 dl 1777045893 ref 1 fl Interpret:/200/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 2534.488152] LustreError: 107723:0:(ldlm_lib.c:3328:target_send_reply_msg()) Skipped 1 previous similar message [ 2535.762146] Lustre: *** cfs_fail_loc=115, val=2147483648*** [ 2535.764922] Lustre: Skipped 1 previous similar message [ 2537.214297] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2537.811825] Lustre: Failing over lustre-MDT0000 [ 2537.900884] Lustre: server umount lustre-MDT0000 complete [ 2550.862936] Lustre: 109182:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9b1703db3480 x1863365098644608/t270582939664(0) o36->f3a011ad-a4b5-42c3-9eae-7fc952216c95@192.168.202.16@tcp:144/0 lens 504/2880 e 0 to 0 dl 1777045909 ref 1 fl Interpret:/202/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 2550.869413] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3139 to 0x240000400:3329) [ 2550.869471] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3267 to 0x280000400:3297) [ 2551.555967] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2556.104350] Lustre: DEBUG MARKER: == replay-single test 53h: open request and close reply while two MDC requests in flight ========================================================== 11:51:42 (1777045902) [ 2556.441039] Lustre: *** cfs_fail_loc=107, val=2147483648*** [ 2557.713100] Lustre: *** cfs_fail_loc=13b, val=315*** [ 2557.714320] Lustre: *** cfs_fail_loc=13b, val=2147483648*** [ 2557.715462] Lustre: Skipped 2 previous similar messages [ 2559.831879] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2560.425191] Lustre: Failing over lustre-MDT0000 [ 2560.479827] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2560.481981] Lustre: Skipped 1 previous similar message [ 2560.529553] Lustre: server umount lustre-MDT0000 complete [ 2574.473069] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2583.115728] Lustre: 110552:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9b1837457480 x1863365098655616/t274877906960(0) o35->f3a011ad-a4b5-42c3-9eae-7fc952216c95@192.168.202.16@tcp:176/0 lens 392/456 e 0 to 0 dl 1777045941 ref 1 fl Interpret:/602/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 2583.122603] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3139 to 0x240000400:3361) [ 2583.122603] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3299 to 0x280000400:3329) [ 2587.651590] Lustre: DEBUG MARKER: == replay-single test 55: let MDS_CHECK_RESENT return the original return code instead of 0 ========================================================== 11:52:13 (1777045933) [ 2587.980381] Lustre: *** cfs_fail_loc=12b, val=2147483991*** [ 2587.982906] LustreError: 110551:0:(ldlm_lib.c:3328:target_send_reply_msg()) @@@ dropping reply req@ffff9b1703db1f80 x1863365098664960/t279172874255(0) o101->f3a011ad-a4b5-42c3-9eae-7fc952216c95@192.168.202.16@tcp:181/0 lens 664/608 e 0 to 0 dl 1777045946 ref 1 fl Interpret:/600/0 rc 301/0 job:'touch.0' uid:0 gid:0 projid:0 [ 2587.990679] LustreError: 110551:0:(ldlm_lib.c:3328:target_send_reply_msg()) Skipped 1 previous similar message [ 2603.577218] Lustre: lustre-MDT0000: Client f3a011ad-a4b5-42c3-9eae-7fc952216c95 (at 192.168.202.16@tcp) reconnecting [ 2603.579522] Lustre: Skipped 2 previous similar messages [ 2603.582438] Lustre: 110549:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9b181cbb5f80 x1863365098664960/t279172874255(0) o101->f3a011ad-a4b5-42c3-9eae-7fc952216c95@192.168.202.16@tcp:197/0 lens 664/3488 e 0 to 0 dl 1777045962 ref 1 fl Interpret:/602/0 rc 0/0 job:'touch.0' uid:0 gid:0 projid:0 [ 2605.684353] Lustre: DEBUG MARKER: == replay-single test 56: don't replay a symlink open request (3440) ========================================================== 11:52:31 (1777045951) [ 2606.892755] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2607.482852] Lustre: Failing over lustre-MDT0000 [ 2607.571635] Lustre: server umount lustre-MDT0000 complete [ 2621.161384] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2623.040602] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3139 to 0x240000400:3393) [ 2623.040647] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3331 to 0x280000400:3361) [ 2624.113171] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2624.665402] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2638.237169] Lustre: DEBUG MARKER: == replay-single test 57: test recovery from llog for setattr op ========================================================== 11:53:04 (1777045984) [ 2639.819064] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2640.446733] Lustre: Failing over lustre-MDT0000 [ 2640.730666] Lustre: server umount lustre-MDT0000 complete [ 2654.391235] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2654.807528] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3139 to 0x240000400:3425) [ 2654.807528] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3363 to 0x280000400:3393) [ 2657.421901] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2657.987700] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2660.251200] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 2665.184493] Lustre: DEBUG MARKER: == replay-single test 58a: test recovery from llog for setattr op (test llog_gen_rec) ========================================================== 11:53:31 (1777046011) [ 2673.382943] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2673.991931] Lustre: Failing over lustre-MDT0000 [ 2674.343647] Lustre: server umount lustre-MDT0000 complete [ 2688.095485] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2690.079674] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:4644 to 0x280000400:4673) [ 2690.079759] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:4676 to 0x240000400:4705) [ 2691.156323] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2691.677661] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2704.918443] Lustre: DEBUG MARKER: == replay-single test 58b: test replay of setxattr op ==== 11:54:11 (1777046051) [ 2707.009975] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2707.574165] Lustre: Failing over lustre-MDT0000 [ 2707.804229] Lustre: server umount lustre-MDT0000 complete [ 2720.122888] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 2720.124413] Lustre: Skipped 16 previous similar messages [ 2720.170173] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 2720.171871] Lustre: Skipped 18 previous similar messages [ 2720.390169] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:4676 to 0x240000400:4737) [ 2720.390246] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:4675 to 0x280000400:4705) [ 2721.445558] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2724.327160] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2724.809573] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2727.465246] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount FULL mgc.*.mgs_server_uuid [ 2727.930458] Lustre: DEBUG MARKER: mgc.*.mgs_server_uuid in FULL state after 0 sec [ 2729.997186] Lustre: DEBUG MARKER: == replay-single test 58c: resend/reconstruct setxattr op ========================================================== 11:54:36 (1777046076) [ 2735.519618] Lustre: *** cfs_fail_loc=123, val=2147483648*** [ 2752.856348] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 2752.857860] Lustre: Skipped 1 previous similar message [ 2752.858953] LustreError: 117794:0:(ldlm_lib.c:3328:target_send_reply_msg()) @@@ dropping reply req@ffff9b1702ae3850 x1863365101431296/t296352743435(0) o36->f3a011ad-a4b5-42c3-9eae-7fc952216c95@192.168.202.16@tcp:346/0 lens 66040/440 e 0 to 0 dl 1777046111 ref 1 fl Interpret:/600/0 rc 0/0 job:'setfattr.0' uid:0 gid:0 projid:0 [ 2768.442986] Lustre: 117264:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9b1703e6d180 x1863365101431296/t296352743435(0) o36->f3a011ad-a4b5-42c3-9eae-7fc952216c95@192.168.202.16@tcp:362/0 lens 66040/440 e 0 to 0 dl 1777046127 ref 1 fl Interpret:/602/0 rc 0/0 job:'setfattr.0' uid:0 gid:0 projid:0 [ 2771.494654] Lustre: DEBUG MARKER: SKIP: replay-single test_59 skipping ALWAYS excluded test 59 [ 2772.023501] Lustre: DEBUG MARKER: == replay-single test 60: test llog post recovery init vs llog unlink ========================================================== 11:55:18 (1777046118) [ 2774.927756] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2775.761117] Lustre: Failing over lustre-MDT0000 [ 2775.987993] Lustre: server umount lustre-MDT0000 complete [ 2789.147912] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:4806 to 0x280000400:4833) [ 2789.147921] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:4839 to 0x240000400:4865) [ 2789.858803] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2792.223093] Lustre: 3307:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1777046124/real 1777046124] req@ffff9b17031f1f80 x1863365109855744/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1777046140 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2792.235805] Lustre: 3307:0:(client.c:2479:ptlrpc_expire_one_request()) Skipped 57 previous similar messages [ 2792.945508] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2793.485420] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2797.250444] Lustre: DEBUG MARKER: == replay-single test 61a: test race llog recovery vs llog cleanup ========================================================== 11:55:43 (1777046143) [ 2801.625698] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 2804.851645] Lustre: Failing over lustre-OST0000 [ 2804.852429] LustreError: lustre-OST0000-osc-MDT0000: operation ost_destroy to node 0@lo failed: rc = -19 [ 2804.854517] LustreError: Skipped 5 previous similar messages [ 2804.913908] Lustre: server umount lustre-OST0000 complete [ 2809.311519] LustreError: 116855:0:(ldlm_lib.c:1180: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. [ 2809.315674] LustreError: 116855:0:(ldlm_lib.c:1180:target_handle_connect()) Skipped 5 previous similar messages [ 2814.431729] LustreError: 33760:0:(ldlm_lib.c:1180: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. [ 2814.439092] LustreError: 33760:0:(ldlm_lib.c:1180:target_handle_connect()) Skipped 1 previous similar message [ 2819.183311] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2830.750251] Lustre: Failing over lustre-OST0000 [ 2830.781232] Lustre: server umount lustre-OST0000 complete [ 2832.864026] LustreError: 14750:0:(ldlm_lib.c:1180: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. [ 2832.871100] LustreError: 14750:0:(ldlm_lib.c:1180:target_handle_connect()) Skipped 1 previous similar message [ 2844.865632] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2847.862052] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 2848.355082] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 2882.069690] Lustre: DEBUG MARKER: == replay-single test 61b: test race mds llog sync vs llog cleanup ========================================================== 11:57:08 (1777046228) [ 2882.963740] Lustre: Failing over lustre-MDT0000 [ 2883.159621] Lustre: server umount lustre-MDT0000 complete [ 2895.643833] LustreError: MGC192.168.202.116@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2895.646628] LustreError: Skipped 14 previous similar messages [ 2895.762966] 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 [ 2895.767925] Lustre: Skipped 33 previous similar messages [ 2896.442274] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 2896.445085] Lustre: Skipped 16 previous similar messages [ 2896.461480] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 2896.463525] Lustre: Skipped 16 previous similar messages [ 2896.479101] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5234 to 0x280000400:5249) [ 2896.479592] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5266 to 0x240000400:5281) [ 2897.021248] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2900.961224] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 2900.963637] Lustre: Skipped 33 previous similar messages [ 2908.405215] Lustre: Failing over lustre-MDT0000 [ 2908.514462] Lustre: server umount lustre-MDT0000 complete [ 2922.078213] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5266 to 0x240000400:5313) [ 2922.078258] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5234 to 0x280000400:5281) [ 2922.460245] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2925.592383] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2926.109541] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2929.413485] Lustre: DEBUG MARKER: == replay-single test 61c: test race mds llog sync vs llog cleanup ========================================================== 11:57:55 (1777046275) [ 2940.786914] Lustre: Failing over lustre-OST0000 [ 2940.832091] Lustre: server umount lustre-OST0000 complete [ 2941.407491] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 2941.409921] LustreError: Skipped 1 previous similar message [ 2941.411526] LustreError: 33772:0:(ldlm_lib.c:1180: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. [ 2941.416362] LustreError: 33772:0:(ldlm_lib.c:1180:target_handle_connect()) Skipped 3 previous similar messages [ 2955.022602] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2958.065104] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 2958.598327] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 2962.283894] Lustre: DEBUG MARKER: == replay-single test 61d: error in llog_setup should cleanup the llog context correctly ========================================================== 11:58:28 (1777046308) [ 2962.917066] Lustre: Failing over lustre-MDT0000 [ 2963.001967] Lustre: lustre-MDT0000: Not available for connect from 192.168.202.16@tcp (stopping) [ 2963.034737] Lustre: server umount lustre-MDT0000 complete [ 2965.775617] Lustre: *** cfs_fail_loc=605, val=0*** [ 2965.776794] LustreError: 127165:0:(llog_obd.c:192:llog_setup()) MGS: ctxt 0 lop_setup=ffffffffc12d5ea0 failed: rc = -95 [ 2965.779408] LustreError: 127165:0:(obd_config.c:845:class_setup()) setup MGS failed (-95) [ 2965.781748] LustreError: 127165:0:(obd_mount.c:250:lustre_start_simple()) MGS setup error -95 [ 2965.784147] LustreError: 127165:0:(tgt_mount.c:114:server_deregister_mount()) MGS not registered [ 2965.786061] LustreError: Failed to start MGS 'MGS' (-95). Is the 'mgs' module loaded? [ 2965.787709] LustreError: 127165:0:(tgt_mount.c:2082:server_put_super()) no obd lustre-MDT0000 [ 2965.817266] Lustre: server umount lustre-MDT0000 complete [ 2965.818414] LustreError: 127165:0:(super25.c:184:lustre_fill_super()) llite: Unable to mount : rc = -95 [ 2968.149442] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5315 to 0x240000400:5345) [ 2968.149574] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5283 to 0x280000400:5313) [ 2969.331274] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2972.101201] Lustre: DEBUG MARKER: == replay-single test 62: don't mis-drop resent replay === 11:58:38 (1777046318) [ 2973.118843] LustreError: 128137:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 2973.121561] LustreError: 128137:0:(osd_handler.c:720:osd_ro()) Skipped 13 previous similar messages [ 2973.477773] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2974.829861] Lustre: Failing over lustre-MDT0000 [ 2975.096614] Lustre: server umount lustre-MDT0000 complete [ 2988.608734] Lustre: *** cfs_fail_loc=707, val=0*** [ 2988.866171] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3004.993064] Lustre: lustre-MDT0000: Client f3a011ad-a4b5-42c3-9eae-7fc952216c95 (at 192.168.202.16@tcp) reconnected, waiting for 1 clients in recovery for 0:53 [ 3005.117366] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5358 to 0x240000400:5377) [ 3005.117404] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5327 to 0x280000400:5345) [ 3006.426379] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3006.969435] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3010.757402] Lustre: DEBUG MARKER: == replay-single test 65a: AT: verify early replies ====== 11:59:16 (1777046356) [ 3034.298770] LustreError: 129884:0:(service.c:2537:ptlrpc_server_handle_request()) @@@ HIT req@ffff9b170b0fc000 x1863365102288384/t0(0) o101->f3a011ad-a4b5-42c3-9eae-7fc952216c95@192.168.202.16@tcp:628/0 lens 664/0 e 0 to 0 dl 1777046393 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 3034.307112] LustreError: 129884:0:(service.c:2538:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a sleeping for 11000ms [ 3045.335068] LustreError: 129884:0:(service.c:2538:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a awake [ 3045.341573] LustreError: 128739:0:(service.c:2537:ptlrpc_server_handle_request()) @@@ HIT req@ffff9b18419d5500 x1863365102289792/t0(0) o35->f3a011ad-a4b5-42c3-9eae-7fc952216c95@192.168.202.16@tcp:645/0 lens 392/0 e 0 to 0 dl 1777046410 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 3046.381690] LustreError: 32630:0:(service.c:2537:ptlrpc_server_handle_request()) @@@ HIT req@ffff9b183b6cc000 x1863365110088064/t0(0) o6->lustre-MDT0000-mdtlov_UUID@0@lo:640/0 lens 544/0 e 0 to 0 dl 1777046405 ref 1 fl Interpret:/200/ffffffff rc 0/-1 job:'osp-syn-0-0.0' uid:0 gid:0 projid:4294967295 [ 3046.389131] LustreError: 32630:0:(service.c:2537:ptlrpc_server_handle_request()) Skipped 48 previous similar messages [ 3057.039189] Lustre: DEBUG MARKER: == replay-single test 65b: AT: verify early replies on packed reply / bulk ========================================================== 12:00:03 (1777046403) [ 3080.504673] LustreError: 32691:0:(tgt_handler.c:2821:tgt_brw_write()) cfs_fail_timeout id 224 sleeping for 11000ms [ 3091.535129] LustreError: 32691:0:(tgt_handler.c:2821:tgt_brw_write()) cfs_fail_timeout id 224 awake [ 3094.489952] Lustre: DEBUG MARKER: == replay-single test 66a: AT: verify MDT service time adjusts with no early replies ========================================================== 12:00:40 (1777046440) [ 3117.473838] LustreError: 128737:0:(service.c:2537:ptlrpc_server_handle_request()) @@@ HIT req@ffff9b1703de0e00 x1863365102311680/t0(0) o101->f3a011ad-a4b5-42c3-9eae-7fc952216c95@192.168.202.16@tcp:711/0 lens 576/0 e 0 to 0 dl 1777046476 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 3117.479267] LustreError: 128737:0:(service.c:2538:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a sleeping for 5000ms [ 3122.575095] LustreError: 128737:0:(service.c:2538:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a awake [ 3122.581557] LustreError: 128736:0:(service.c:2537:ptlrpc_server_handle_request()) @@@ HIT req@ffff9b1824948a80 x1863365102312448/t0(0) o101->f3a011ad-a4b5-42c3-9eae-7fc952216c95@192.168.202.16@tcp:716/0 lens 664/0 e 0 to 0 dl 1777046481 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 3123.315673] LustreError: 129124:0:(service.c:2538:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a sleeping for 10000ms [ 3131.367346] LustreError: 33760:0:(service.c:2537:ptlrpc_server_handle_request()) @@@ HIT req@ffff9b18361df800 x1863365110107648/t0(0) o6->lustre-MDT0000-mdtlov_UUID@0@lo:725/0 lens 544/0 e 0 to 0 dl 1777046490 ref 1 fl Interpret:/200/ffffffff rc 0/-1 job:'osp-syn-1-0.0' uid:0 gid:0 projid:4294967295 [ 3131.373784] LustreError: 33760:0:(service.c:2537:ptlrpc_server_handle_request()) Skipped 118 previous similar messages [ 3133.407110] LustreError: 129124:0:(service.c:2538:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a awake [ 3145.467109] Lustre: DEBUG MARKER: == replay-single test 66b: AT: verify net latency adjusts ========================================================== 12:01:31 (1777046491) [ 3230.526432] Lustre: DEBUG MARKER: == replay-single test 67a: AT: verify slow request processing doesn't induce reconnects ========================================================== 12:02:56 (1777046576) [ 3253.928147] LustreError: 130063:0:(service.c:2537:ptlrpc_server_handle_request()) @@@ HIT req@ffff9b181cbb4700 x1863365102387072/t0(0) o101->f3a011ad-a4b5-42c3-9eae-7fc952216c95@192.168.202.16@tcp:92/0 lens 576/0 e 0 to 0 dl 1777046612 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 3253.936337] LustreError: 130063:0:(service.c:2537:ptlrpc_server_handle_request()) Skipped 99 previous similar messages [ 3253.938590] LustreError: 130063:0:(service.c:2538:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a sleeping for 400ms [ 3254.359065] LustreError: 130063:0:(service.c:2538:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a awake [ 3270.208770] LustreError: 129884:0:(service.c:2538:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a sleeping for 400ms [ 3270.212660] LustreError: 129884:0:(service.c:2538:ptlrpc_server_handle_request()) Skipped 38 previous similar messages [ 3270.631098] LustreError: 129884:0:(service.c:2538:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a awake [ 3270.633597] LustreError: 129884:0:(service.c:2538:ptlrpc_server_handle_request()) Skipped 38 previous similar messages [ 3286.081773] LustreError: 130063:0:(service.c:2537:ptlrpc_server_handle_request()) @@@ HIT req@ffff9b181f9e3b80 x1863365102405888/t0(0) o36->f3a011ad-a4b5-42c3-9eae-7fc952216c95@192.168.202.16@tcp:124/0 lens 504/0 e 0 to 0 dl 1777046644 ref 1 fl Interpret:/200/ffffffff rc 0/-1 job:'unlinkmany.0' uid:0 gid:0 projid:4294967295 [ 3286.088147] LustreError: 130063:0:(service.c:2537:ptlrpc_server_handle_request()) Skipped 83 previous similar messages [ 3298.837378] Lustre: DEBUG MARKER: == replay-single test 67b: AT: verify instant slowdown doesn't induce reconnects ========================================================== 12:04:05 (1777046645) [ 3324.356883] Lustre: DEBUG MARKER: phase 2 [ 3328.095212] Lustre: DEBUG MARKER: == replay-single test 68: AT: verify slowing locks ======= 12:04:34 (1777046674) [ 3399.846961] Lustre: DEBUG MARKER: == replay-single test 70a: check multi client t-f ======== 12:05:45 (1777046745) [ 3400.571870] Lustre: DEBUG MARKER: SKIP: replay-single test_70a Need two or more clients, have 1 [ 3401.333315] Lustre: DEBUG MARKER: == replay-single test 70b: dbench 1mdts recovery; 1 clients ========================================================== 12:05:47 (1777046747) [ 3403.212853] Lustre: DEBUG MARKER: Started rundbench load pid=126185 ... [ 3405.916905] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3407.481037] Lustre: DEBUG MARKER: test_70b fail mds1 1 times [ 3408.219597] Lustre: Failing over lustre-MDT0000 [ 3408.533988] Lustre: server umount lustre-MDT0000 complete [ 3421.889848] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3421.891595] Lustre: Skipped 8 previous similar messages [ 3421.914043] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 3421.915693] Lustre: Skipped 8 previous similar messages [ 3423.537643] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3428.319177] Lustre: 3305:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1777046760/real 1777046760] req@ffff9b1705abbb80 x1863365110253440/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1777046776 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3428.336374] Lustre: 3305:0:(client.c:2479:ptlrpc_expire_one_request()) Skipped 22 previous similar messages [ 3429.230415] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5442 to 0x280000400:5473) [ 3429.230589] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5495 to 0x240000400:5537) [ 3430.708543] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3431.493742] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3435.587902] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3437.136326] Lustre: DEBUG MARKER: test_70b fail mds1 2 times [ 3437.810148] Lustre: Failing over lustre-MDT0000 [ 3437.966689] Lustre: server umount lustre-MDT0000 complete [ 3452.482874] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3453.866933] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5534 to 0x280000400:5569) [ 3453.866987] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5598 to 0x240000400:5633) [ 3455.973125] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3456.602119] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3460.620327] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3462.376194] Lustre: DEBUG MARKER: test_70b fail mds1 3 times [ 3463.035927] Lustre: Failing over lustre-MDT0000 [ 3463.335057] Lustre: server umount lustre-MDT0000 complete [ 3476.449562] LustreError: 138548:0:(ldlm_lib.c:1180: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. [ 3476.466175] LustreError: 138548:0:(ldlm_lib.c:1180:target_handle_connect()) Skipped 5 previous similar messages [ 3477.781239] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3479.362840] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5632 to 0x280000400:5665) [ 3479.364752] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5696 to 0x240000400:5729) [ 3481.218429] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3481.923887] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3485.953806] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3487.464375] Lustre: DEBUG MARKER: test_70b fail mds1 4 times [ 3488.084408] Lustre: Failing over lustre-MDT0000 [ 3488.362693] Lustre: server umount lustre-MDT0000 complete [ 3500.913588] LustreError: MGC192.168.202.116@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3500.918180] LustreError: Skipped 6 previous similar messages [ 3501.026227] 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 [ 3501.032045] Lustre: Skipped 13 previous similar messages [ 3502.606181] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3504.697872] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 3504.702746] Lustre: Skipped 7 previous similar messages [ 3504.990150] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 3504.994552] Lustre: Skipped 7 previous similar messages [ 3505.016551] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5730 to 0x280000400:5761) [ 3505.016650] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5794 to 0x240000400:5825) [ 3506.147142] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 3506.155983] Lustre: Skipped 14 previous similar messages [ 3506.619448] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3507.458710] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3511.535730] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3513.171212] Lustre: DEBUG MARKER: test_70b fail mds1 5 times [ 3513.812652] Lustre: Failing over lustre-MDT0000 [ 3513.951711] Lustre: server umount lustre-MDT0000 complete [ 3528.284277] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3530.724359] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5822 to 0x280000400:5857) [ 3530.725213] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5885 to 0x240000400:5921) [ 3531.934299] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3532.496503] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3549.827436] Lustre: DEBUG MARKER: == replay-single test 70c: tar 1mdts recovery ============ 12:08:15 (1777046895) [ 3671.453335] LustreError: 142167:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 3671.456111] LustreError: 142167:0:(osd_handler.c:720:osd_ro()) Skipped 5 previous similar messages [ 3671.843773] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3682.629749] Lustre: DEBUG MARKER: test_70c fail mds1 1 times [ 3683.294859] Lustre: Failing over lustre-MDT0000 [ 3683.332274] LustreError: 3306:0:(client.c:1380:ptlrpc_import_delay_req()) @@@ IMP_CLOSED req@ffff9b1702741880 x1863365112885888/t0(0) o2->lustre-OST0000-osc-MDT0000@0@lo:28/4 lens 440/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 [ 3683.659946] Lustre: server umount lustre-MDT0000 complete [ 3697.575679] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3703.864029] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:8669 to 0x280000400:8705) [ 3703.864568] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:8734 to 0x240000400:8769) [ 3705.114043] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3705.696560] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3828.674554] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3839.590103] Lustre: DEBUG MARKER: test_70c fail mds1 2 times [ 3840.234230] Lustre: Failing over lustre-MDT0000 [ 3840.294131] LustreError: 3306:0:(client.c:1380:ptlrpc_import_delay_req()) @@@ IMP_CLOSED req@ffff9b170d7fa680 x1863365115046912/t0(0) o6->lustre-OST0001-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-1-0.0' uid:0 gid:0 projid:4294967295 [ 3840.300418] LustreError: 3306:0:(client.c:1380:ptlrpc_import_delay_req()) Skipped 3 previous similar messages [ 3840.613546] Lustre: server umount lustre-MDT0000 complete [ 3854.552320] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3863.267553] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:11531 to 0x240000400:11553) [ 3863.267614] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:11470 to 0x280000400:11489) [ 3864.426936] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3864.963421] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3875.848236] Lustre: DEBUG MARKER: == replay-single test 70d: mkdir/rmdir striped dir 1mdts recovery ========================================================== 12:13:42 (1777047222) [ 3876.340337] Lustre: DEBUG MARKER: SKIP: replay-single test_70d needs >= 2 MDTs [ 3876.878868] Lustre: DEBUG MARKER: == replay-single test 70e: rename cross-MDT with random fails ========================================================== 12:13:43 (1777047223) [ 3877.313723] Lustre: DEBUG MARKER: SKIP: replay-single test_70e needs >= 2 MDTs [ 3877.797452] Lustre: DEBUG MARKER: == replay-single test 70f: OSS O_DIRECT recovery with 1 clients ========================================================== 12:13:44 (1777047224) [ 3882.329921] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 3883.821622] Lustre: DEBUG MARKER: test_70f failing OST 1 times [ 3884.480090] Lustre: Failing over lustre-OST0000 [ 3884.503913] Lustre: server umount lustre-OST0000 complete [ 3888.698434] LustreError: 33770:0:(ldlm_lib.c:1180:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.202.16@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3888.703071] LustreError: 33770:0:(ldlm_lib.c:1180:target_handle_connect()) Skipped 1 previous similar message [ 3889.119930] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 3898.313351] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3901.480419] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 3902.096466] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 3909.977085] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 3911.618079] Lustre: DEBUG MARKER: test_70f failing OST 2 times [ 3912.391188] Lustre: Failing over lustre-OST0000 [ 3912.412439] Lustre: server umount lustre-OST0000 complete [ 3913.695514] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 3926.721149] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3930.103023] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 3930.733517] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 3938.426404] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 3939.902096] Lustre: DEBUG MARKER: test_70f failing OST 3 times [ 3940.510790] Lustre: Failing over lustre-OST0000 [ 3940.535068] Lustre: server umount lustre-OST0000 complete [ 3942.367570] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 3954.849622] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3958.211786] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 3958.840081] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 3964.467200] Lustre: DEBUG MARKER: == replay-single test 71a: mkdir/rmdir striped dir with 2 mdts recovery ========================================================== 12:15:10 (1777047310) [ 3965.010444] Lustre: DEBUG MARKER: SKIP: replay-single test_71a needs >= 2 MDTs [ 3965.607881] Lustre: DEBUG MARKER: == replay-single test 73a: open(O_CREAT), unlink, replay, reconnect before open replay, close ========================================================== 12:15:11 (1777047311) [ 3966.953529] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3968.010945] Lustre: Failing over lustre-MDT0000 [ 3968.109103] Lustre: server umount lustre-MDT0000 complete [ 3980.858424] LustreError: 150251:0:(ldlm_lib.c:1180:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.202.16@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3980.863945] LustreError: 150251:0:(ldlm_lib.c:1180:target_handle_connect()) Skipped 14 previous similar messages [ 3982.332972] Lustre: *** cfs_fail_loc=302, val=2147483648*** [ 3982.458329] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3998.277641] Lustre: lustre-MDT0000: Client f3a011ad-a4b5-42c3-9eae-7fc952216c95 (at 192.168.202.16@tcp) reconnected, waiting for 1 clients in recovery for 0:54 [ 3998.331815] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:11632 to 0x240000400:11649) [ 3998.331823] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:11567 to 0x280000400:11585) [ 3999.735427] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4000.356237] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4003.770501] Lustre: DEBUG MARKER: == replay-single test 73b: open(O_CREAT), unlink, replay, reconnect at open_replay reply, close ========================================================== 12:15:49 (1777047349) [ 4005.098401] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4006.003239] Lustre: Failing over lustre-MDT0000 [ 4006.259874] Lustre: server umount lustre-MDT0000 complete [ 4020.463157] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4021.830126] Lustre: *** cfs_fail_loc=157, val=2147483648*** [ 4021.831668] LustreError: 151737:0:(ldlm_lib.c:3328:target_send_reply_msg()) @@@ dropping reply req@ffff9b18067a4e00 x1863365146935296/t352187318275(352187318275) o101->f3a011ad-a4b5-42c3-9eae-7fc952216c95@192.168.202.16@tcp:105/0 lens 592/608 e 0 to 0 dl 1777047380 ref 1 fl Interpret:/604/0 rc 301/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 4032.479074] Lustre: 3308:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1777047364/real 1777047364] req@ffff9b18067a6680 x1863365115550208/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1777047380 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4032.485423] Lustre: 3308:0:(client.c:2479:ptlrpc_expire_one_request()) Skipped 39 previous similar messages [ 4038.212764] Lustre: lustre-MDT0000: Client f3a011ad-a4b5-42c3-9eae-7fc952216c95 (at 192.168.202.16@tcp) reconnected, waiting for 1 clients in recovery for 0:53 [ 4038.218111] Lustre: 151738:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9b18067a4700 x1863365146935296/t352187318275(352187318275) o101->f3a011ad-a4b5-42c3-9eae-7fc952216c95@192.168.202.16@tcp:122/0 lens 592/3488 e 0 to 0 dl 1777047397 ref 1 fl Interpret:/606/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 4038.255252] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:11632 to 0x240000400:11681) [ 4038.255445] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:11587 to 0x280000400:11617) [ 4039.568540] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4040.083686] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4043.755596] Lustre: DEBUG MARKER: == replay-single test 74: Ensure applications don't fail waiting for OST recovery ========================================================== 12:16:29 (1777047389) [ 4044.642770] Lustre: Failing over lustre-OST0000 [ 4044.673895] Lustre: server umount lustre-OST0000 complete [ 4045.954897] Lustre: Failing over lustre-MDT0000 [ 4046.074890] Lustre: server umount lustre-MDT0000 complete [ 4058.500859] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4058.502743] Lustre: Skipped 11 previous similar messages [ 4058.549205] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:11587 to 0x280000400:11649) [ 4059.798700] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4062.047360] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 4062.049190] Lustre: Skipped 11 previous similar messages [ 4062.163745] Lustre: lustre-OST0000: Denying connection for new client c88c4489-b338-4601-931b-b4677769d580 (at 192.168.202.16@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 1:00 [ 4062.169026] Lustre: Skipped 11 previous similar messages [ 4063.930050] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4067.316892] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:11632 to 0x240000400:11713) [ 4068.049035] Lustre: DEBUG MARKER: == replay-single test 80a: DNE: create remote dir, drop update rep from MDT0, fail MDT0 ========================================================== 12:16:54 (1777047414) [ 4068.540786] Lustre: DEBUG MARKER: SKIP: replay-single test_80a needs >= 2 MDTs [ 4069.065270] Lustre: DEBUG MARKER: == replay-single test 80b: DNE: create remote dir, drop update rep from MDT0, fail MDT1 ========================================================== 12:16:55 (1777047415) [ 4069.595815] Lustre: DEBUG MARKER: SKIP: replay-single test_80b needs >= 2 MDTs [ 4070.161728] Lustre: DEBUG MARKER: == replay-single test 80c: DNE: create remote dir, drop update rep from MDT1, fail MDT[0,1] ========================================================== 12:16:56 (1777047416) [ 4070.733376] Lustre: DEBUG MARKER: SKIP: replay-single test_80c needs >= 2 MDTs [ 4071.316988] Lustre: DEBUG MARKER: == replay-single test 80d: DNE: create remote dir, drop update rep from MDT1, fail 2 MDTs ========================================================== 12:16:57 (1777047417) [ 4071.841503] Lustre: DEBUG MARKER: SKIP: replay-single test_80d needs >= 2 MDTs [ 4072.420834] Lustre: DEBUG MARKER: == replay-single test 80e: DNE: create remote dir, drop MDT1 rep, fail MDT0 ========================================================== 12:16:58 (1777047418) [ 4072.945344] Lustre: DEBUG MARKER: SKIP: replay-single test_80e needs >= 2 MDTs [ 4073.507650] Lustre: DEBUG MARKER: == replay-single test 80f: DNE: create remote dir, drop MDT1 rep, fail MDT1 ========================================================== 12:16:59 (1777047419) [ 4074.010894] Lustre: DEBUG MARKER: SKIP: replay-single test_80f needs >= 2 MDTs [ 4074.540895] Lustre: DEBUG MARKER: == replay-single test 80g: DNE: create remote dir, drop MDT1 rep, fail MDT0, then MDT1 ========================================================== 12:17:00 (1777047420) [ 4075.071785] Lustre: DEBUG MARKER: SKIP: replay-single test_80g needs >= 2 MDTs [ 4075.601797] Lustre: DEBUG MARKER: == replay-single test 80h: DNE: create remote dir, drop MDT1 rep, fail 2 MDTs ========================================================== 12:17:01 (1777047421) [ 4076.058226] Lustre: DEBUG MARKER: SKIP: replay-single test_80h needs >= 2 MDTs [ 4076.580184] Lustre: DEBUG MARKER: == replay-single test 81a: DNE: unlink remote dir, drop MDT0 update rep, fail MDT1 ========================================================== 12:17:02 (1777047422) [ 4077.050901] Lustre: DEBUG MARKER: SKIP: replay-single test_81a needs >= 2 MDTs [ 4077.593096] Lustre: DEBUG MARKER: == replay-single test 81b: DNE: unlink remote dir, drop MDT0 update reply, fail MDT0 ========================================================== 12:17:03 (1777047423) [ 4078.110752] Lustre: DEBUG MARKER: SKIP: replay-single test_81b needs >= 2 MDTs [ 4078.658235] Lustre: DEBUG MARKER: == replay-single test 81c: DNE: unlink remote dir, drop MDT0 update reply, fail MDT0,MDT1 ========================================================== 12:17:04 (1777047424) [ 4079.130332] Lustre: DEBUG MARKER: SKIP: replay-single test_81c needs >= 2 MDTs [ 4079.711937] Lustre: DEBUG MARKER: == replay-single test 81d: DNE: unlink remote dir, drop MDT0 update reply, fail 2 MDTs ========================================================== 12:17:05 (1777047425) [ 4080.198231] Lustre: DEBUG MARKER: SKIP: replay-single test_81d needs >= 2 MDTs [ 4080.745774] Lustre: DEBUG MARKER: == replay-single test 81e: DNE: unlink remote dir, drop MDT1 req reply, fail MDT0 ========================================================== 12:17:06 (1777047426) [ 4081.273974] Lustre: DEBUG MARKER: SKIP: replay-single test_81e needs >= 2 MDTs [ 4081.829662] Lustre: DEBUG MARKER: == replay-single test 81f: DNE: unlink remote dir, drop MDT1 req reply, fail MDT1 ========================================================== 12:17:08 (1777047428) [ 4082.296771] Lustre: DEBUG MARKER: SKIP: replay-single test_81f needs >= 2 MDTs [ 4082.836426] Lustre: DEBUG MARKER: == replay-single test 81g: DNE: unlink remote dir, drop req reply, fail M0, then M1 ========================================================== 12:17:09 (1777047429) [ 4083.363672] Lustre: DEBUG MARKER: SKIP: replay-single test_81g needs >= 2 MDTs [ 4083.924644] Lustre: DEBUG MARKER: == replay-single test 81h: DNE: unlink remote dir, drop request reply, fail 2 MDTs ========================================================== 12:17:10 (1777047430) [ 4084.427189] Lustre: DEBUG MARKER: SKIP: replay-single test_81h needs >= 2 MDTs [ 4084.999675] Lustre: DEBUG MARKER: == replay-single test 84a: stale open during export disconnect ========================================================== 12:17:11 (1777047431) [ 4085.592378] Lustre: 156096:0:(genops.c:1795:obd_export_evict_by_uuid()) lustre-MDT0000: evicting c88c4489-b338-4601-931b-b4677769d580 at adminstrative request [ 4088.937516] Lustre: DEBUG MARKER: == replay-single test 85a: check the cancellation of unused locks during recovery(IBITS) ========================================================== 12:17:15 (1777047435) [ 4090.940154] Lustre: Failing over lustre-MDT0000 [ 4091.271880] Lustre: server umount lustre-MDT0000 complete [ 4103.686746] LustreError: MGC192.168.202.116@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4103.689595] LustreError: Skipped 6 previous similar messages [ 4105.184317] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4106.810588] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4106.813620] Lustre: Skipped 9 previous similar messages [ 4106.974369] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4106.977300] Lustre: Skipped 9 previous similar messages [ 4106.993362] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:11701 to 0x280000400:11745) [ 4106.993447] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:11765 to 0x240000400:11809) [ 4108.291200] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4108.831161] 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 [ 4108.838358] Lustre: Skipped 16 previous similar messages [ 4108.843586] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 4108.846841] Lustre: Skipped 16 previous similar messages [ 4108.915658] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4112.623847] Lustre: DEBUG MARKER: == replay-single test 85b: check the cancellation of unused locks during recovery(EXTENT) ========================================================== 12:17:38 (1777047458) [ 4117.627114] Lustre: Failing over lustre-OST0000 [ 4117.697237] Lustre: server umount lustre-OST0000 complete [ 4119.008345] LustreError: 6548:0:(ldlm_lib.c:1180: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. [ 4119.015224] LustreError: 6548:0:(ldlm_lib.c:1180:target_handle_connect()) Skipped 3 previous similar messages [ 4132.852637] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4136.114101] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 4136.707229] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4140.467151] Lustre: DEBUG MARKER: == replay-single test 86: umount server after clear nid_stats should not hit LBUG ========================================================== 12:18:06 (1777047486) [ 4141.788922] Lustre: Failing over lustre-MDT0000 [ 4141.949430] Lustre: server umount lustre-MDT0000 complete [ 4144.818410] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:11910 to 0x240000400:11937) [ 4144.818423] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:11701 to 0x280000400:11777) [ 4146.170074] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4149.222423] Lustre: DEBUG MARKER: == replay-single test 87a: write replay ================== 12:18:15 (1777047495) [ 4151.204404] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 4152.101371] Lustre: Failing over lustre-OST0000 [ 4152.125538] Lustre: server umount lustre-OST0000 complete [ 4154.848196] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 4166.864946] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4170.423330] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 4170.925209] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4174.556444] Lustre: DEBUG MARKER: == replay-single test 87b: write replay with changed data (checksum resend) ========================================================== 12:18:40 (1777047520) [ 4176.310467] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 4178.346717] Lustre: Failing over lustre-OST0000 [ 4178.371089] Lustre: server umount lustre-OST0000 complete [ 4192.622308] LustreError: lustre-OST0000: BAD WRITE CHECKSUM: from 12345-192.168.202.16@tcp inode [0x20002a3e1:0x5:0x0] object 0x240000400:11939 extent [0-1048575]: client csum 20c6ffa3, server csum f4c2ff8d [ 4193.607795] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4196.732712] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 4197.258610] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4200.635167] Lustre: DEBUG MARKER: == replay-single test 88: MDS should not assign same objid to different files ========================================================== 12:19:06 (1777047546) [ 4201.869540] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 4203.087036] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4204.987483] Lustre: Failing over lustre-MDT0000 [ 4205.224850] Lustre: server umount lustre-MDT0000 complete [ 4206.479949] LustreError: 5759:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1777047554 with bad export cookie 10892502418358309023 [ 4216.800405] Lustre: Failing over lustre-OST0000 [ 4216.833450] Lustre: server umount lustre-OST0000 complete [ 4231.263146] LustreError: 164265:0:(import.c:337:ptlrpc_invalidate_import()) MGS: timeout waiting for callback (1 != 0) [ 4231.269056] LustreError: 164265:0:(import.c:361:ptlrpc_invalidate_import()) @@@ still on sending list req@ffff9b1809230e00 x1863365115644032/t0(0) o250->MGC192.168.202.116@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 1777047579 ref 1 fl Rpc:NQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4231.284658] LustreError: 164265:0:(import.c:371:ptlrpc_invalidate_import()) MGS: Unregistering RPCs found (0). Network is sluggish? Waiting for them to error out. [ 4232.159723] LustreError: 3304:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9b18193e5c00 x1863365115644416/t0(0) o250->MGC192.168.202.116@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 [ 4234.177932] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4235.576574] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:11816 to 0x280000400:11841) [ 4248.413834] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:11940 to 0x240000400:11969) [ 4249.321461] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4255.247317] Lustre: DEBUG MARKER: == replay-single test 89: no disk space leak on late ost connection ========================================================== 12:20:01 (1777047601) [ 4265.105973] Lustre: Failing over lustre-OST0000 [ 4265.160491] Lustre: server umount lustre-OST0000 complete [ 4266.509169] Lustre: Failing over lustre-MDT0000 [ 4266.823624] Lustre: server umount lustre-MDT0000 complete [ 4280.748656] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4281.474967] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:11816 to 0x280000400:11873) [ 4287.211355] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4287.926160] Lustre: lustre-OST0000: Denying connection for new client c0875523-39a2-47d5-9a8d-8b5601289419 (at 192.168.202.16@tcp), waiting for 2 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:59 [ 4287.933686] Lustre: Skipped 1 previous similar message [ 4308.537711] Lustre: lustre-OST0000: Denying connection for new client c0875523-39a2-47d5-9a8d-8b5601289419 (at 192.168.202.16@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 0:48 [ 4308.548826] Lustre: Skipped 3 previous similar messages [ 4344.377102] Lustre: lustre-OST0000: Denying connection for new client c0875523-39a2-47d5-9a8d-8b5601289419 (at 192.168.202.16@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 0:13 [ 4344.381214] Lustre: Skipped 6 previous similar messages [ 4357.500154] Lustre: lustre-OST0000: recovery is timed out, evict stale exports [ 4357.502923] Lustre: 167263:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-OST0000: disconnect stale client f4d5bebc-6831-41c8-9bd1-f098e8ee90af@ [ 4357.508390] Lustre: lustre-OST0000: disconnecting 1 stale clients [ 4357.525082] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:11980 to 0x240000400:12001) [ 4360.926061] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 69 sec [ 4378.648219] Lustre: DEBUG MARKER: free_before: 7520256 free_after: 7520256 [ 4381.324485] Lustre: DEBUG MARKER: == replay-single test 90: lfs find identifies the missing striped file segments ========================================================== 12:22:07 (1777047727) [ 4382.764352] Lustre: Failing over lustre-OST0001 [ 4382.798433] Lustre: server umount lustre-OST0001 complete [ 4385.353129] LustreError: 33767:0:(ldlm_lib.c:1180:target_handle_connect()) lustre-OST0001: not available for connect from 192.168.202.16@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4385.362798] LustreError: 33767:0:(ldlm_lib.c:1180:target_handle_connect()) Skipped 31 previous similar messages [ 4387.295751] LustreError: lustre-OST0001-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 4398.857667] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4403.338677] Lustre: DEBUG MARKER: == replay-single test 93a: replay + reconnect ============ 12:22:29 (1777047749) [ 4404.982085] Lustre: Failing over lustre-OST0000 [ 4405.062618] Lustre: server umount lustre-OST0000 complete [ 4419.139963] LustreError: 170310:0:(ldlm_lib.c:2887:target_recovery_thread()) cfs_fail_timeout id 715 sleeping for 40000ms [ 4419.146866] LustreError: 170310:0:(ldlm_lib.c:2887:target_recovery_thread()) Skipped 78 previous similar messages [ 4420.140314] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4425.183281] Lustre: *** cfs_fail_loc=715, val=40*** [ 4434.399590] Lustre: lustre-OST0000: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnected, waiting for 2 clients in recovery for 1:25 [ 4440.543176] Lustre: *** cfs_fail_loc=715, val=40*** [ 4440.546303] Lustre: Skipped 1 previous similar message [ 4450.783467] Lustre: lustre-OST0000: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnected, waiting for 2 clients in recovery for 1:08 [ 4450.788415] Lustre: Skipped 1 previous similar message [ 4456.927175] Lustre: *** cfs_fail_loc=715, val=40*** [ 4456.929964] Lustre: Skipped 1 previous similar message [ 4459.191110] LustreError: 170310:0:(ldlm_lib.c:2887:target_recovery_thread()) cfs_fail_timeout id 715 awake [ 4459.196221] LustreError: 170310:0:(ldlm_lib.c:2887:target_recovery_thread()) Skipped 79 previous similar messages [ 4460.744881] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 4461.258845] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4464.646577] Lustre: DEBUG MARKER: == replay-single test 93b: replay + reconnect on mds ===== 12:23:30 (1777047810) [ 4466.322301] Lustre: Failing over lustre-MDT0000 [ 4466.673043] Lustre: server umount lustre-MDT0000 complete [ 4481.391296] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4481.598991] LustreError: 171743:0:(ldlm_lib.c:2887:target_recovery_thread()) cfs_fail_timeout id 715 sleeping for 80000ms [ 4487.647219] Lustre: *** cfs_fail_loc=715, val=80*** [ 4487.650963] Lustre: Skipped 1 previous similar message [ 4497.992024] Lustre: lustre-MDT0000: Client c0875523-39a2-47d5-9a8d-8b5601289419 (at 192.168.202.16@tcp) reconnected, waiting for 1 clients in recovery for 0:53 [ 4497.995269] Lustre: Skipped 1 previous similar message [ 4504.031122] Lustre: *** cfs_fail_loc=715, val=80*** [ 4513.336911] Lustre: lustre-MDT0000: Client c0875523-39a2-47d5-9a8d-8b5601289419 (at 192.168.202.16@tcp) reconnected, waiting for 1 clients in recovery for 0:38 [ 4519.391146] Lustre: *** cfs_fail_loc=715, val=80*** [ 4529.721183] Lustre: lustre-MDT0000: Client c0875523-39a2-47d5-9a8d-8b5601289419 (at 192.168.202.16@tcp) reconnected, waiting for 1 clients in recovery for 0:21 [ 4535.775160] Lustre: *** cfs_fail_loc=715, val=80*** [ 4561.465092] Lustre: lustre-MDT0000: Recovery already passed deadline 0:09. If you do not want to wait more, you may force taget eviction via 'lctl --device lustre-MDT0000 abort_recovery. [ 4561.679088] LustreError: 171743:0:(ldlm_lib.c:2887:target_recovery_thread()) cfs_fail_timeout id 715 awake [ 4561.689488] Lustre: 171743:0:(ldlm_lib.c:2933:target_recovery_thread()) too long recovery - read logs [ 4561.692131] LustreError: dumping log to /tmp/lustre-log.1777047909.171743 [ 4561.750528] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:11886 to 0x280000400:11905) [ 4561.750538] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:12015 to 0x240000400:12033) [ 4562.977257] Lustre: DEBUG MARKER: oleg216-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4563.558821] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4567.942577] Lustre: DEBUG MARKER: == replay-single test complete, duration 4369 sec ======== 12:25:14 (1777047914) [ 4568.572734] Lustre: DEBUG MARKER: === replay-single: start cleanup 12:25:14 (1777047914) === [ 4572.518379] Lustre: DEBUG MARKER: === replay-single: finish cleanup 12:25:18 (1777047918) === [ 4602.848574] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4602.852942] Lustre: Skipped 1 previous similar message [ 4604.667111] Lustre: server umount lustre-MDT0000 complete [ 4605.993658] LustreError: 116637:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1777047953 with bad export cookie 10892502418358322015 [ 4605.997109] LustreError: 116637:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 4606.024592] Lustre: server umount lustre-OST0000 complete [ 4607.565580] Lustre: server umount lustre-OST0001 complete [ 4612.994290] Lustre: DEBUG MARKER: oleg216-server.virtnet: executing unload_modules_local [ 4614.456621] Key type lgssc unregistered [ 4614.626506] LNet: 173734:0:(lib-ptl.c:967:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 4614.631559] LNetError: 173734:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 4614.642799] LNet: Removed LNI 192.168.202.116@tcp [ 4615.086188] Key type .llcrypt unregistered [ 4615.088577] Key type ._llcrypt unregistered