[ 0.000000] Linux version 4.18.0rh8.10-debug (green@maintenance) (gcc version 8.5.0 20210514 (Red Hat 8.5.0-26) (GCC)) #2 SMP Mon Jul 14 01:24:22 EDT 2025 [ 0.000000] Command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers' [ 0.000000] x86/fpu: xstate_offset[2]: 576, xstate_sizes[2]: 256 [ 0.000000] x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'standard' format. [ 0.000000] signal: max sigframe size: 1776 [ 0.000000] BIOS-provided physical RAM map: [ 0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable [ 0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000000100000-0x00000000bffcdfff] usable [ 0.000000] BIOS-e820: [mem 0x00000000bffce000-0x00000000bfffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000100000000-0x0000000146dfffff] usable [ 0.000000] NX (Execute Disable) protection: active [ 0.000000] SMBIOS 2.8 present. [ 0.000000] DMI: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.17.0-10.fc44 06/10/2025 [ 0.000000] Hypervisor detected: KVM [ 0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00 [ 0.000000] kvm-clock: using sched offset of 453442790 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2400.000 MHz processor [ 0.000000] last_pfn = 0x146e00 max_arch_pfn = 0x400000000 [ 0.000000] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT [ 0.000000] last_pfn = 0xbffce max_arch_pfn = 0x400000000 [ 0.000000] found SMP MP-table at [mem 0x000f54b0-0x000f54bf] [ 0.000000] RAMDISK: [mem 0xbcc54000-0xbffbffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F52D0 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE247C 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE2318 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 0022D8 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE238C 000090 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE241C 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE2454 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe2318-0xbffe238b] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe2317] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe238c-0xbffe241b] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe241c-0xbffe2453] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe2454-0xbffe247b] [ 0.000000] No NUMA configuration found [ 0.000000] Faking a node at [mem 0x0000000000000000-0x0000000146dfffff] [ 0.000000] NODE_DATA(0) allocated [mem 0x1465a3000-0x1465cdfff] [ 0.000000] Reserving 256MB of memory at 2752MB for crashkernel (System RAM: 4205MB) [ 0.000000] Zone ranges: [ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.000000] DMA32 [mem 0x0000000001000000-0x00000000ffffffff] [ 0.000000] Normal [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Device empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff] [ 0.000000] node 0: [mem 0x0000000000100000-0x00000000bffcdfff] [ 0.000000] node 0: [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Zeroed struct page in unavailable ranges: 4756 pages [ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x0000000146dfffff] [ 0.000000] ACPI: PM-Timer IO Port: 0x608 [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) [ 0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) [ 0.000000] Using ACPI (MADT) for SMP configuration information [ 0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000] TSC deadline timer available [ 0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs [ 0.000000] kvm-guest: KVM setup pv remote TLB flush [ 0.000000] kvm-guest: setup PV sched yield [ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff] [ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff] [ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff] [ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff] [ 0.000000] PM: Registered nosave memory: [mem 0xbffce000-0xbfffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xc0000000-0xfeffbfff] [ 0.000000] PM: Registered nosave memory: [mem 0xfeffc000-0xfeffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xff000000-0xfffbffff] [ 0.000000] PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff] [ 0.000000] [mem 0xc0000000-0xfeffbfff] available for PCI devices [ 0.000000] Booting paravirtualized kernel on KVM [ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns [ 0.000000] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1 [ 0.000000] percpu: Embedded 63 pages/cpu s221184 r8192 d28672 u524288 [ 0.000000] kvm-guest: PV spinlocks enabled [ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1059606 [ 0.000000] Policy zone: Normal [ 0.000000] Kernel command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] Specific versions of hardware are certified with Red Hat Enterprise Linux 8. Please see the list of hardware certified with Red Hat Enterprise Linux 8 at https://catalog.redhat.com. [ 0.000000] audit: disabled (until reboot) [ 0.000000] software IO TLB: area num 4. [ 0.000000] Memory: 2829652K/4306352K available (18435K kernel code, 11221K rwdata, 7248K rodata, 2908K init, 18040K bss, 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.002406] x2apic enabled [ 0.003009] Switched APIC routing to physical x2apic. [ 0.004015] kvm-guest: setup PV IPIs [ 0.007454] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.008000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x22983777dd9, max_idle_ns: 440795300422 ns [ 0.009024] Calibrating delay loop (skipped) preset value.. 4800.00 BogoMIPS (lpj=2400000) [ 0.011005] pid_max: default: 32768 minimum: 301 [ 0.012132] LSM: Security Framework initializing [ 0.013057] Yama: becoming mindful. [ 0.014040] SELinux: Initializing. [ 0.015080] *** VALIDATE selinux *** [ 0.024508] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.029297] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.030167] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.031108] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.032131] *** VALIDATE tmpfs *** [ 0.034213] *** VALIDATE proc *** [ 0.036016] *** VALIDATE cgroup *** [ 0.037010] *** VALIDATE cgroup2 *** [ 0.038291] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.039150] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.040011] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.041031] Spectre V2 : User space: Vulnerable [ 0.042010] Speculative Store Bypass: Vulnerable [ 0.045078] debug: unmapping init [mem 0xffffffff87059000-0xffffffff87060fff] [ 0.048000] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.048695] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.049030] ... version: 2 [ 0.050020] ... bit width: 48 [ 0.051017] ... generic registers: 4 [ 0.052016] ... value mask: 0000ffffffffffff [ 0.053019] ... max period: 00007fffffffffff [ 0.054018] ... fixed-purpose events: 3 [ 0.055014] ... event mask: 000000070000000f [ 0.056285] rcu: Hierarchical SRCU implementation. [ 0.058454] smp: Bringing up secondary CPUs ... [ 0.059625] x86: Booting SMP configuration: [ 0.060026] .... node #0, CPUs: #1 #2 #3 [ 0.063419] smp: Brought up 1 node, 4 CPUs [ 0.065015] smpboot: Max logical packages: 1 [ 0.066019] smpboot: Total of 4 processors activated (19200.00 BogoMIPS) [ 0.136513] node 0 deferred pages initialised in 68ms [ 0.139105] devtmpfs: initialized [ 0.140286] x86/mm: Memory block size: 128MB [ 0.144113] gcov: version magic: 0x41383552 [ 0.147135] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.150109] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.152356] pinctrl core: initialized pinctrl subsystem [ 0.155207] [ 0.155812] ************************************************************* [ 0.158013] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.160010] ** ** [ 0.162011] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.165012] ** ** [ 0.167011] ** This means that this kernel is built to expose internal ** [ 0.169014] ** IOMMU data structures, which may compromise security on ** [ 0.171012] ** your system. ** [ 0.173013] ** ** [ 0.175014] ** If you see this message and you are not debugging the ** [ 0.177010] ** kernel, report this immediately to your vendor! ** [ 0.179010] ** ** [ 0.181010] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.183011] ************************************************************* [ 0.185638] NET: Registered protocol family 16 [ 0.187431] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.190065] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.193063] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.196100] cpuidle: using governor menu [ 0.197754] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.198609] PCI: Using configuration type 1 for base access [ 0.200134] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.209143] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.212044] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.215083] cryptd: max_cpu_qlen set to 1000 [ 0.218219] ACPI: Added _OSI(Module Device) [ 0.219011] ACPI: Added _OSI(Processor Device) [ 0.220007] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.222011] ACPI: Added _OSI(Processor Aggregator Device) [ 0.226908] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.233492] ACPI: Interpreter enabled [ 0.234063] ACPI: PM: (supports S0 S3 S4 S5) [ 0.236016] ACPI: Using IOAPIC for interrupt routing [ 0.237100] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.240538] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.253286] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.256043] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.258018] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.262094] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.267705] acpiphp: Slot [2] registered [ 0.269135] acpiphp: Slot [5] registered [ 0.271183] acpiphp: Slot [6] registered [ 0.273118] acpiphp: Slot [7] registered [ 0.274108] acpiphp: Slot [8] registered [ 0.276153] acpiphp: Slot [9] registered [ 0.278133] acpiphp: Slot [10] registered [ 0.279106] acpiphp: Slot [3] registered [ 0.281130] acpiphp: Slot [4] registered [ 0.283160] acpiphp: Slot [11] registered [ 0.285132] acpiphp: Slot [12] registered [ 0.287124] acpiphp: Slot [13] registered [ 0.288113] acpiphp: Slot [14] registered [ 0.290135] acpiphp: Slot [15] registered [ 0.292110] acpiphp: Slot [16] registered [ 0.293143] acpiphp: Slot [17] registered [ 0.295115] acpiphp: Slot [18] registered [ 0.296125] acpiphp: Slot [19] registered [ 0.298113] acpiphp: Slot [20] registered [ 0.299119] acpiphp: Slot [21] registered [ 0.300142] acpiphp: Slot [22] registered [ 0.302131] acpiphp: Slot [23] registered [ 0.304111] acpiphp: Slot [24] registered [ 0.305111] acpiphp: Slot [25] registered [ 0.307122] acpiphp: Slot [26] registered [ 0.308138] acpiphp: Slot [27] registered [ 0.310136] acpiphp: Slot [28] registered [ 0.312122] acpiphp: Slot [29] registered [ 0.313145] acpiphp: Slot [30] registered [ 0.315066] acpiphp: Slot [31] registered [ 0.316067] PCI host bridge to bus 0000:00 [ 0.318033] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.320025] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.323032] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.325025] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.328024] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.331027] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.333189] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.336054] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.339314] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.348738] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.355563] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.359019] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.361018] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.363017] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.366500] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.369830] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.372044] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.376813] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.382016] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.396025] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.401015] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.406526] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.414016] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.420017] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.437016] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.447401] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.456013] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.467015] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.482022] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.494221] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.503014] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.512015] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.531013] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.540674] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.547015] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.551014] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.561016] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.571325] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.578020] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.583018] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.597018] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 0.605953] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.611962] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.615948] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.634021] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 0.645252] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.647442] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.650388] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.653366] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.655218] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.659112] iommu: Default domain type: Passthrough [ 0.661420] SCSI subsystem initialized [ 0.662152] ACPI: bus type USB registered [ 0.664123] usbcore: registered new interface driver usbfs [ 0.666065] usbcore: registered new interface driver hub [ 0.668107] usbcore: registered new device driver usb [ 0.669158] pps_core: LinuxPPS API ver. 1 registered [ 0.671015] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.674061] PTP clock support registered [ 0.677079] EDAC MC: Ver: 3.0.0 [ 0.679151] PCI: Using ACPI for IRQ routing [ 0.681881] NetLabel: Initializing [ 0.683014] NetLabel: domain hash size = 128 [ 0.684011] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.686087] NetLabel: unlabeled traffic allowed by default [ 0.688148] vgaarb: loaded [ 0.689305] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.691013] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.695360] clocksource: Switched to clocksource kvm-clock [ 0.805048] VFS: Disk quotas dquot_6.6.0 [ 0.806690] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.809147] *** VALIDATE ramfs *** [ 0.810374] *** VALIDATE hugetlbfs *** [ 0.811907] pnp: PnP ACPI init [ 0.814378] pnp: PnP ACPI: found 6 devices [ 0.830853] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.834280] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.836439] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.838612] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.840460] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.843089] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.845960] NET: Registered protocol family 2 [ 0.848429] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.853470] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.856691] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.862414] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.865966] TCP: Hash tables configured (established 65536 bind 65536) [ 0.869287] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.872086] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.874821] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.877989] NET: Registered protocol family 1 [ 0.881406] RPC: Registered named UNIX socket transport module. [ 0.883614] RPC: Registered udp transport module. [ 0.885257] RPC: Registered tcp transport module. [ 0.886548] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.888156] NET: Registered protocol family 44 [ 0.890152] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.892453] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.894521] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.896891] PCI: CLS 0 bytes, default 64 [ 0.899607] Unpacking initramfs... [ 2.304378] debug: unmapping init [mem 0xffffa0ce3cc54000-0xffffa0ce3ffbffff] [ 2.308453] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.310842] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.314073] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x22983777dd9, max_idle_ns: 440795300422 ns [ 2.838279] Initialise system trusted keyrings [ 2.840288] Key type blacklist registered [ 2.842443] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.854666] zbud: loaded [ 2.858509] *** VALIDATE nfs *** [ 2.860081] *** VALIDATE nfs4 *** [ 2.861650] pstore: using deflate compression [ 2.865876] Platform Keyring initialized [ 2.973869] NET: Registered protocol family 38 [ 2.975835] Key type asymmetric registered [ 2.977552] Asymmetric key parser 'x509' registered [ 2.979844] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 2.983348] io scheduler mq-deadline registered [ 2.985462] io scheduler kyber registered [ 2.987393] io scheduler bfq registered [ 2.989460] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 2.992665] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 2.996108] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 2.999531] ACPI: Power Button [PWRF] [ 3.005194] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 3.012690] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 3.028129] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 3.034722] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 3.047284] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 3.076192] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.105718] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.109583] Non-volatile memory driver v1.3 [ 3.111160] Linux agpgart interface v0.103 [ 3.149426] virtio_blk virtio1: [vda] 150648 512-byte logical blocks (77.1 MB/73.6 MiB) [ 3.152701] vda: detected capacity change from 0 to 77131776 [ 3.169943] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.173417] vdb: detected capacity change from 0 to 1073741824 [ 3.189844] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.193356] vdc: detected capacity change from 0 to 2621440000 [ 3.209722] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.213139] vdd: detected capacity change from 0 to 2621440000 [ 3.228864] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.232355] vde: detected capacity change from 0 to 4294967296 [ 3.248524] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.251045] vdf: detected capacity change from 0 to 4294967296 [ 3.256877] libphy: Fixed MDIO Bus: probed [ 3.265229] usbcore: registered new interface driver usbserial_generic [ 3.268076] usbserial: USB Serial support registered for generic [ 3.270394] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.274706] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.276587] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.279089] mousedev: PS/2 mouse device common for all mice [ 3.282690] rtc_cmos 00:05: RTC can wake from S4 [ 3.284294] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.286350] rtc_cmos 00:05: registered as rtc0 [ 3.290644] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.293349] intel_pstate: CPU model not supported [ 3.296356] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.296805] hid: raw HID events driver (C) Jiri Kosina [ 3.303630] usbcore: registered new interface driver usbhid [ 3.305373] usbhid: USB HID core driver [ 3.306814] drop_monitor: Initializing network drop monitor service [ 3.310791] Initializing XFRM netlink socket [ 3.313737] NET: Registered protocol family 10 [ 3.316888] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.317726] Segment Routing with IPv6 [ 3.326162] NET: Registered protocol family 17 [ 3.331073] mpls_gso: MPLS GSO support [ 3.340342] RAS: Correctable Errors collector initialized. [ 3.342822] AVX version of gcm_enc/dec engaged. [ 3.344761] AES CTR mode by8 optimization enabled [ 3.527264] sched_clock: Marking stable (3527195393, 0)->(4490351967, -963156574) [ 3.535515] registered taskstats version 1 [ 3.548091] Loading compiled-in X.509 certificates [ 3.550380] zswap: loaded using pool lzo/zbud [ 3.610631] Key type big_key registered [ 3.634445] Key type encrypted registered [ 3.636327] ima: No TPM chip found, activating TPM-bypass! [ 3.638751] ima: Allocated hash algorithm: sha1 [ 3.644737] ima: No architecture policies found [ 3.646336] evm: Initialising EVM extended attributes: [ 3.651541] evm: security.selinux [ 3.653199] evm: security.ima [ 3.654417] evm: security.capability [ 3.656730] evm: HMAC attrs: 0x1 [ 3.662309] rtc_cmos 00:05: setting system clock to 2026-09-30 01:57:50 UTC (1790733470) [ 3.676874] debug: unmapping init [mem 0xffffffff88003000-0xffffffff881fffff] [ 3.686829] debug: unmapping init [mem 0xffffffff86d82000-0xffffffff87058fff] [ 3.691208] Write protecting the kernel read-only data: 28672k [ 3.699875] debug: unmapping init [mem 0xffffffff85403000-0xffffffff855fffff] [ 3.710897] debug: unmapping init [mem 0xffffffff85d14000-0xffffffff85dfffff] [ 3.818279] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 3.833503] systemd[1]: Detected virtualization kvm. [ 3.845338] systemd[1]: Detected architecture x86-64. [ 3.848585] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.891977] systemd[1]: No hostname configured. [ 3.894879] systemd[1]: Set hostname to . [ 3.898822] random: systemd: uninitialized urandom read (16 bytes read) [ 3.901918] systemd[1]: Initializing machine ID from random generator. [ 4.044982] random: ln: uninitialized urandom read (6 bytes read) [ 4.204993] random: systemd: uninitialized urandom read (16 bytes read) [ 4.208467] systemd[1]: Reached target Timers. [ OK ] Reached target Timers. [ 4.216368] systemd[1]: Reached target Slices. [ OK ] Reached target Slices. [ 4.228104] systemd[1]: Started Dispatch Password Requests to Console Directory Watch. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Listening on Journal Socket (/dev/log). [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Swap. [ OK ] Reached target Local File Systems. [ OK ] Reached target Paths. [ OK ] Listening on udev Kernel Socket. [ OK ] Listening on Journal Socket. Starting Create Volatile Files and Directories... Starting Setup Virtual Console... [ OK ] Started Memstrack Anylazing Service. Starting Create list of required st…ce nodes for the current kernel... Starting Journal Service... [ OK ] Reached target Initrd Root Device. [ OK ] Listening on udev Control Socket. [ OK ] Reached target Sockets. Starting Apply Kernel Variables... [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Setup Virtual Console. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Apply Kernel Variables. Starting Create Static Device Nodes in /dev... Starting dracut cmdline hook... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started Journal Service. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 5.682714] device-mapper: uevent: version 1.0.3 [ 5.685181] 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... [ 7.466308] virtio_net virtio0 ens2: renamed from eth0 [ 7.593361] random: fast init done [ 7.662921] scsi host0: ata_piix [ 7.685167] scsi host1: ata_piix [ 7.688015] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 7.691615] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 12.180616] random: crng init done [ 12.184553] random: 7 urandom warning(s) missed due to ratelimiting [ 13.989893] dracut-initqueue[593]: 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... [ 15.191893] 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 Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Slices. [ OK ] Stopped target Paths. [ OK ] Stopped target Sockets. [ OK ] Stopped target System Initialization. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. Stopping udev Kernel Device Manager... [ OK ] Stopped target Local File Systems. [ OK ] Stopped target Swap. [ 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... [ 17.423238] printk: systemd: 26 output lines suppressed due to ratelimiting [ 18.015665] SELinux: Disabled at runtime. [ 18.110567] 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) [ 18.119824] systemd[1]: Detected virtualization kvm. [ 18.123439] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 19.324882] systemd[1]: initrd-switch-root.service: Succeeded. [ 19.329644] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 19.335975] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 19.342903] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 19.349573] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 19.368387] systemd[1]: Starting Journal Service... Starting Journal Service... [ 19.378760] systemd[1]: Stopped target Switch Root. [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd File Systems. [ OK ] Created slice system-sshd\x2dkeygen.slice. [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Created slice User and Session Slice. [ OK ] Listening on udev Control Socket. [ OK ] Created slice system-getty.slice. [ OK ] Reached target rpc_pipefs.target. [ OK ] Listening on Process Core Dump Socket. Starting Remount Root and Kernel File Systems... [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Reached target RPC Port Mapper. [ OK ] Started Dispatch Password Requests to Console Directory Watch. Mounting POSIX Message Queue File System... [ OK ] Reached target Slices. Starting Create list of required st…ce nodes for the current kernel... Mounting Kernel Debug File System... [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Reached target Local Encrypted Volumes. Mounting Huge Pages File System... Activating swap /dev/disk/by-label/SWAP... [ OK ] Listening on udev Kernel Socket. Starting udev Coldplug all Devices... [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Reached target Paths. [ OK ] Stopped target Initrd Root File System. Starting Apply Kernel Variables... [ 19.691921] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS [ OK ] Started Journal Service. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Mounted Kernel Debug File System. [ OK ] Mounted Huge Pages File System. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Started Apply Kernel Variables. [ OK ] Reached target Swap. Starting Create Static Device Nodes in /dev... Starting Configure read-only root support... Starting Flush Journal to Persistent Storage... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started udev Coldplug all Devices. [ OK ] Reached target Local File Systems (Pre). Mounting /home/green/git/lustre-release... Mounting /mnt... Starting udev Kernel Device Manager... [ OK ] Mounted /mnt. [ 20.663783] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 21.573170] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 21.704485] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 22.252544] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 22.292145] EDAC sbridge: Ver: 1.1.2 [ 26.095391] Key type dns_resolver registered [* ] A start job is running for Configur…-only root support (7s / no limit)[ 26.772052] NFS: Registering the id_resolver key type [ 26.776794] Key type id_resolver registered [ 26.780873] Key type id_legacy registered [** ] 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) [ OK ] Started Configure read-only root support. Starting Load/Save Random Seed... [ OK ] Reached target Local File Systems. Starting Rebuild Dynamic Linker Cache... Starting Mark the need to relabel after reboot... Starting Create Volatile Files and Directories... [ OK ] Started Load/Save Random Seed. [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Create Volatile Files and Directories. Starting RPC Bind... Starting Update UTMP about System Boot/Shutdown... [ OK ] Started RPC Bind. [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Reached target Basic System. [ OK ] Started irqbalance daemon. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Started D-Bus System Message Bus. Starting Network Manager... Starting Restore /run/initramfs on shutdown... Starting Login Service... [ OK ] Started dnf makecache --timer. [ OK ] Reached target Timers. [ OK ] Reached target sshd-keygen.target. [ 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... Starting Hostname Service... [ OK ] Started OpenSSH server daemon. [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... [ OK ] Started Permit User Sessions. [ OK ] Started Getty on tty1. [ OK ] Started Serial Getty on ttyS1. [ OK ] Started Serial Getty on ttyS0. [ OK ] Reached target Login Prompts. [ OK ] Started Command Scheduler. [ OK ] Started Login Service. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting Crash recovery kernel arming... Starting Notify NFS peers of a restart... Starting System Logging Service... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Starting Authorization Manager... Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg359-server login: [ 64.150452] spl: loading out-of-tree module taints kernel. [ 67.346776] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 77.689190] Key type ._llcrypt registered [ 77.691603] Key type .llcrypt registered [ 77.785695] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_hostid [ 94.125618] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing load_modules_local [ 95.331723] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 95.344381] alg: No test for adler32 (adler32-zlib) [ 96.846640] Lustre: Lustre: Build Version: 2.17.59_3_g4e55f3f [ 97.735685] LNet: Added LNI 192.168.203.159@tcp [8/256/0/180] [ 99.512189] Key type lgssc registered [ 101.412691] Lustre: Echo OBD driver; http://www.lustre.org/ [ 111.228256] vdc: vdc1 vdc9 [ 120.345190] vde: vde1 vde9 [ 129.640977] vdf: vdf1 vdf9 [ 129.656990] vdf: vdf1 vdf9 [ 146.214312] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing load_modules_local [ 154.902567] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' or install '{/usr}/sbin/mount.lustre_tgt' [ 156.154986] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 156.410577] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 156.493332] Lustre: lustre-MDT0000: new disk, initializing [ 156.824622] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 156.894491] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 160.901716] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 165.029767] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 170.709943] Lustre: lustre-OST0000: new disk, initializing [ 170.718222] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 170.726438] Lustre: Skipped 1 previous similar message [ 170.849524] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 172.304631] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:0:ost [ 172.309779] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:0:ost] [ 172.412142] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x240000400 [ 177.022350] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 186.714186] Lustre: lustre-OST0001: new disk, initializing [ 186.718738] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 186.823623] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 192.546560] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 193.145340] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:1:ost [ 193.151855] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:1:ost] [ 193.296639] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x280000400 [ 203.136604] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 209.428325] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 215.153655] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing check_logdir /tmp/testlogs/ [ 219.858201] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing yml_node [ 223.302099] Lustre: DEBUG MARKER: Client: 2.17.59.3 [ 223.744006] hrtimer: interrupt took 3871554 ns [ 225.694194] Lustre: DEBUG MARKER: MDS: 2.17.59.3 [ 227.941278] Lustre: DEBUG MARKER: OSS: 2.17.59.3 [ 229.378098] Lustre: DEBUG MARKER: -----============= acceptance-small: replay-single ============----- Tue Sep 29 22:01:33 EDT 2026 [ 244.840427] Lustre: DEBUG MARKER: only running tests: 0-99 [ 246.419724] Lustre: DEBUG MARKER: excepting tests: 59 36 [ 248.444690] Lustre: DEBUG MARKER: === replay-single: start setup 22:01:52 (1790733712) === [ 253.602172] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing check_config_client /mnt/lustre [ 267.901428] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 271.109796] Lustre: 11369:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 274.491414] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 277.550431] Lustre: DEBUG MARKER: === replay-single: finish setup 22:02:21 (1790733741) === [ 278.895204] Lustre: DEBUG MARKER: == replay-single test 0a: empty replay =================== 22:02:23 (1790733743) [ 281.569968] LustreError: 11863:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 282.341957] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 284.146392] Lustre: Failing over lustre-MDT0000 [ 284.396988] Lustre: server umount lustre-MDT0000 complete [ 300.512311] Lustre: 3313:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790733751/real 1790733751] req@ffffa0ceb47bc000 x1877720237655680/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1790733767 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 300.512883] 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 [ 300.525839] Lustre: 3313:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 300.525971] LustreError: MGC192.168.203.159@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 300.557528] Lustre: Skipped 1 previous similar message [ 306.656183] Lustre: 3313:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790733757/real 1790733757] req@ffffa0cec1e64a80 x1877720237656064/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1790733773 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 306.692704] Lustre: 3313:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 310.763724] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xa21f4b807fa58024 [ 310.772957] Lustre: MGC192.168.203.159@tcp: Connection restored to 0@lo (at 0@lo) [ 311.167668] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 312.033177] Lustre: 3314:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790733762/real 1790733762] req@ffffa0ce906ea300 x1877720237656576/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1790733778 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 312.233694] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 312.394330] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 316.800296] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 325.352053] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 328.606749] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 330.881766] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 341.037577] Lustre: DEBUG MARKER: == replay-single test 0b: ensure object created after recover exists. (3284) ========================================================== 22:03:24 (1790733804) [ 342.943734] Lustre: Failing over lustre-OST0000 [ 343.004390] Lustre: lustre-OST0000: Not available for connect from 192.168.203.59@tcp (stopping) [ 343.031574] Lustre: server umount lustre-OST0000 complete [ 346.081767] 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 [ 351.219044] LustreError: 6691:0:(ldlm_lib.c:1199: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. [ 351.231868] LustreError: 6691:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 3 previous similar messages [ 353.201851] LustreError: 11797:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.203.59@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 356.321181] LustreError: 6690:0:(ldlm_lib.c:1199: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. [ 359.866853] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 361.259308] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 361.866691] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 361.866755] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 361.874980] Lustre: Skipped 1 previous similar message [ 365.291330] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 373.927929] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 375.406821] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 383.240212] Lustre: DEBUG MARKER: == replay-single test 0c: check replay-barrier =========== 22:04:07 (1790733847) [ 385.844987] LustreError: 14895:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 386.640304] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 388.573110] Lustre: Failing over lustre-MDT0000 [ 388.858588] Lustre: server umount lustre-MDT0000 complete [ 405.718385] LustreError: MGC192.168.203.159@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 405.976320] 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 [ 406.137656] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 407.073467] Lustre: 3311:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790733857/real 1790733857] req@ffffa0ce90761f80 x1877720237687424/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1790733873 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 407.088784] Lustre: 3311:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 409.645103] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 411.114945] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 411.218512] Lustre: 3312:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790733862/real 1790733862] req@ffffa0ce906e8000 x1877720237687808/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1790733878 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 411.252755] Lustre: 3312:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 411.511638] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 411.517083] Lustre: lustre-MDT0000: Denying connection for new client 7ea7f2ba-2784-4432-b1b0-19acd6b64de3 (at 192.168.203.59@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:59 [ 416.682502] Lustre: lustre-MDT0000: Denying connection for new client 7ea7f2ba-2784-4432-b1b0-19acd6b64de3 (at 192.168.203.59@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:54 [ 421.814534] Lustre: lustre-MDT0000: Denying connection for new client 7ea7f2ba-2784-4432-b1b0-19acd6b64de3 (at 192.168.203.59@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:49 [ 426.934911] Lustre: lustre-MDT0000: Denying connection for new client 7ea7f2ba-2784-4432-b1b0-19acd6b64de3 (at 192.168.203.59@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:44 [ 432.045533] Lustre: lustre-MDT0000: Denying connection for new client 7ea7f2ba-2784-4432-b1b0-19acd6b64de3 (at 192.168.203.59@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:39 [ 442.286727] Lustre: lustre-MDT0000: Denying connection for new client 7ea7f2ba-2784-4432-b1b0-19acd6b64de3 (at 192.168.203.59@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:29 [ 442.303584] Lustre: Skipped 1 previous similar message [ 462.765517] Lustre: lustre-MDT0000: Denying connection for new client 7ea7f2ba-2784-4432-b1b0-19acd6b64de3 (at 192.168.203.59@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:08 [ 462.782965] Lustre: Skipped 3 previous similar messages [ 471.500307] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 471.517642] Lustre: 15547:0:(genops.c:1600:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 679fa5df-ebbc-4294-bd8e-c0ce7f529942@ [ 471.552825] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 471.623746] Lustre: lustre-MDT0000: Recovery over after 1:00, of 1 clients 0 recovered and 1 was evicted. [ 471.694220] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:44 to 0x280000400:65) [ 471.695224] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:44 to 0x240000400:65) [ 482.548489] Lustre: DEBUG MARKER: == replay-single test 0d: expired recovery with no clients ========================================================== 22:05:46 (1790733946) [ 486.095694] LustreError: 16286:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 487.147335] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 489.244139] Lustre: Failing over lustre-MDT0000 [ 489.533493] Lustre: server umount lustre-MDT0000 complete [ 508.005887] LustreError: MGC192.168.203.159@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 508.247262] Lustre: 3314:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790733959/real 1790733959] req@ffffa0ceb4f50380 x1877720237712512/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1790733975 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 508.276794] Lustre: 3314:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 508.282978] 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 [ 508.304706] Lustre: Skipped 1 previous similar message [ 508.474694] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 513.109557] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 513.508777] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 513.517298] Lustre: Skipped 1 previous similar message [ 515.534327] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 515.549197] Lustre: lustre-MDT0000: Denying connection for new client a1582f77-8a80-46a1-972c-dcdc8a9170c9 (at 192.168.203.59@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:59 [ 515.568191] Lustre: Skipped 1 previous similar message [ 575.500334] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 575.509699] Lustre: 16928:0:(genops.c:1600:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 7ea7f2ba-2784-4432-b1b0-19acd6b64de3@ [ 575.525800] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 575.601319] Lustre: lustre-MDT0000: Recovery over after 1:00, of 1 clients 0 recovered and 1 was evicted. [ 575.663372] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:44 to 0x280000400:97) [ 575.666225] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:44 to 0x240000400:97) [ 586.406540] Lustre: DEBUG MARKER: == replay-single test 1: simple create =================== 22:07:29 (1790734049) [ 589.381687] LustreError: 17665:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 590.355608] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 592.461846] Lustre: Failing over lustre-MDT0000 [ 592.784141] Lustre: server umount lustre-MDT0000 complete [ 611.808279] Lustre: 3311:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790734062/real 1790734062] req@ffffa0cebadf8700 x1877720237735808/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1790734078 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 611.812361] LustreError: MGC192.168.203.159@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 611.852743] Lustre: 3311:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 6 previous similar messages [ 611.853864] 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 [ 611.853873] Lustre: Skipped 1 previous similar message [ 621.951891] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 622.002609] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 626.061119] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 633.772804] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 633.880733] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 633.955776] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:44 to 0x280000400:129) [ 633.957728] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:44 to 0x240000400:129) [ 636.402452] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 636.410513] Lustre: Skipped 1 previous similar message [ 640.237445] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 641.957933] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 650.172335] Lustre: DEBUG MARKER: == replay-single test 2a: touch ========================== 22:08:34 (1790734114) [ 653.287920] LustreError: 19267:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 654.170788] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 656.228982] Lustre: Failing over lustre-MDT0000 [ 656.486145] Lustre: server umount lustre-MDT0000 complete [ 673.186344] Lustre: 3312:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790734123/real 1790734123] req@ffffa0ceb4069180 x1877720237751552/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1790734139 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 673.225780] Lustre: 3312:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 7 previous similar messages [ 673.241914] 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 [ 673.262396] Lustre: Skipped 1 previous similar message [ 675.469242] LustreError: MGC192.168.203.159@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 676.007431] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 681.407747] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 684.066430] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 684.073418] Lustre: Skipped 1 previous similar message [ 685.485084] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 685.763423] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 685.839560] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:131 to 0x280000400:161) [ 685.840080] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:44 to 0x240000400:161) [ 692.107756] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 693.914779] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 703.113030] Lustre: DEBUG MARKER: == replay-single test 2b: touch ========================== 22:09:26 (1790734166) [ 706.601295] LustreError: 20851:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 707.668340] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 709.723919] Lustre: Failing over lustre-MDT0000 [ 710.129616] Lustre: server umount lustre-MDT0000 complete [ 729.250720] LustreError: MGC192.168.203.159@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 729.799206] 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 [ 729.815048] Lustre: Skipped 1 previous similar message [ 730.014084] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 730.021678] Lustre: Skipped 1 previous similar message [ 730.124745] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 734.816443] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 735.223373] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 735.233547] Lustre: Skipped 1 previous similar message [ 736.753422] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 736.923585] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 736.954570] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:131 to 0x280000400:193) [ 736.955447] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:163 to 0x240000400:193) [ 741.345063] Lustre: 3311:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790734191/real 1790734191] req@ffffa0ceba732a00 x1877720237769728/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1790734207 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 741.376380] Lustre: 3311:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 12 previous similar messages [ 746.588890] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 748.695932] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 759.442974] Lustre: DEBUG MARKER: == replay-single test 2c: setstripe replay =============== 22:10:23 (1790734223) [ 762.880044] LustreError: 22433:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 763.986572] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 766.416983] Lustre: Failing over lustre-MDT0000 [ 766.949160] Lustre: server umount lustre-MDT0000 complete [ 786.400191] 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 [ 786.400611] LustreError: MGC192.168.203.159@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 786.420524] Lustre: Skipped 2 previous similar messages [ 796.641391] LustreError: 3310:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffffa0ce85c5c000 x1877720237787520/t0(0) o250->MGC192.168.203.159@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 [ 797.318144] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 801.890917] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 808.372911] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 808.530793] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 808.596253] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:225) [ 808.601440] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:225) [ 811.362283] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 811.372721] Lustre: Skipped 1 previous similar message [ 814.839705] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 816.298918] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 824.254376] Lustre: DEBUG MARKER: == replay-single test 2d: setdirstripe replay ============ 22:11:28 (1790734288) [ 827.479467] LustreError: 24021:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 828.450501] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 830.381161] Lustre: Failing over lustre-MDT0000 [ 830.738612] Lustre: server umount lustre-MDT0000 complete [ 847.331323] LustreError: MGC192.168.203.159@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 858.163850] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 858.166085] Lustre: Skipped 1 previous similar message [ 858.266695] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 860.879789] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:257) [ 860.886321] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:257) [ 863.199607] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 872.519919] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 874.302185] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 882.635598] Lustre: DEBUG MARKER: == replay-single test 2e: O_CREAT|O_EXCL create replay === 22:12:26 (1790734346) [ 883.688221] Lustre: *** cfs_fail_loc=13b, val=315*** [ 883.697545] Lustre: *** cfs_fail_loc=13b, val=2147483648*** [ 883.701280] LustreError: 24627:0:(ldlm_lib.c:3382:target_send_reply_msg()) @@@ dropping reply req@ffffa0ce8ecf7480 x1877720219900032/t38654705666(0) o35->a1582f77-8a80-46a1-972c-dcdc8a9170c9@192.168.203.59@tcp:452/0 lens 392/456 e 0 to 0 dl 1790734367 ref 1 fl Interpret:/600/0 rc 0/0 job:'openfile.0' uid:0 gid:0 projid:0 [ 887.956739] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 889.594531] Lustre: Failing over lustre-MDT0000 [ 889.828289] Lustre: server umount lustre-MDT0000 complete [ 908.192226] Lustre: 3314:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790734359/real 1790734359] req@ffffa0ce85c5dc00 x1877720237817856/t0(0) o400->MGC192.168.203.159@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1790734375 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 908.195203] 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 [ 908.249343] Lustre: 3314:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 16 previous similar messages [ 908.308267] Lustre: Skipped 2 previous similar messages [ 918.498275] LustreError: 3310:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffffa0ce8ecf4000 x1877720237819392/t0(0) o250->MGC192.168.203.159@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 [ 919.248738] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 924.059410] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 930.665484] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 930.675569] Lustre: Skipped 1 previous similar message [ 930.737177] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 930.743292] Lustre: Skipped 1 previous similar message [ 930.753067] Lustre: 26255:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffffa0ce8ed8b800 x1877720219900032/t38654705666(0) o35->a1582f77-8a80-46a1-972c-dcdc8a9170c9@192.168.203.59@tcp:499/0 lens 392/456 e 0 to 0 dl 1790734414 ref 1 fl Interpret:/602/0 rc 0/0 job:'openfile.0' uid:0 gid:0 projid:0 [ 930.767361] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:289) [ 930.770060] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:289) [ 935.225721] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 936.732746] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 944.582155] Lustre: DEBUG MARKER: == replay-single test 3a: replay failed open(O_DIRECTORY) ========================================================== 22:13:28 (1790734408) [ 947.330879] LustreError: 27238:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 947.342107] LustreError: 27238:0:(osd_handler.c:720:osd_ro()) Skipped 1 previous similar message [ 948.185783] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 950.242163] Lustre: Failing over lustre-MDT0000 [ 950.621123] Lustre: server umount lustre-MDT0000 complete [ 969.891847] LustreError: MGC192.168.203.159@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 969.909352] LustreError: Skipped 1 previous similar message [ 970.695629] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 975.070827] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 977.962078] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:321) [ 977.967301] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:321) [ 979.621227] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 979.627280] Lustre: Skipped 5 previous similar messages [ 984.785776] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 986.583302] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 994.439145] Lustre: DEBUG MARKER: == replay-single test 3b: replay failed open -ENOMEM ===== 22:14:18 (1790734458) [ 998.315860] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 999.331716] Lustre: *** cfs_fail_loc=114, val=0*** [ 1002.391235] Lustre: Failing over lustre-MDT0000 [ 1002.714058] Lustre: server umount lustre-MDT0000 complete [ 1021.473576] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1026.062366] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1029.171296] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:353) [ 1029.172661] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:353) [ 1034.871155] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1036.344475] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1045.034730] Lustre: DEBUG MARKER: == replay-single test 3c: replay failed open -ENOMEM ===== 22:15:08 (1790734508) [ 1049.492592] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1050.440699] Lustre: *** cfs_fail_loc=128, val=0*** [ 1053.217145] Lustre: Failing over lustre-MDT0000 [ 1053.651065] Lustre: server umount lustre-MDT0000 complete [ 1073.635583] 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 [ 1073.652991] Lustre: Skipped 5 previous similar messages [ 1083.876468] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xa21f4b807fa5b6b1 [ 1089.572628] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1096.617828] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1096.641487] Lustre: Skipped 2 previous similar messages [ 1096.744940] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1096.757178] Lustre: Skipped 2 previous similar messages [ 1096.796096] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:385) [ 1096.796473] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:385) [ 1102.898800] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1104.610318] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1112.024284] Lustre: DEBUG MARKER: == replay-single test 4a: |x| 10 open(O_CREAT)s ========== 22:16:16 (1790734576) [ 1114.714379] LustreError: 32175:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 1114.724178] LustreError: 32175:0:(osd_handler.c:720:osd_ro()) Skipped 2 previous similar messages [ 1115.594681] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1118.108528] Lustre: Failing over lustre-MDT0000 [ 1118.546266] Lustre: server umount lustre-MDT0000 complete [ 1135.584234] LustreError: MGC192.168.203.159@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1135.599234] LustreError: Skipped 2 previous similar messages [ 1145.827797] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xa21f4b807fa5bcca [ 1146.300925] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1146.305149] Lustre: Skipped 4 previous similar messages [ 1146.360574] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1146.374428] Lustre: Skipped 1 previous similar message [ 1149.229564] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:391 to 0x240000400:417) [ 1149.229840] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:391 to 0x280000400:417) [ 1151.496300] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1161.557598] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1163.301326] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1171.687562] Lustre: DEBUG MARKER: == replay-single test 4b: |x| rm 10 files ================ 22:17:15 (1790734635) [ 1175.294896] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1177.237892] Lustre: Failing over lustre-MDT0000 [ 1177.504246] Lustre: server umount lustre-MDT0000 complete [ 1196.704793] Lustre: 3312:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790734647/real 1790734648] req@ffffa0ceba9cce00 x1877720237897984/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1790734663 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1196.741680] Lustre: 3312:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 39 previous similar messages [ 1200.908907] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1205.414795] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:423 to 0x280000400:449) [ 1205.415563] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:423 to 0x240000400:449) [ 1211.008750] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1212.503105] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1220.804936] Lustre: DEBUG MARKER: == replay-single test 5: |x| 220 open(O_CREAT) =========== 22:18:04 (1790734684) [ 1224.548415] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1232.634136] Lustre: Failing over lustre-MDT0000 [ 1232.936449] Lustre: server umount lustre-MDT0000 complete [ 1256.353313] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:577) [ 1256.353963] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:577) [ 1256.539174] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1257.462665] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 1257.466965] Lustre: Skipped 11 previous similar messages [ 1265.676370] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1267.075874] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1289.231906] Lustre: DEBUG MARKER: == replay-single test 6a: mkdir + contained create ======= 22:19:13 (1790734753) [ 1292.886325] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1294.743722] Lustre: Failing over lustre-MDT0000 [ 1295.180308] Lustre: server umount lustre-MDT0000 complete [ 1313.675448] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1313.693266] Lustre: Skipped 2 previous similar messages [ 1314.443763] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:609) [ 1314.448313] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:609) [ 1317.995888] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1327.413262] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1329.077669] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1339.631278] Lustre: DEBUG MARKER: == replay-single test 6b: |X| rmdir ====================== 22:20:03 (1790734803) [ 1343.668991] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1345.781504] Lustre: Failing over lustre-MDT0000 [ 1346.155834] Lustre: server umount lustre-MDT0000 complete [ 1364.641770] 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 [ 1364.655086] Lustre: Skipped 9 previous similar messages [ 1365.440411] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1365.461612] Lustre: Skipped 4 previous similar messages [ 1365.669277] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1365.683815] Lustre: Skipped 4 previous similar messages [ 1365.747612] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:641) [ 1365.747762] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:641) [ 1369.449252] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1378.177771] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1379.541196] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1385.981633] Lustre: DEBUG MARKER: == replay-single test 7: mkdir |X| contained create ====== 22:20:50 (1790734850) [ 1388.527588] LustreError: 40158:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 1388.533660] LustreError: 40158:0:(osd_handler.c:720:osd_ro()) Skipped 4 previous similar messages [ 1389.277835] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1391.214850] Lustre: Failing over lustre-MDT0000 [ 1391.558734] Lustre: server umount lustre-MDT0000 complete [ 1411.707903] LustreError: MGC192.168.203.159@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1411.720440] LustreError: Skipped 4 previous similar messages [ 1412.059432] Lustre: lustre-MDT0000: Not available for connect from 0@lo (not set up) [ 1412.072454] Lustre: Skipped 1 previous similar message [ 1412.769844] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:673) [ 1412.773533] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:673) [ 1417.045274] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1425.977199] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1427.503847] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1435.764521] Lustre: DEBUG MARKER: == replay-single test 8: creat open |X| close ============ 22:21:39 (1790734899) [ 1439.638396] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1441.654220] Lustre: Failing over lustre-MDT0000 [ 1441.937890] Lustre: server umount lustre-MDT0000 complete [ 1474.484759] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1484.427736] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:705) [ 1484.433095] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:705) [ 1489.244426] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1490.781313] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1498.431514] Lustre: DEBUG MARKER: == replay-single test 9: |X| create (same inum/gen) ====== 22:22:42 (1790734962) [ 1501.550605] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1503.060544] Lustre: Failing over lustre-MDT0000 [ 1503.264626] Lustre: server umount lustre-MDT0000 complete [ 1520.612750] LustreError: 43925:0:(ldlm_lib.c:1199: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. [ 1520.626623] LustreError: 43925:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 1 previous similar message [ 1522.313224] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:737) [ 1522.314487] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:737) [ 1525.711342] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1534.757337] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1536.216330] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1543.849534] Lustre: DEBUG MARKER: == replay-single test 10: create |X| rename unlink ======= 22:23:27 (1790735007) [ 1547.535868] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1549.306845] Lustre: Failing over lustre-MDT0000 [ 1549.622394] Lustre: server umount lustre-MDT0000 complete [ 1569.639823] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:769) [ 1569.647719] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:769) [ 1572.551888] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1580.916875] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1582.212450] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1590.346925] Lustre: DEBUG MARKER: == replay-single test 11: create open write rename |X| create-old-name read ========================================================== 22:24:14 (1790735054) [ 1595.189208] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1597.417754] Lustre: Failing over lustre-MDT0000 [ 1597.830670] Lustre: server umount lustre-MDT0000 complete [ 1615.291616] LustreError: 47093:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.203.59@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1615.321841] LustreError: 47093:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 1 previous similar message [ 1615.662337] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1615.667937] Lustre: Skipped 5 previous similar messages [ 1617.059278] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:771 to 0x240000400:801) [ 1617.060524] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:771 to 0x280000400:801) [ 1619.108276] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1627.886652] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1629.988971] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1639.251877] Lustre: DEBUG MARKER: == replay-single test 12: open, unlink |X| close ========= 22:25:03 (1790735103) [ 1643.270193] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1645.324219] Lustre: Failing over lustre-MDT0000 [ 1645.591201] Lustre: server umount lustre-MDT0000 complete [ 1664.347215] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1664.353848] Lustre: Skipped 9 previous similar messages [ 1669.158379] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1672.876103] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:771 to 0x280000400:833) [ 1672.884766] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:771 to 0x240000400:833) [ 1678.490551] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1679.825820] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1687.269251] Lustre: DEBUG MARKER: == replay-single test 13: open chmod 0 |x| write close === 22:25:51 (1790735151) [ 1691.181103] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1693.032594] Lustre: Failing over lustre-MDT0000 [ 1693.127146] Lustre: lustre-MDT0000: Not available for connect from 192.168.203.59@tcp (stopping) [ 1693.332454] Lustre: server umount lustre-MDT0000 complete [ 1712.225495] Lustre: 3313:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790735162/real 1790735162] req@ffffa0ce85c5fb80 x1877720238115200/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1790735178 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1712.255992] Lustre: 3313:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 66 previous similar messages [ 1713.765183] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:835 to 0x280000400:865) [ 1713.765410] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:771 to 0x240000400:865) [ 1716.032851] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1725.426934] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1726.756317] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1734.841628] Lustre: DEBUG MARKER: == replay-single test 14: open(O_CREAT), unlink |X| close ========================================================== 22:26:38 (1790735198) [ 1738.739155] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1740.607404] Lustre: Failing over lustre-MDT0000 [ 1740.922065] Lustre: server umount lustre-MDT0000 complete [ 1758.123746] LustreError: 51856:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.203.59@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1760.274607] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:867 to 0x280000400:897) [ 1760.275059] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:771 to 0x240000400:897) [ 1762.940203] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1773.037278] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1774.589507] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1783.299518] Lustre: DEBUG MARKER: == replay-single test 15: open(O_CREAT), unlink |X| touch new, close ========================================================== 22:27:27 (1790735247) [ 1787.046970] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1788.691378] Lustre: Failing over lustre-MDT0000 [ 1788.846759] Lustre: lustre-MDT0000: Not available for connect from 192.168.203.59@tcp (stopping) [ 1788.971808] Lustre: server umount lustre-MDT0000 complete [ 1816.037264] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xa21f4b807fa69212 [ 1816.056932] Lustre: MGC192.168.203.159@tcp: Connection restored to 0@lo (at 0@lo) [ 1816.063771] Lustre: Skipped 21 previous similar messages [ 1820.758240] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1828.947391] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:899 to 0x240000400:929) [ 1828.948291] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:899 to 0x280000400:929) [ 1833.980917] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1835.501421] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1843.468854] Lustre: DEBUG MARKER: == replay-single test 16: |X| open(O_CREAT), unlink, touch new, unlink new ========================================================== 22:28:27 (1790735307) [ 1847.287235] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1849.436027] Lustre: Failing over lustre-MDT0000 [ 1849.855494] Lustre: server umount lustre-MDT0000 complete [ 1877.984737] LustreError: 3310:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffffa0cec145ed80 x1877720238164096/t0(0) o250->MGC192.168.203.159@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 0 ref 1 fl Rpc:NQU/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1879.978164] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1879.984801] Lustre: Skipped 9 previous similar messages [ 1880.204761] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1880.217850] Lustre: Skipped 9 previous similar messages [ 1880.273779] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:899 to 0x280000400:961) [ 1880.274315] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:931 to 0x240000400:961) [ 1883.213854] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1893.891599] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1895.508947] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1904.086517] Lustre: DEBUG MARKER: == replay-single test 17: |X| open(O_CREAT), |replay| close ========================================================== 22:29:28 (1790735368) [ 1906.805242] LustreError: 56025:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 1906.814757] LustreError: 56025:0:(osd_handler.c:720:osd_ro()) Skipped 9 previous similar messages [ 1907.627485] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1909.516772] Lustre: Failing over lustre-MDT0000 [ 1909.927891] Lustre: server umount lustre-MDT0000 complete [ 1927.568695] LustreError: MGC192.168.203.159@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1927.575399] LustreError: Skipped 9 previous similar messages [ 1927.870921] 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 [ 1927.879910] Lustre: Skipped 21 previous similar messages [ 1932.442074] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1937.580384] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:963 to 0x240000400:993) [ 1937.583226] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:899 to 0x280000400:993) [ 1943.307594] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1945.068433] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1953.613730] Lustre: DEBUG MARKER: == replay-single test 18: open(O_CREAT), unlink, touch new, close, touch, unlink ========================================================== 22:30:17 (1790735417) [ 1957.330467] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1959.250720] Lustre: Failing over lustre-MDT0000 [ 1959.642172] Lustre: server umount lustre-MDT0000 complete [ 1981.259114] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:995 to 0x240000400:1025) [ 1981.261881] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:995 to 0x280000400:1025) [ 1984.367045] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1994.083291] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1995.745740] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2003.882995] Lustre: DEBUG MARKER: == replay-single test 19: mcreate, open, write, rename === 22:31:07 (1790735467) [ 2007.527937] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2009.527366] Lustre: Failing over lustre-MDT0000 [ 2009.873667] Lustre: server umount lustre-MDT0000 complete [ 2035.692202] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xa21f4b807fa6a719 [ 2042.103484] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2051.242583] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1027 to 0x280000400:1057) [ 2051.253710] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1027 to 0x240000400:1057) [ 2057.504841] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2059.408122] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2068.411931] Lustre: DEBUG MARKER: == replay-single test 20a: |X| open(O_CREAT), unlink, replay, close (test mds_cleanup_orphans) ========================================================== 22:32:12 (1790735532) [ 2072.007242] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2073.888989] Lustre: Failing over lustre-MDT0000 [ 2074.218591] Lustre: server umount lustre-MDT0000 complete [ 2103.937235] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1027 to 0x280000400:1089) [ 2103.941228] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1059 to 0x240000400:1089) [ 2106.662936] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2115.591743] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2117.055661] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2125.749636] Lustre: DEBUG MARKER: == replay-single test 20b: write, unlink, eviction, replay (test mds_cleanup_orphans) ========================================================== 22:33:09 (1790735589) [ 2130.561922] Lustre: 62413:0:(genops.c:1773:obd_export_evict_by_uuid()) lustre-MDT0000: evicting a1582f77-8a80-46a1-972c-dcdc8a9170c9 at adminstrative request [ 2136.428922] Lustre: Failing over lustre-MDT0000 [ 2136.655903] Lustre: server umount lustre-MDT0000 complete [ 2162.337251] LustreError: 3310:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffffa0ceaab9f480 x1877720238243968/t0(0) o250->MGC192.168.203.159@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 [ 2162.944843] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 2162.955538] Lustre: Skipped 9 previous similar messages [ 2163.752173] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1027 to 0x280000400:1121) [ 2163.757209] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1091 to 0x240000400:1121) [ 2166.977321] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2176.676852] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2178.270606] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2183.477670] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 2197.931408] Lustre: DEBUG MARKER: before 4096, after 4096 [ 2205.109889] Lustre: DEBUG MARKER: == replay-single test 20c: check that client eviction does not affect file content ========================================================== 22:34:28 (1790735668) [ 2206.211495] Lustre: 64495:0:(genops.c:1773:obd_export_evict_by_uuid()) lustre-MDT0000: evicting a1582f77-8a80-46a1-972c-dcdc8a9170c9 at adminstrative request [ 2216.136940] Lustre: DEBUG MARKER: == replay-single test 21: |X| open(O_CREAT), unlink touch new, replay, close (test mds_cleanup_orphans) ========================================================== 22:34:40 (1790735680) [ 2220.396665] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2222.512861] Lustre: Failing over lustre-MDT0000 [ 2222.965677] Lustre: server umount lustre-MDT0000 complete [ 2249.697059] LustreError: 3310:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffffa0cebba35f80 x1877720238264832/t0(0) o250->MGC192.168.203.159@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 [ 2251.039101] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1124 to 0x240000400:1153) [ 2251.048504] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1123 to 0x280000400:1153) [ 2255.172808] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2264.943770] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2266.612471] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2275.635390] Lustre: DEBUG MARKER: == replay-single test 22: open(O_CREAT), |X| unlink, replay, close (test mds_cleanup_orphans) ========================================================== 22:35:39 (1790735739) [ 2280.159862] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2281.964886] Lustre: Failing over lustre-MDT0000 [ 2282.299473] Lustre: server umount lustre-MDT0000 complete [ 2310.624620] LustreError: 3310:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffffa0ceb4cab800 x1877720238281344/t0(0) o250->MGC192.168.203.159@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 [ 2311.234847] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 2311.238829] Lustre: Skipped 10 previous similar messages [ 2312.333486] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1155 to 0x280000400:1185) [ 2312.335770] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1155 to 0x240000400:1185) [ 2316.192986] Lustre: 3311:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790735767/real 1790735767] req@ffffa0cec145c700 x1877720238280960/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1790735783 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2316.223231] Lustre: 3311:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 83 previous similar messages [ 2316.617172] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2327.083980] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2328.582597] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2337.346369] Lustre: DEBUG MARKER: == replay-single test 23: open(O_CREAT), |X| unlink touch new, replay, close (test mds_cleanup_orphans) ========================================================== 22:36:41 (1790735801) [ 2341.364903] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2343.695369] Lustre: Failing over lustre-MDT0000 [ 2344.186652] Lustre: server umount lustre-MDT0000 complete [ 2374.852949] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1187 to 0x280000400:1217) [ 2374.853461] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1187 to 0x240000400:1217) [ 2375.967708] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2384.465737] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2385.844129] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2393.461366] Lustre: DEBUG MARKER: == replay-single test 24: open(O_CREAT), replay, unlink, close (test mds_cleanup_orphans) ========================================================== 22:37:37 (1790735857) [ 2396.739954] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2398.421812] Lustre: Failing over lustre-MDT0000 [ 2398.665928] Lustre: server umount lustre-MDT0000 complete [ 2416.562433] LustreError: 70197:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.203.59@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 2417.832419] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1219 to 0x240000400:1249) [ 2417.832532] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1219 to 0x280000400:1249) [ 2421.115964] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2422.252732] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 2422.266262] Lustre: Skipped 21 previous similar messages [ 2430.350462] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2431.632985] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2439.626434] Lustre: DEBUG MARKER: == replay-single test 25: open(O_CREAT), unlink, replay, close (test mds_cleanup_orphans) ========================================================== 22:38:23 (1790735903) [ 2443.296633] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2444.938773] Lustre: Failing over lustre-MDT0000 [ 2445.250364] Lustre: server umount lustre-MDT0000 complete [ 2462.645663] LustreError: 71779:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.203.59@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 2464.555173] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1251 to 0x240000400:1281) [ 2464.560308] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1219 to 0x280000400:1281) [ 2468.183396] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2477.368967] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2478.929520] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2487.339453] Lustre: DEBUG MARKER: == replay-single test 26: |X| open(O_CREAT), unlink two, close one, replay, close one (test mds_cleanup_orphans) ========================================================== 22:39:11 (1790735951) [ 2491.103625] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2492.948290] Lustre: Failing over lustre-MDT0000 [ 2493.293249] Lustre: server umount lustre-MDT0000 complete [ 2524.609982] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2534.314151] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 2534.330780] Lustre: Skipped 10 previous similar messages [ 2534.535049] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 2534.544163] Lustre: Skipped 10 previous similar messages [ 2534.579724] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1283 to 0x280000400:1313) [ 2534.585477] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1283 to 0x240000400:1313) [ 2540.073287] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2541.598215] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2549.388878] Lustre: DEBUG MARKER: == replay-single test 27: |X| open(O_CREAT), unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 22:40:13 (1790736013) [ 2552.225116] LustreError: 74361:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 2552.230748] LustreError: 74361:0:(osd_handler.c:720:osd_ro()) Skipped 9 previous similar messages [ 2553.129539] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2555.242275] Lustre: Failing over lustre-MDT0000 [ 2555.649236] Lustre: server umount lustre-MDT0000 complete [ 2573.069570] LustreError: MGC192.168.203.159@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2573.078890] LustreError: Skipped 10 previous similar messages [ 2573.410316] 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 [ 2573.432115] Lustre: Skipped 21 previous similar messages [ 2575.563508] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1315 to 0x280000400:1345) [ 2575.567426] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1315 to 0x240000400:1345) [ 2578.099837] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2586.728317] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2587.879518] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2594.948619] Lustre: DEBUG MARKER: == replay-single test 28: open(O_CREAT), |X| unlink two, close one, replay, close one (test mds_cleanup_orphans) ========================================================== 22:40:59 (1790736059) [ 2598.684616] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2600.461247] Lustre: Failing over lustre-MDT0000 [ 2600.735452] Lustre: server umount lustre-MDT0000 complete [ 2623.230117] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2627.710801] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1347 to 0x280000400:1377) [ 2627.714487] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1347 to 0x240000400:1377) [ 2632.900140] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2634.397764] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2641.839819] Lustre: DEBUG MARKER: == replay-single test 29: open(O_CREAT), |X| unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 22:41:45 (1790736105) [ 2646.463348] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2648.039532] Lustre: Failing over lustre-MDT0000 [ 2648.215192] Lustre: server umount lustre-MDT0000 complete [ 2675.895376] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xa21f4b807fa6de94 [ 2679.027175] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1379 to 0x240000400:1409) [ 2679.027677] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1379 to 0x280000400:1409) [ 2681.710226] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2691.656453] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2693.056589] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2701.049449] Lustre: DEBUG MARKER: == replay-single test 30: open(O_CREAT) two, unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 22:42:44 (1790736164) [ 2704.960710] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2706.788775] Lustre: Failing over lustre-MDT0000 [ 2706.964801] Lustre: server umount lustre-MDT0000 complete [ 2730.277428] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2735.206144] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1411 to 0x280000400:1441) [ 2735.206333] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1411 to 0x240000400:1441) [ 2741.057482] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2742.582985] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2751.129794] Lustre: DEBUG MARKER: == replay-single test 31: open(O_CREAT) two, unlink one, |X| unlink one, close two (test mds_cleanup_orphans) ========================================================== 22:43:35 (1790736215) [ 2755.226920] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2757.184139] Lustre: Failing over lustre-MDT0000 [ 2757.486391] Lustre: server umount lustre-MDT0000 complete [ 2776.759377] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 2776.775842] Lustre: Skipped 10 previous similar messages [ 2777.267520] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1443 to 0x280000400:1473) [ 2777.268035] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1443 to 0x240000400:1473) [ 2781.576788] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2791.265492] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2792.818993] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2801.484633] Lustre: DEBUG MARKER: == replay-single test 32: close() notices client eviction; close() after client eviction ========================================================== 22:44:25 (1790736265) [ 2802.648276] Lustre: 82198:0:(genops.c:1773:obd_export_evict_by_uuid()) lustre-MDT0000: evicting a1582f77-8a80-46a1-972c-dcdc8a9170c9 at adminstrative request [ 2812.639064] Lustre: DEBUG MARKER: == replay-single test 33a: fid seq shouldn't be reused after abort recovery ========================================================== 22:44:36 (1790736276) [ 2815.536102] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2817.337957] Lustre: Failing over lustre-MDT0000 [ 2817.643860] Lustre: server umount lustre-MDT0000 complete [ 2826.206333] Lustre: lustre-MDT0000: Aborting client recovery [ 2826.212420] LustreError: 83112:0:(ldlm_lib.c:3038:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 2826.230363] Lustre: 83157:0:(ldlm_lib.c:2438:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 2826.240528] Lustre: 83157:0:(genops.c:1600:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client a1582f77-8a80-46a1-972c-dcdc8a9170c9@ [ 2826.251409] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 2826.321601] Lustre: lustre-MDT0000-osd: cancel update llog [0x200000400:0x1:0x0] [ 2826.444417] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1479 to 0x240000400:1505) [ 2826.464397] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1480 to 0x280000400:1505) [ 2831.321601] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2845.302676] Lustre: DEBUG MARKER: == replay-single test 33b: test fid seq allocation ======= 22:45:09 (1790736309) [ 2849.355060] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2851.467750] Lustre: Failing over lustre-MDT0000 [ 2851.739250] Lustre: server umount lustre-MDT0000 complete [ 2861.194697] Lustre: *** cfs_fail_loc=1311, val=0*** [ 2861.234617] Lustre: lustre-MDT0000: Aborting client recovery [ 2861.239635] LustreError: 84477:0:(ldlm_lib.c:3038:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 2861.249464] Lustre: 84524:0:(ldlm_lib.c:2438:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 2861.258284] Lustre: 84524:0:(ldlm_lib.c:2438:target_recovery_overseer()) Skipped 2 previous similar messages [ 2861.265597] Lustre: 84524:0:(genops.c:1600:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client a1582f77-8a80-46a1-972c-dcdc8a9170c9@ [ 2861.286131] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 2861.341311] Lustre: lustre-MDT0000-osd: cancel update llog [0x200015bc0:0x1:0x0] [ 2861.468711] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1516 to 0x280000400:1537) [ 2861.472072] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1516 to 0x240000400:1537) [ 2866.494521] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2872.296466] Lustre: *** cfs_fail_loc=1311, val=0*** [ 2879.560429] Lustre: DEBUG MARKER: == replay-single test 34: abort recovery before client does replay (test mds_cleanup_orphans) ========================================================== 22:45:43 (1790736343) [ 2883.808843] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2885.681650] Lustre: Failing over lustre-MDT0000 [ 2885.896341] Lustre: server umount lustre-MDT0000 complete [ 2894.378449] Lustre: lustre-MDT0000: Aborting client recovery [ 2894.381156] LustreError: 85856:0:(ldlm_lib.c:3038:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 2894.386396] Lustre: 85902:0:(ldlm_lib.c:2438:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 2894.391660] Lustre: 85902:0:(ldlm_lib.c:2438:target_recovery_overseer()) Skipped 2 previous similar messages [ 2894.396725] Lustre: 85902:0:(genops.c:1600:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client a1582f77-8a80-46a1-972c-dcdc8a9170c9@ [ 2894.405185] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 2894.438385] Lustre: lustre-MDT0000-osd: cancel update llog [0x200016778:0x1:0x0] [ 2894.566364] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1543 to 0x280000400:1569) [ 2894.585930] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1544 to 0x240000400:1569) [ 2899.489705] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2912.095953] Lustre: DEBUG MARKER: == replay-single test 35: test recovery from llog for unlink op ========================================================== 22:46:16 (1790736376) [ 2913.357552] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 2913.365804] LustreError: 85867:0:(ldlm_lib.c:3382:target_send_reply_msg()) @@@ dropping reply req@ffffa0ce86b2ca80 x1877720220876800/t201863462916(0) o36->a1582f77-8a80-46a1-972c-dcdc8a9170c9@192.168.203.59@tcp:211/0 lens 512/456 e 0 to 0 dl 1790736391 ref 1 fl Interpret:/200/0 rc 0/0 job:'rm.0' uid:0 gid:0 projid:4294967295 [ 2917.209687] Lustre: Failing over lustre-MDT0000 [ 2917.559755] Lustre: server umount lustre-MDT0000 complete [ 2926.854157] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 2926.858673] Lustre: Skipped 12 previous similar messages [ 2926.952303] Lustre: lustre-MDT0000: Aborting client recovery [ 2926.955195] LustreError: 87081:0:(ldlm_lib.c:3038:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 2926.961506] Lustre: 87129:0:(ldlm_lib.c:2438:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 2926.967305] Lustre: 87129:0:(ldlm_lib.c:2438:target_recovery_overseer()) Skipped 2 previous similar messages [ 2926.973712] Lustre: 87129:0:(genops.c:1600:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client a1582f77-8a80-46a1-972c-dcdc8a9170c9@ [ 2926.984724] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 2927.050948] Lustre: lustre-MDT0000-osd: cancel update llog [0x200017330:0x1:0x0] [ 2927.220650] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1543 to 0x280000400:1601) [ 2927.227721] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1571 to 0x240000400:1601) [ 2931.790523] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2935.264158] Lustre: 3312:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790736386/real 1790736386] req@ffffa0ceb5ae2a00 x1877720238495872/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1790736402 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2935.317884] Lustre: 3312:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 79 previous similar messages [ 2944.565422] Lustre: DEBUG MARKER: SKIP: replay-single test_36 skipping ALWAYS excluded test 36 [ 2946.405736] Lustre: DEBUG MARKER: == replay-single test 37: abort recovery before client does replay (test mds_cleanup_orphans for directories) ========================================================== 22:46:50 (1790736410) [ 2950.534859] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2953.835797] Lustre: Failing over lustre-MDT0000 [ 2954.167260] Lustre: server umount lustre-MDT0000 complete [ 2963.113387] Lustre: lustre-MDT0000: Aborting client recovery [ 2963.115698] LustreError: 88549:0:(ldlm_lib.c:3038:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 2963.139073] Lustre: 88595:0:(ldlm_lib.c:2438:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 2963.151894] Lustre: 88595:0:(ldlm_lib.c:2438:target_recovery_overseer()) Skipped 2 previous similar messages [ 2963.159916] Lustre: 88595:0:(genops.c:1600:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client a1582f77-8a80-46a1-972c-dcdc8a9170c9@ [ 2963.180590] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 2963.235252] Lustre: lustre-MDT0000-osd: cancel update llog [0x200017b00:0x1:0x0] [ 2963.494227] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1571 to 0x240000400:1633) [ 2963.496539] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1543 to 0x280000400:1633) [ 2968.371164] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2980.760579] Lustre: DEBUG MARKER: == replay-single test 38: test recovery from unlink llog (test llog_gen_rec) ========================================================== 22:47:24 (1790736444) [ 3010.980552] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3013.017396] Lustre: Failing over lustre-MDT0000 [ 3013.271266] Lustre: server umount lustre-MDT0000 complete [ 3043.364147] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2034 to 0x240000400:2049) [ 3043.368131] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2034 to 0x280000400:2049) [ 3044.130526] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3053.770210] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3054.306737] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 3054.315824] Lustre: Skipped 26 previous similar messages [ 3055.266215] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3074.762517] Lustre: DEBUG MARKER: == replay-single test 39: test recovery from unlink llog (test llog_gen_rec) ========================================================== 22:48:59 (1790736539) [ 3097.862068] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3107.952673] Lustre: Failing over lustre-MDT0000 [ 3108.231568] Lustre: server umount lustre-MDT0000 complete [ 3140.608367] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3150.770080] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 3150.776642] Lustre: Skipped 6 previous similar messages [ 3154.460700] Lustre: lustre-MDT0000: Recovery over after 0:04, of 1 clients 1 recovered and 0 were evicted. [ 3154.471942] Lustre: Skipped 6 previous similar messages [ 3154.553666] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2450 to 0x240000400:2465) [ 3154.555139] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2450 to 0x280000400:2465) [ 3160.972771] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3162.490399] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3183.219591] Lustre: DEBUG MARKER: == replay-single test 41: read from a valid osc while other oscs are invalid ========================================================== 22:50:47 (1790736647) [ 3185.231860] Lustre: setting import lustre-OST0001_UUID INACTIVE by administrator request [ 3186.248534] Lustre: lustre-OST0001-osc-MDT0000: Connection to lustre-OST0001 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 3186.265773] Lustre: Skipped 22 previous similar messages [ 3186.273847] Lustre: lustre-OST0001: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnecting [ 3186.284623] LustreError: lustre-OST0001-osc-MDT0000: This client was evicted by lustre-OST0001; in progress operations using this service will fail. [ 3193.359341] Lustre: DEBUG MARKER: == replay-single test 42: recovery after ost failure ===== 22:50:56 (1790736656) [ 3216.418108] LustreError: 94068:0:(osd_handler.c:720:osd_ro()) lustre-OST0000: *** setting device osd-zfs read-only *** [ 3216.424580] LustreError: 94068:0:(osd_handler.c:720:osd_ro()) Skipped 10 previous similar messages [ 3217.364988] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 3231.124797] Lustre: Failing over lustre-OST0000 [ 3231.712746] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 3231.726485] Lustre: lustre-OST0000: Not available for connect from 0@lo (stopping) [ 3232.737886] Lustre: lustre-OST0000: Not available for connect from 192.168.203.59@tcp (stopping) [ 3233.242765] Lustre: server umount lustre-OST0000 complete [ 3233.261109] LustreError: 36638:0:(ldlm_lib.c:1199: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. [ 3237.804773] LustreError: 36637:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.203.59@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3242.928411] LustreError: 36645:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.203.59@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3242.963077] LustreError: 36645:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 1 previous similar message [ 3248.043172] LustreError: 36639:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.203.59@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3248.075991] LustreError: 36639:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 1 previous similar message [ 3258.518075] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3317.653506] Lustre: DEBUG MARKER: == replay-single test 43: mds osc import failure during recovery; don't LBUG ========================================================== 22:53:01 (1790736781) [ 3321.364993] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3323.658365] Lustre: Failing over lustre-MDT0000 [ 3323.903119] Lustre: server umount lustre-MDT0000 complete [ 3342.008925] LustreError: MGC192.168.203.159@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3342.017080] LustreError: Skipped 11 previous similar messages [ 3347.082139] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3351.591773] Lustre: *** cfs_fail_loc=204, val=2147483648*** [ 3351.595252] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2866 to 0x280000400:2881) [ 3357.285034] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3359.087765] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3367.910913] LustreError: 96583:0:(osp_precreate.c:974:osp_precreate_cleanup_orphans()) lustre-OST0000-osc-MDT0000: cannot cleanup orphans: rc = -11 [ 3367.923912] Lustre: lustre-OST0000: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnecting [ 3368.929887] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2867 to 0x240000400:2913) [ 3376.482757] Lustre: DEBUG MARKER: == replay-single test 44a: race in target handle connect ========================================================== 22:54:00 (1790736840) [ 3380.945063] LustreError: 96561:0:(ldlm_lib.c:1185:target_handle_connect()) cfs_race id 701 sleeping [ 3386.336431] LustreError: 96561:0:(ldlm_lib.c:1185:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 3386.347614] Lustre: lustre-MDT0000: Client a1582f77-8a80-46a1-972c-dcdc8a9170c9 (at 192.168.203.59@tcp) reconnecting [ 3386.409423] LustreError: 6690:0:(ldlm_lib.c:1185:target_handle_connect()) cfs_fail_race id 701 waking [ 3388.739324] LustreError: 96561:0:(ldlm_lib.c:1185:target_handle_connect()) cfs_race id 701 sleeping [ 3394.016117] LustreError: 96561:0:(ldlm_lib.c:1185:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 3394.027175] Lustre: lustre-MDT0000: Client a1582f77-8a80-46a1-972c-dcdc8a9170c9 (at 192.168.203.59@tcp) reconnecting [ 3395.902855] LustreError: 96562:0:(ldlm_lib.c:1185:target_handle_connect()) cfs_race id 701 sleeping [ 3401.184166] LustreError: 96562:0:(ldlm_lib.c:1185:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 3401.192282] Lustre: lustre-MDT0000: Client a1582f77-8a80-46a1-972c-dcdc8a9170c9 (at 192.168.203.59@tcp) reconnecting [ 3402.913458] LustreError: 97210:0:(ldlm_lib.c:1185:target_handle_connect()) cfs_race id 701 sleeping [ 3408.352488] LustreError: 97210:0:(ldlm_lib.c:1185:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 3410.771614] LustreError: 96562:0:(ldlm_lib.c:1185:target_handle_connect()) cfs_race id 701 sleeping [ 3416.036400] LustreError: 96562:0:(ldlm_lib.c:1185:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 3416.046990] Lustre: lustre-MDT0000: Client a1582f77-8a80-46a1-972c-dcdc8a9170c9 (at 192.168.203.59@tcp) reconnecting [ 3416.067020] Lustre: Skipped 1 previous similar message [ 3425.030786] LustreError: 96559:0:(ldlm_lib.c:1185:target_handle_connect()) cfs_race id 701 sleeping [ 3425.045745] LustreError: 96559:0:(ldlm_lib.c:1185:target_handle_connect()) Skipped 1 previous similar message [ 3430.368297] LustreError: 96559:0:(ldlm_lib.c:1185:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 3430.392418] LustreError: 96559:0:(ldlm_lib.c:1185:target_handle_connect()) Skipped 1 previous similar message [ 3438.048756] Lustre: lustre-MDT0000: Client a1582f77-8a80-46a1-972c-dcdc8a9170c9 (at 192.168.203.59@tcp) reconnecting [ 3438.060332] Lustre: Skipped 2 previous similar messages [ 3446.962628] LustreError: 96561:0:(ldlm_lib.c:1185:target_handle_connect()) cfs_race id 701 sleeping [ 3446.969545] LustreError: 96561:0:(ldlm_lib.c:1185:target_handle_connect()) Skipped 2 previous similar messages [ 3452.386396] LustreError: 96561:0:(ldlm_lib.c:1185:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 3452.394050] LustreError: 96561:0:(ldlm_lib.c:1185:target_handle_connect()) Skipped 2 previous similar messages [ 3461.282641] Lustre: DEBUG MARKER: == replay-single test 44b: race in target handle connect ========================================================== 22:55:25 (1790736925) [ 3463.187794] LustreError: 96561:0:(ldlm_lib.c:1443:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 3473.328457] Lustre: lustre-MDT0000: Export ffffa0ceb4051000 already connecting from 192.168.203.59@tcp [ 3476.334994] Lustre: lustre-MDT0000: Export ffffa0ceb4051000 already connecting from 192.168.203.59@tcp [ 3478.383515] Lustre: lustre-MDT0000: Export ffffa0ceb4051000 already connecting from 192.168.203.59@tcp [ 3483.562341] Lustre: lustre-MDT0000: Export ffffa0ceb4051000 already connecting from 192.168.203.59@tcp [ 3488.682331] Lustre: lustre-MDT0000: Export ffffa0ceb4051000 already connecting from 192.168.203.59@tcp [ 3488.690984] Lustre: Skipped 1 previous similar message [ 3498.921609] Lustre: lustre-MDT0000: Export ffffa0ceb4051000 already connecting from 192.168.203.59@tcp [ 3498.933783] Lustre: Skipped 1 previous similar message [ 3503.192148] LustreError: 96561:0:(ldlm_lib.c:1443:target_handle_connect()) cfs_fail_timeout id 704 awake [ 3503.206853] Lustre: 96561:0:(service.c:2605:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/20s); client may timeout req@ffffa0ce861da300 x1877720223518848/t0(0) o38->a1582f77-8a80-46a1-972c-dcdc8a9170c9@192.168.203.59@tcp:0/0 lens 520/416 e 0 to 0 dl 1790736950 ref 1 fl Complete:H/200/0 rc 0/0 job:'lctl.0' uid:0 gid:0 projid:4294967295 [ 3504.047402] Lustre: lustre-MDT0000: Client a1582f77-8a80-46a1-972c-dcdc8a9170c9 (at 192.168.203.59@tcp) reconnecting [ 3504.064943] Lustre: Skipped 3 previous similar messages [ 3504.074864] LustreError: 97210:0:(ldlm_lib.c:1443:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 3528.621685] Lustre: lustre-MDT0000: Export ffffa0ceb4051000 already connecting from 192.168.203.59@tcp [ 3544.152119] LustreError: 97210:0:(ldlm_lib.c:1443:target_handle_connect()) cfs_fail_timeout id 704 awake [ 3544.163418] Lustre: 97210:0:(service.c:2605:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/21s); client may timeout req@ffffa0ce883c8a80 x1877720223522176/t0(0) o38->a1582f77-8a80-46a1-972c-dcdc8a9170c9@192.168.203.59@tcp:0/0 lens 520/416 e 0 to 0 dl 1790736990 ref 1 fl Complete:H/200/0 rc 0/0 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3549.098284] LustreError: 97670:0:(ldlm_lib.c:1443:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 3573.673953] Lustre: lustre-MDT0000: Export ffffa0ceb4051000 already connecting from 192.168.203.59@tcp [ 3573.690639] Lustre: Skipped 4 previous similar messages [ 3589.112898] LustreError: 97670:0:(ldlm_lib.c:1443:target_handle_connect()) cfs_fail_timeout id 704 awake [ 3589.124241] Lustre: 97670:0:(service.c:2605:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/20s); client may timeout req@ffffa0ce84446d80 x1877720223524352/t0(0) o38->a1582f77-8a80-46a1-972c-dcdc8a9170c9@192.168.203.59@tcp:0/0 lens 520/416 e 0 to 0 dl 1790737035 ref 1 fl Complete:H/200/0 rc 0/0 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3594.154547] Lustre: lustre-MDT0000: Client a1582f77-8a80-46a1-972c-dcdc8a9170c9 (at 192.168.203.59@tcp) reconnecting [ 3594.160140] Lustre: Skipped 1 previous similar message [ 3594.169697] LustreError: 97210:0:(ldlm_lib.c:1443:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 3634.192206] LustreError: 97210:0:(ldlm_lib.c:1443:target_handle_connect()) cfs_fail_timeout id 704 awake [ 3634.208324] Lustre: 97210:0:(service.c:2605:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/21s); client may timeout req@ffffa0ceb406ad80 x1877720223526528/t0(0) o38->a1582f77-8a80-46a1-972c-dcdc8a9170c9@192.168.203.59@tcp:0/0 lens 520/416 e 0 to 0 dl 1790737080 ref 1 fl Complete:H/200/0 rc 0/0 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3639.211325] LustreError: 99463:0:(ldlm_lib.c:1443:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 3663.788542] Lustre: lustre-MDT0000: Export ffffa0ceb4051000 already connecting from 192.168.203.59@tcp [ 3663.797526] Lustre: Skipped 9 previous similar messages [ 3679.264312] LustreError: 99463:0:(ldlm_lib.c:1443:target_handle_connect()) cfs_fail_timeout id 704 awake [ 3679.273530] Lustre: 99463:0:(service.c:2605:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/20s); client may timeout req@ffffa0ceb4f51880 x1877720223528704/t0(0) o38->a1582f77-8a80-46a1-972c-dcdc8a9170c9@192.168.203.59@tcp:0/0 lens 520/416 e 0 to 0 dl 1790737126 ref 1 fl Complete:H/200/0 rc 0/0 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3684.278153] LustreError: 99463:0:(ldlm_lib.c:1443:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 3687.839287] LustreError: 99463:0:(ldlm_lib.c:1443:target_handle_connect()) cfs_fail_timeout interrupted [ 3692.323484] Lustre: DEBUG MARKER: == replay-single test 44c: race in target handle connect ========================================================== 22:59:16 (1790737156) [ 3696.132883] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3700.302164] Lustre: Failing over lustre-MDT0000 [ 3700.518696] Lustre: server umount lustre-MDT0000 complete [ 3709.457273] Lustre: *** cfs_fail_loc=712, val=0*** [ 3709.467550] LustreError: 6690:0:(service.c:1412:ptlrpc_check_req()) @@@ Invalid replay without recovery req@ffffa0cebaf7dc00 x1877720239084160/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 [ 3709.683368] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3709.691901] Lustre: Skipped 5 previous similar messages [ 3709.789559] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 3709.795153] Lustre: lustre-MDT0000: Aborting client recovery [ 3709.797115] Lustre: Skipped 19 previous similar messages [ 3709.808663] LustreError: 101084:0:(ldlm_lib.c:3038:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 3709.814568] Lustre: 101133:0:(ldlm_lib.c:2438:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 3709.820385] Lustre: 101133:0:(ldlm_lib.c:2438:target_recovery_overseer()) Skipped 2 previous similar messages [ 3709.829261] Lustre: 101133:0:(genops.c:1600:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client a1582f77-8a80-46a1-972c-dcdc8a9170c9@ [ 3709.842883] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 3709.876238] Lustre: lustre-MDT0000: Denying connection for new client a1582f77-8a80-46a1-972c-dcdc8a9170c9 (at 192.168.203.59@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 1 evicted) already passed deadline 61:49 [ 3709.895885] Lustre: Skipped 11 previous similar messages [ 3709.940482] Lustre: lustre-MDT0000-osd: cancel update llog [0x2000182d0:0x1:0x0] [ 3710.048785] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2866 to 0x280000400:2913) [ 3710.048933] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2867 to 0x240000400:2945) [ 3714.194355] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3715.045819] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 3715.057042] Lustre: Skipped 8 previous similar messages [ 3721.031804] Lustre: Failing over lustre-MDT0000 [ 3721.432698] Lustre: server umount lustre-MDT0000 complete [ 3740.600677] Lustre: lustre-MDT0000: Not available for connect from 192.168.203.59@tcp (not set up) [ 3741.728136] Lustre: 3312:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790737192/real 1790737192] req@ffffa0cec1c40380 x1877720239093632/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1790737208 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3741.789971] Lustre: 3312:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 26 previous similar messages [ 3742.052267] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2867 to 0x240000400:2977) [ 3742.058058] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2866 to 0x280000400:2945) [ 3745.411217] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3755.890868] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3757.472819] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3765.515625] Lustre: DEBUG MARKER: == replay-single test 45: Handle failed close ============ 23:00:29 (1790737229) [ 3765.755261] Lustre: lustre-MDT0000: Client a1582f77-8a80-46a1-972c-dcdc8a9170c9 (at 192.168.203.59@tcp) reconnecting [ 3765.759946] Lustre: Skipped 2 previous similar messages [ 3773.388788] Lustre: DEBUG MARKER: == replay-single test 46: Don't leak file handle after open resend (3325) ========================================================== 23:00:37 (1790737237) [ 3774.401274] Lustre: *** cfs_fail_loc=122, val=2147483648*** [ 3774.423712] LustreError: 102049:0:(ldlm_lib.c:3382:target_send_reply_msg()) @@@ dropping reply req@ffffa0cebfaac700 x1877720223586304/t0(0) o700->a1582f77-8a80-46a1-972c-dcdc8a9170c9@192.168.203.59@tcp:317/0 lens 264/248 e 0 to 0 dl 1790737252 ref 1 fl Interpret:/200/0 rc 0/0 job:'touch.0' uid:0 gid:0 projid:4294967295 [ 3793.052549] Lustre: Failing over lustre-MDT0000 [ 3793.452316] Lustre: server umount lustre-MDT0000 complete [ 3812.104409] 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 [ 3812.119781] Lustre: Skipped 8 previous similar messages [ 3817.127892] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3821.490176] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 3821.494871] Lustre: Skipped 3 previous similar messages [ 3821.566109] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 3821.575929] Lustre: Skipped 3 previous similar messages [ 3821.615250] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2947 to 0x280000400:2977) [ 3821.617566] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2979 to 0x240000400:3009) [ 3826.861793] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3828.667326] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3838.765903] Lustre: DEBUG MARKER: == replay-single test 47: MDS->OSC failure during precreate cleanup (2824) ========================================================== 23:01:42 (1790737302) [ 3840.797502] Lustre: Failing over lustre-OST0000 [ 3840.868316] Lustre: server umount lustre-OST0000 complete [ 3841.990838] LustreError: 14875:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.203.59@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3842.016828] LustreError: 14875:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 1 previous similar message [ 3842.531106] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 3852.202064] LustreError: 36648:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.203.59@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3852.219176] LustreError: 36648:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 4 previous similar messages [ 3864.012452] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3873.457139] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 3875.165908] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 3946.667785] Lustre: DEBUG MARKER: == replay-single test 48: MDS->OSC failure during precreate cleanup (2824) ========================================================== 23:03:30 (1790737410) [ 3949.313937] LustreError: 106249:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 3949.322961] LustreError: 106249:0:(osd_handler.c:720:osd_ro()) Skipped 2 previous similar messages [ 3950.156389] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3952.318071] Lustre: Failing over lustre-MDT0000 [ 3952.712409] Lustre: server umount lustre-MDT0000 complete [ 3970.817837] LustreError: MGC192.168.203.159@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3970.827185] LustreError: Skipped 3 previous similar messages [ 3971.032379] Lustre: lustre-MDT0000: Not available for connect from 192.168.203.59@tcp (not set up) [ 3971.040345] Lustre: Skipped 2 previous similar messages [ 3973.583512] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2998 to 0x280000400:3041) [ 3973.587260] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3030 to 0x240000400:3073) [ 3975.042849] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4040.233453] Lustre: *** cfs_fail_loc=216, val=0*** [ 4047.068712] Lustre: DEBUG MARKER: == replay-single test 50: Double OSC recovery, don't LASSERT (3812) ========================================================== 23:05:11 (1790737511) [ 4048.462636] Lustre: lustre-OST0000: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnecting [ 4048.469460] Lustre: Skipped 2 previous similar messages [ 4061.193276] Lustre: DEBUG MARKER: == replay-single test 52: time out lock replay (3764) ==== 23:05:24 (1790737524) [ 4064.602331] Lustre: Failing over lustre-MDT0000 [ 4065.101432] Lustre: server umount lustre-MDT0000 complete [ 4099.371626] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4108.234215] Lustre: *** cfs_fail_loc=157, val=2147483648*** [ 4108.245163] LustreError: 108525:0:(ldlm_lib.c:3382:target_send_reply_msg()) @@@ dropping reply req@ffffa0ceaa8ef480 x1877720223709184/t0(0) o101->a1582f77-8a80-46a1-972c-dcdc8a9170c9@192.168.203.59@tcp:651/0 lens 328/344 e 0 to 0 dl 1790737586 ref 1 fl Complete:/240/0 rc 0/0 job:'ldlm_lock_repla.0' uid:0 gid:0 projid:4294967295 [ 4124.586635] Lustre: lustre-MDT0000: Client a1582f77-8a80-46a1-972c-dcdc8a9170c9 (at 192.168.203.59@tcp) reconnected, waiting for 1 clients in recovery for 1:23 [ 4124.715051] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3052 to 0x280000400:3073) [ 4124.720836] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3085 to 0x240000400:3105) [ 4131.109470] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4132.596494] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4141.740773] Lustre: DEBUG MARKER: == replay-single test 53a: |X| close request while two MDC requests in flight ========================================================== 23:06:45 (1790737605) [ 4143.801729] Lustre: *** cfs_fail_loc=115, val=2147483648*** [ 4148.677290] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4150.549671] Lustre: Failing over lustre-MDT0000 [ 4150.902084] Lustre: server umount lustre-MDT0000 complete [ 4177.889499] LustreError: 3310:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffffa0cec1c40a80 x1877720239209984/t0(0) o250->MGC192.168.203.159@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 [ 4182.974354] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4185.088123] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3085 to 0x240000400:3137) [ 4185.096320] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3075 to 0x280000400:3105) [ 4192.200922] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4193.547906] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4201.620240] Lustre: DEBUG MARKER: == replay-single test 53b: |X| open request while two MDC requests in flight ========================================================== 23:07:45 (1790737665) [ 4202.656808] Lustre: *** cfs_fail_loc=107, val=2147483648*** [ 4207.662723] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4209.455754] Lustre: Failing over lustre-MDT0000 [ 4209.764987] Lustre: server umount lustre-MDT0000 complete [ 4228.578346] LustreError: 111950:0:(ldlm_lib.c:1199: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. [ 4228.592096] LustreError: 111950:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 2 previous similar messages [ 4229.233807] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3075 to 0x280000400:3137) [ 4229.236029] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3139 to 0x240000400:3169) [ 4233.822658] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4243.016577] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4244.594571] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4252.282936] Lustre: DEBUG MARKER: == replay-single test 53c: |X| open request and close request while two MDC requests in flight ========================================================== 23:08:36 (1790737716) [ 4253.230336] Lustre: *** cfs_fail_loc=107, val=2147483648*** [ 4258.211893] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4259.932952] Lustre: Failing over lustre-MDT0000 [ 4260.219770] Lustre: server umount lustre-MDT0000 complete [ 4278.798769] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3139 to 0x240000400:3201) [ 4278.801287] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3139 to 0x280000400:3169) [ 4282.244205] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4293.463705] Lustre: DEBUG MARKER: == replay-single test 53d: close reply while two MDC requests in flight ========================================================== 23:09:17 (1790737757) [ 4295.676759] Lustre: *** cfs_fail_loc=13b, val=315*** [ 4295.694860] Lustre: *** cfs_fail_loc=13b, val=2147483648*** [ 4295.697247] LustreError: 113633:0:(ldlm_lib.c:3382:target_send_reply_msg()) @@@ dropping reply req@ffffa0cebaebad80 x1877720223758848/t257698037777(0) o35->a1582f77-8a80-46a1-972c-dcdc8a9170c9@192.168.203.59@tcp:83/0 lens 392/456 e 0 to 0 dl 1790737773 ref 1 fl Interpret:/600/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 4298.320208] Lustre: Failing over lustre-MDT0000 [ 4298.690674] Lustre: server umount lustre-MDT0000 complete [ 4317.840970] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4317.849880] Lustre: Skipped 8 previous similar messages [ 4317.961894] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4317.980780] Lustre: Skipped 10 previous similar messages [ 4321.714778] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4322.717164] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3203 to 0x240000400:3233) [ 4322.720537] Lustre: 114923:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffffa0ceb4f50a80 x1877720223758848/t257698037777(0) o35->a1582f77-8a80-46a1-972c-dcdc8a9170c9@192.168.203.59@tcp:110/0 lens 392/456 e 0 to 0 dl 1790737800 ref 1 fl Interpret:/602/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 4322.720898] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3139 to 0x280000400:3201) [ 4324.842400] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 4324.851334] Lustre: Skipped 18 previous similar messages [ 4332.725969] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4334.782501] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4344.237530] Lustre: DEBUG MARKER: == replay-single test 53e: |X| open reply while two MDC requests in flight ========================================================== 23:10:07 (1790737807) [ 4345.649734] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 4345.651851] LustreError: 114921:0:(ldlm_lib.c:3382:target_send_reply_msg()) @@@ dropping reply req@ffffa0ceb406b100 x1877720223772672/t261993005072(0) o36->a1582f77-8a80-46a1-972c-dcdc8a9170c9@192.168.203.59@tcp:133/0 lens 504/448 e 0 to 0 dl 1790737823 ref 1 fl Interpret:/200/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 4351.961753] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4354.268103] Lustre: Failing over lustre-MDT0000 [ 4354.490829] Lustre: server umount lustre-MDT0000 complete [ 4371.872465] Lustre: 3311:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790737822/real 1790737822] req@ffffa0ce88e69500 x1877720239270912/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1790737838 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4371.906852] Lustre: 3311:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 60 previous similar messages [ 4382.176820] LustreError: 3310:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffffa0ce84444380 x1877720239272832/t0(0) o250->MGC192.168.203.159@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 [ 4386.751775] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4386.766553] Lustre: 116612:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffffa0ce84447100 x1877720223772672/t261993005072(0) o36->a1582f77-8a80-46a1-972c-dcdc8a9170c9@192.168.203.59@tcp:174/0 lens 504/2880 e 0 to 0 dl 1790737864 ref 1 fl Interpret:/202/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 4386.794644] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3203 to 0x280000400:3233) [ 4386.796246] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3203 to 0x240000400:3265) [ 4396.069366] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4397.475434] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4405.458931] Lustre: DEBUG MARKER: == replay-single test 53f: |X| open reply and close reply while two MDC requests in flight ========================================================== 23:11:09 (1790737869) [ 4406.433205] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 4406.441063] LustreError: 116610:0:(ldlm_lib.c:3382:target_send_reply_msg()) @@@ dropping reply req@ffffa0cebb525180 x1877720223787904/t266287972368(0) o36->a1582f77-8a80-46a1-972c-dcdc8a9170c9@192.168.203.59@tcp:194/0 lens 504/448 e 0 to 0 dl 1790737884 ref 1 fl Interpret:/200/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 4408.227295] Lustre: *** cfs_fail_loc=13b, val=315*** [ 4411.621240] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4413.366571] Lustre: Failing over lustre-MDT0000 [ 4413.410384] 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 [ 4413.415941] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4413.424546] Lustre: Skipped 19 previous similar messages [ 4413.682931] Lustre: server umount lustre-MDT0000 complete [ 4431.785958] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4431.801638] Lustre: Skipped 8 previous similar messages [ 4431.912379] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4431.926419] Lustre: Skipped 8 previous similar messages [ 4431.957330] Lustre: 118301:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffffa0ceb4068380 x1877720223788672/t266287972369(0) o35->a1582f77-8a80-46a1-972c-dcdc8a9170c9@192.168.203.59@tcp:219/0 lens 392/456 e 0 to 0 dl 1790737909 ref 1 fl Interpret:/602/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 4431.975427] Lustre: 118301:0:(mdt_recovery.c:102:mdt_req_from_lrd()) Skipped 1 previous similar message [ 4431.977349] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3203 to 0x280000400:3265) [ 4431.977701] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3267 to 0x240000400:3297) [ 4435.146799] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4445.451604] Lustre: DEBUG MARKER: == replay-single test 53g: |X| drop open reply and close request while close and open are both in flight ========================================================== 23:11:49 (1790737909) [ 4446.234229] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 4446.237559] Lustre: Skipped 1 previous similar message [ 4446.239907] LustreError: 118300:0:(ldlm_lib.c:3382:target_send_reply_msg()) @@@ dropping reply req@ffffa0ce85820380 x1877720223800704/t270582939664(0) o36->a1582f77-8a80-46a1-972c-dcdc8a9170c9@192.168.203.59@tcp:234/0 lens 504/448 e 0 to 0 dl 1790737924 ref 1 fl Interpret:/200/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 4446.265354] LustreError: 118300:0:(ldlm_lib.c:3382:target_send_reply_msg()) Skipped 1 previous similar message [ 4447.983127] Lustre: *** cfs_fail_loc=115, val=2147483648*** [ 4447.985971] Lustre: Skipped 1 previous similar message [ 4452.088223] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4453.690646] Lustre: Failing over lustre-MDT0000 [ 4453.857370] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4453.862302] Lustre: Skipped 1 previous similar message [ 4453.957421] Lustre: server umount lustre-MDT0000 complete [ 4473.136524] Lustre: 119840:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffffa0cd820dc700 x1877720223800704/t270582939664(0) o36->a1582f77-8a80-46a1-972c-dcdc8a9170c9@192.168.203.59@tcp:260/0 lens 504/2880 e 0 to 0 dl 1790737950 ref 1 fl Interpret:/202/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 4473.137712] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3267 to 0x240000400:3329) [ 4473.138840] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3267 to 0x280000400:3297) [ 4476.099952] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4486.792851] Lustre: DEBUG MARKER: == replay-single test 53h: open request and close reply while two MDC requests in flight ========================================================== 23:12:30 (1790737950) [ 4487.761187] Lustre: *** cfs_fail_loc=107, val=2147483648*** [ 4489.580334] Lustre: *** cfs_fail_loc=13b, val=315*** [ 4489.588595] Lustre: *** cfs_fail_loc=13b, val=2147483648*** [ 4489.596739] LustreError: 119844:0:(ldlm_lib.c:3382:target_send_reply_msg()) @@@ dropping reply req@ffffa0ce883cb480 x1877720223812992/t274877906960(0) o35->a1582f77-8a80-46a1-972c-dcdc8a9170c9@192.168.203.59@tcp:277/0 lens 392/456 e 0 to 0 dl 1790737967 ref 1 fl Interpret:/600/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 4494.037338] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4495.768500] Lustre: Failing over lustre-MDT0000 [ 4496.084408] Lustre: server umount lustre-MDT0000 complete [ 4514.543861] Lustre: lustre-MDT0000: Not available for connect from 192.168.203.59@tcp (not set up) [ 4514.554162] Lustre: Skipped 1 previous similar message [ 4518.727246] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3267 to 0x280000400:3329) [ 4518.728113] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3331 to 0x240000400:3361) [ 4518.742797] Lustre: 121284:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffffa0ce8ee78700 x1877720223812992/t274877906960(0) o35->a1582f77-8a80-46a1-972c-dcdc8a9170c9@192.168.203.59@tcp:306/0 lens 392/456 e 0 to 0 dl 1790737996 ref 1 fl Interpret:/602/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 4519.124438] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4530.308348] Lustre: DEBUG MARKER: == replay-single test 55: let MDS_CHECK_RESENT return the original return code instead of 0 ========================================================== 23:13:14 (1790737994) [ 4531.324077] Lustre: *** cfs_fail_loc=12b, val=2147483991*** [ 4531.334107] LustreError: 121281:0:(ldlm_lib.c:3382:target_send_reply_msg()) @@@ dropping reply req@ffffa0ceb9e3f800 x1877720223822976/t279172874255(0) o101->a1582f77-8a80-46a1-972c-dcdc8a9170c9@192.168.203.59@tcp:319/0 lens 664/608 e 0 to 0 dl 1790738009 ref 1 fl Interpret:/600/0 rc 301/0 job:'touch.0' uid:0 gid:0 projid:0 [ 4547.516821] Lustre: 121283:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffffa0ceb4ca8700 x1877720223822976/t279172874255(0) o101->a1582f77-8a80-46a1-972c-dcdc8a9170c9@192.168.203.59@tcp:335/0 lens 664/3488 e 0 to 0 dl 1790738025 ref 1 fl Interpret:/602/0 rc 0/0 job:'touch.0' uid:0 gid:0 projid:0 [ 4553.801526] Lustre: DEBUG MARKER: == replay-single test 56: don't replay a symlink open request (3440) ========================================================== 23:13:37 (1790738017) [ 4556.735951] LustreError: 122400:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 4556.746178] LustreError: 122400:0:(osd_handler.c:720:osd_ro()) Skipped 7 previous similar messages [ 4557.626713] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4559.509931] Lustre: Failing over lustre-MDT0000 [ 4559.781805] Lustre: server umount lustre-MDT0000 complete [ 4576.229672] LustreError: MGC192.168.203.159@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4576.248218] LustreError: Skipped 9 previous similar messages [ 4586.473899] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xa21f4b807faba2cb [ 4589.599729] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3331 to 0x240000400:3393) [ 4589.600012] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3331 to 0x280000400:3361) [ 4591.075194] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4600.173907] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4601.864102] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4621.860116] Lustre: DEBUG MARKER: == replay-single test 57: test recovery from llog for setattr op ========================================================== 23:14:45 (1790738085) [ 4628.503625] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4631.127694] Lustre: Failing over lustre-MDT0000 [ 4631.561917] Lustre: server umount lustre-MDT0000 complete [ 4657.633857] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xa21f4b807faba708 [ 4661.328067] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3331 to 0x280000400:3393) [ 4661.329629] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3395 to 0x240000400:3425) [ 4663.103274] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4671.709848] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4673.299400] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4678.238818] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 4688.582880] Lustre: DEBUG MARKER: == replay-single test 58a: test recovery from llog for setattr op (test llog_gen_rec) ========================================================== 23:15:52 (1790738152) [ 4729.884032] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4731.458641] Lustre: Failing over lustre-MDT0000 [ 4732.852361] Lustre: lustre-MDT0000: Not available for connect from 192.168.203.59@tcp (stopping) [ 4733.895027] Lustre: server umount lustre-MDT0000 complete [ 4764.118171] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4773.151806] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:4676 to 0x240000400:4705) [ 4773.152562] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:4644 to 0x280000400:4673) [ 4778.598785] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4779.952290] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4831.083432] Lustre: DEBUG MARKER: == replay-single test 58b: test replay of setxattr op ==== 23:18:15 (1790738295) [ 4834.765040] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4836.298287] Lustre: Failing over lustre-MDT0000 [ 4836.742532] Lustre: server umount lustre-MDT0000 complete [ 4859.378234] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4863.606989] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:4675 to 0x280000400:4705) [ 4863.608935] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:4676 to 0x240000400:4737) [ 4870.460789] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4872.303457] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4882.414823] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount FULL mgc.*.mgs_server_uuid 1475 0 [ 4883.962540] Lustre: DEBUG MARKER: mgc.*.mgs_server_uuid in FULL state after 0 sec [ 4892.267529] Lustre: DEBUG MARKER: == replay-single test 58c: resend/reconstruct setxattr op ========================================================== 23:19:16 (1790738356) [ 4899.917670] Lustre: *** cfs_fail_loc=123, val=2147483648*** [ 4916.145442] Lustre: lustre-MDT0000: Client a1582f77-8a80-46a1-972c-dcdc8a9170c9 (at 192.168.203.59@tcp) reconnecting [ 4916.152740] Lustre: Skipped 2 previous similar messages [ 4918.662802] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 4918.670127] Lustre: Skipped 1 previous similar message [ 4918.674702] LustreError: 128715:0:(ldlm_lib.c:3382:target_send_reply_msg()) @@@ dropping reply req@ffffa0cd83bac450 x1877720226606976/t296352743435(0) o36->a1582f77-8a80-46a1-972c-dcdc8a9170c9@192.168.203.59@tcp:706/0 lens 66040/440 e 0 to 0 dl 1790738396 ref 1 fl Interpret:/600/0 rc 0/0 job:'setfattr.0' uid:0 gid:0 projid:0 [ 4935.129036] Lustre: 128717:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffffa0cd829ff480 x1877720226606976/t296352743435(0) o36->a1582f77-8a80-46a1-972c-dcdc8a9170c9@192.168.203.59@tcp:722/0 lens 66040/440 e 0 to 0 dl 1790738412 ref 1 fl Interpret:/602/0 rc 0/0 job:'setfattr.0' uid:0 gid:0 projid:0 [ 4947.392664] Lustre: DEBUG MARKER: SKIP: replay-single test_59 skipping ALWAYS excluded test 59 [ 4949.699977] Lustre: DEBUG MARKER: == replay-single test 60: test llog post recovery init vs llog unlink ========================================================== 23:20:13 (1790738413) [ 4959.059978] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4962.019600] Lustre: Failing over lustre-MDT0000 [ 4962.422633] Lustre: server umount lustre-MDT0000 complete [ 4981.167335] LustreError: 131194:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.203.59@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4981.187929] LustreError: 131194:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 1 previous similar message [ 4981.492345] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4981.496091] Lustre: Skipped 8 previous similar messages [ 4981.554131] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4981.570048] Lustre: Skipped 8 previous similar messages [ 4982.371633] Lustre: 3313:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790738433/real 1790738433] req@ffffa0ce85859880 x1877720240114816/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1790738449 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4982.407468] Lustre: 3313:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 46 previous similar messages [ 4983.865693] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:4807 to 0x280000400:4833) [ 4983.881170] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:4838 to 0x240000400:4865) [ 4986.256942] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4986.858494] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 4986.862721] Lustre: Skipped 19 previous similar messages [ 4995.105437] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4996.543369] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5007.880887] Lustre: DEBUG MARKER: == replay-single test 61a: test race llog recovery vs llog cleanup ========================================================== 23:21:11 (1790738471) [ 5027.140631] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 5041.361244] Lustre: Failing over lustre-OST0000 [ 5041.563819] Lustre: server umount lustre-OST0000 complete [ 5042.627606] LustreError: 36647:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.203.59@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 5042.659716] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 5042.665621] 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 [ 5042.678528] Lustre: Skipped 14 previous similar messages [ 5052.852541] LustreError: 36643:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.203.59@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 5052.876296] LustreError: 36643:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 4 previous similar messages [ 5061.602620] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 5061.607540] Lustre: Skipped 7 previous similar messages [ 5063.671140] Lustre: lustre-OST0000: Recovery over after 0:02, of 2 clients 2 recovered and 0 were evicted. [ 5063.695584] Lustre: Skipped 7 previous similar messages [ 5066.898666] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5082.861372] Lustre: Failing over lustre-OST0000 [ 5082.945815] Lustre: server umount lustre-OST0000 complete [ 5084.130282] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 5084.151758] LustreError: 11797:0:(ldlm_lib.c:1199: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. [ 5084.180032] LustreError: 11797:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 3 previous similar messages [ 5107.599992] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5117.081690] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 5118.927438] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 5158.603365] Lustre: DEBUG MARKER: == replay-single test 61b: test race mds llog sync vs llog cleanup ========================================================== 23:23:42 (1790738622) [ 5161.270924] Lustre: Failing over lustre-MDT0000 [ 5161.739835] Lustre: server umount lustre-MDT0000 complete [ 5179.809124] LustreError: MGC192.168.203.159@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5179.818845] LustreError: Skipped 4 previous similar messages [ 5195.669846] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5204.505718] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5266 to 0x240000400:5281) [ 5204.509798] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5234 to 0x280000400:5249) [ 5210.586419] Lustre: Failing over lustre-MDT0000 [ 5210.881089] Lustre: server umount lustre-MDT0000 complete [ 5230.131206] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5266 to 0x240000400:5313) [ 5230.132876] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5234 to 0x280000400:5281) [ 5234.201859] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5243.671863] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5245.237952] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5252.690214] Lustre: DEBUG MARKER: == replay-single test 61c: test race mds llog sync vs llog cleanup ========================================================== 23:25:16 (1790738716) [ 5266.930158] Lustre: Failing over lustre-OST0000 [ 5267.066438] Lustre: server umount lustre-OST0000 complete [ 5270.516293] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 5270.517158] LustreError: 14875:0:(ldlm_lib.c:1199: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. [ 5270.552856] LustreError: 14875:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 3 previous similar messages [ 5292.087911] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5301.653866] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 5303.066683] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 5312.826977] Lustre: DEBUG MARKER: == replay-single test 61d: error in llog_setup should cleanup the llog context correctly ========================================================== 23:26:16 (1790738776) [ 5315.033695] Lustre: Failing over lustre-MDT0000 [ 5315.422908] Lustre: server umount lustre-MDT0000 complete [ 5325.097548] Lustre: *** cfs_fail_loc=605, val=0*** [ 5325.102894] LustreError: 139746:0:(llog_obd.c:192:llog_setup()) MGS: ctxt 0 lop_setup=ffffffffc11f1ac0 failed: rc = -95 [ 5325.115542] LustreError: 139746:0:(obd_config.c:845:class_setup()) setup MGS failed (-95) [ 5325.122816] LustreError: 139746:0:(obd_mount.c:259:lustre_start_simple()) MGS setup error -95 [ 5325.133443] LustreError: 139746:0:(tgt_mount.c:116:server_deregister_mount()) MGS not registered [ 5325.145914] LustreError: Failed to start MGS 'MGS' (-95). Is the 'mgs' module loaded? [ 5325.156982] LustreError: 139746:0:(tgt_mount.c:2128:server_put_super()) no obd lustre-MDT0000 [ 5325.320096] Lustre: server umount lustre-MDT0000 complete [ 5325.322218] LustreError: 139746:0:(super25.c:179:lustre_fill_super()) llite: Unable to mount : rc = -95 [ 5332.555355] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5315 to 0x240000400:5345) [ 5332.568517] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5283 to 0x280000400:5313) [ 5336.507874] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5344.846824] Lustre: DEBUG MARKER: == replay-single test 62: don't mis-drop resent replay === 23:26:48 (1790738808) [ 5348.992529] LustreError: 140793:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 5349.014808] LustreError: 140793:0:(osd_handler.c:720:osd_ro()) Skipped 5 previous similar messages [ 5350.458953] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5354.916642] Lustre: Failing over lustre-MDT0000 [ 5355.355648] Lustre: server umount lustre-MDT0000 complete [ 5383.909366] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xa21f4b807fb10053 [ 5384.632624] Lustre: *** cfs_fail_loc=707, val=0*** [ 5388.954919] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5401.039908] Lustre: lustre-MDT0000: Client a1582f77-8a80-46a1-972c-dcdc8a9170c9 (at 192.168.203.59@tcp) reconnected, waiting for 1 clients in recovery for 0:53 [ 5401.886303] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5359 to 0x240000400:5377) [ 5401.893084] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5326 to 0x280000400:5345) [ 5408.209516] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5409.939975] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5420.506860] Lustre: DEBUG MARKER: == replay-single test 65a: AT: verify early replies ====== 23:28:04 (1790738884) [ 5451.523431] LustreError: 141858:0:(service.c:2581:ptlrpc_server_handle_request()) @@@ HIT req@ffffa0ce8ee3d500 x1877720227484544/t0(0) o101->a1582f77-8a80-46a1-972c-dcdc8a9170c9@192.168.203.59@tcp:484/0 lens 664/0 e 0 to 0 dl 1790738929 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 5451.542994] LustreError: 141858:0:(service.c:2582:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a sleeping for 11000ms [ 5462.600497] LustreError: 141858:0:(service.c:2582:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a awake [ 5462.621502] LustreError: 141871:0:(service.c:2581:ptlrpc_server_handle_request()) @@@ HIT req@ffffa0cd84b66680 x1877720227485568/t0(0) o35->a1582f77-8a80-46a1-972c-dcdc8a9170c9@192.168.203.59@tcp:501/0 lens 392/0 e 0 to 0 dl 1790738946 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 5464.491123] LustreError: 141454:0:(service.c:2581:ptlrpc_server_handle_request()) @@@ HIT req@ffffa0ceb51fce00 x1877720227491456/t0(0) o101->a1582f77-8a80-46a1-972c-dcdc8a9170c9@192.168.203.59@tcp:536/0 lens 576/0 e 0 to 0 dl 1790738981 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'unlinkmany.0' uid:0 gid:0 projid:0 [ 5464.520965] LustreError: 141454:0:(service.c:2581:ptlrpc_server_handle_request()) Skipped 27 previous similar messages [ 5468.857914] LustreError: 36643:0:(service.c:2581:ptlrpc_server_handle_request()) @@@ HIT req@ffffa0cd84b67100 x1877720240380672/t0(0) o6->lustre-MDT0000-mdtlov_UUID@0@lo:501/0 lens 544/0 e 0 to 0 dl 1790738946 ref 1 fl Interpret:/200/ffffffff rc 0/-1 job:'osp-syn-1-0.0' uid:0 gid:0 projid:4294967295 [ 5468.893852] LustreError: 36643:0:(service.c:2581:ptlrpc_server_handle_request()) Skipped 24 previous similar messages [ 5473.820407] LustreError: 6692:0:(service.c:2581:ptlrpc_server_handle_request()) @@@ HIT req@ffffa0cebada2a00 x1877720240382592/t0(0) o6->lustre-MDT0000-mdtlov_UUID@0@lo:506/0 lens 544/0 e 0 to 0 dl 1790738951 ref 1 fl Interpret:/200/ffffffff rc 0/-1 job:'osp-syn-1-0.0' uid:0 gid:0 projid:4294967295 [ 5473.837625] LustreError: 6692:0:(service.c:2581:ptlrpc_server_handle_request()) Skipped 3 previous similar messages [ 5479.791802] Lustre: DEBUG MARKER: == replay-single test 65b: AT: verify early replies on packed reply / bulk ========================================================== 23:29:03 (1790738943) [ 5509.689814] LustreError: 32236:0:(tgt_handler.c:2874:tgt_brw_write()) cfs_fail_timeout id 224 sleeping for 11000ms [ 5520.760970] LustreError: 32236:0:(tgt_handler.c:2874:tgt_brw_write()) cfs_fail_timeout id 224 awake [ 5529.400973] Lustre: DEBUG MARKER: == replay-single test 66a: AT: verify MDT service time adjusts with no early replies ========================================================== 23:29:53 (1790738993) [ 5558.270374] LustreError: 141858:0:(service.c:2581:ptlrpc_server_handle_request()) @@@ HIT req@ffffa0cebadf6d80 x1877720227509120/t0(0) o101->a1582f77-8a80-46a1-972c-dcdc8a9170c9@192.168.203.59@tcp:591/0 lens 576/0 e 0 to 0 dl 1790739036 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 5558.300626] LustreError: 141858:0:(service.c:2582:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a sleeping for 5000ms [ 5563.336594] LustreError: 141858:0:(service.c:2582:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a awake [ 5575.936119] LustreError: 142898:0:(service.c:2582:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a awake [ 5575.959095] LustreError: 141455:0:(service.c:2581:ptlrpc_server_handle_request()) @@@ HIT req@ffffa0ce858d0000 x1877720227531648/t0(0) o101->a1582f77-8a80-46a1-972c-dcdc8a9170c9@192.168.203.59@tcp:647/0 lens 664/0 e 0 to 0 dl 1790739092 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 5575.981487] LustreError: 141455:0:(service.c:2581:ptlrpc_server_handle_request()) Skipped 120 previous similar messages [ 5595.713893] Lustre: DEBUG MARKER: == replay-single test 66b: AT: verify net latency adjusts ========================================================== 23:30:59 (1790739059) [ 5688.529561] Lustre: DEBUG MARKER: == replay-single test 67a: AT: verify slow request processing doesn't induce reconnects ========================================================== 23:32:32 (1790739152) [ 5717.112126] LustreError: 142898:0:(service.c:2581:ptlrpc_server_handle_request()) @@@ HIT req@ffffa0cd8383b480 x1877720227587328/t0(0) o101->a1582f77-8a80-46a1-972c-dcdc8a9170c9@192.168.203.59@tcp:749/0 lens 576/0 e 0 to 0 dl 1790739194 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 5717.148352] LustreError: 142898:0:(service.c:2581:ptlrpc_server_handle_request()) Skipped 98 previous similar messages [ 5717.156069] LustreError: 142898:0:(service.c:2582:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a sleeping for 400ms [ 5717.165912] LustreError: 142898:0:(service.c:2582:ptlrpc_server_handle_request()) Skipped 1 previous similar message [ 5717.600676] LustreError: 142898:0:(service.c:2582:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a awake [ 5733.457401] LustreError: 141458:0:(service.c:2582:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a sleeping for 400ms [ 5733.468777] LustreError: 141458:0:(service.c:2582:ptlrpc_server_handle_request()) Skipped 37 previous similar messages [ 5733.904117] LustreError: 141458:0:(service.c:2582:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a awake [ 5733.925546] LustreError: 141458:0:(service.c:2582:ptlrpc_server_handle_request()) Skipped 37 previous similar messages [ 5767.710648] Lustre: DEBUG MARKER: == replay-single test 67b: AT: verify instant slowdown doesn't induce reconnects ========================================================== 23:33:51 (1790739231) [ 5802.378687] Lustre: DEBUG MARKER: phase 2 [ 5811.806239] Lustre: DEBUG MARKER: == replay-single test 68: AT: verify slowing locks ======= 23:34:35 (1790739275) [ 5894.477778] Lustre: DEBUG MARKER: == replay-single test 70a: check multi client t-f ======== 23:35:58 (1790739358) [ 5896.004898] Lustre: DEBUG MARKER: SKIP: replay-single test_70a Need two or more clients, have 1 [ 5897.644319] Lustre: DEBUG MARKER: == replay-single test 70b: dbench 1mdts recovery; 1 clients ========================================================== 23:36:01 (1790739361) [ 5901.768655] Lustre: DEBUG MARKER: Started rundbench load pid=128884 ... [ 5907.175572] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5909.647103] Lustre: DEBUG MARKER: test_70b fail mds1 1 times [ 5911.625405] Lustre: Failing over lustre-MDT0000 [ 5911.909467] Lustre: server umount lustre-MDT0000 complete [ 5928.416109] Lustre: 3313:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790739379/real 1790739379] req@ffffa0ce88a1dc00 x1877720240509056/t0(0) o400->MGC192.168.203.159@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1790739395 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5928.446244] Lustre: 3313:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 39 previous similar messages [ 5928.471083] LustreError: MGC192.168.203.159@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5928.487134] LustreError: Skipped 3 previous similar messages [ 5929.440341] 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 [ 5929.451925] Lustre: Skipped 11 previous similar messages [ 5939.189094] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 5939.194728] Lustre: Skipped 7 previous similar messages [ 5939.296366] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 5939.305932] Lustre: Skipped 7 previous similar messages [ 5940.071180] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 5940.076286] Lustre: Skipped 13 previous similar messages [ 5944.348062] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5946.666199] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 5946.678376] Lustre: Skipped 6 previous similar messages [ 5947.182112] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 5947.191990] Lustre: Skipped 6 previous similar messages [ 5947.231303] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5426 to 0x280000400:5441) [ 5947.234261] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5479 to 0x240000400:5505) [ 5954.985875] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5956.540743] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5962.972055] LustreError: 149715:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 5962.983339] LustreError: 149715:0:(osd_handler.c:720:osd_ro()) Skipped 1 previous similar message [ 5963.831748] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5966.614033] Lustre: DEBUG MARKER: test_70b fail mds1 2 times [ 5968.435492] Lustre: Failing over lustre-MDT0000 [ 5968.799253] Lustre: server umount lustre-MDT0000 complete [ 5996.512889] LustreError: 3310:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffffa0cd84752d80 x1877720240587520/t0(0) o250->MGC192.168.203.159@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 [ 6002.411369] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6008.064063] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5466 to 0x280000400:5505) [ 6008.071769] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5531 to 0x240000400:5569) [ 6014.440219] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6016.298424] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6052.745865] Lustre: DEBUG MARKER: == replay-single test 70c: tar 1mdts recovery ============ 23:38:36 (1790739516) [ 6178.384711] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 6190.679996] Lustre: DEBUG MARKER: test_70c fail mds1 1 times [ 6193.074670] Lustre: Failing over lustre-MDT0000 [ 6193.669136] Lustre: server umount lustre-MDT0000 complete [ 6221.280853] LustreError: 3310:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffffa0cd8e9f5500 x1877720241097728/t0(0) o250->MGC192.168.203.159@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 [ 6226.772189] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6239.852828] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6196 to 0x280000400:6241) [ 6239.853717] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6259 to 0x240000400:6305) [ 6246.512864] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6248.232784] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6343.679651] Lustre: DEBUG MARKER: == replay-single test 70d: mkdir/rmdir striped dir 1mdts recovery ========================================================== 23:43:27 (1790739807) [ 6345.336629] Lustre: DEBUG MARKER: SKIP: replay-single test_70d needs >= 2 MDTs [ 6347.175621] Lustre: DEBUG MARKER: == replay-single test 70e: rename cross-MDT with random fails ========================================================== 23:43:31 (1790739811) [ 6348.759834] Lustre: DEBUG MARKER: SKIP: replay-single test_70e needs >= 2 MDTs [ 6350.821092] Lustre: DEBUG MARKER: == replay-single test 70f: OSS O_DIRECT recovery with 1 clients ========================================================== 23:43:34 (1790739814) [ 6358.090406] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 6360.609462] Lustre: DEBUG MARKER: test_70f failing OST 1 times [ 6362.455736] Lustre: Failing over lustre-OST0000 [ 6362.517318] Lustre: server umount lustre-OST0000 complete [ 6363.106697] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 6363.121660] LustreError: 36643:0:(ldlm_lib.c:1199: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. [ 6363.142884] LustreError: 36643:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 5 previous similar messages [ 6375.399466] LustreError: 36647:0:(ldlm_lib.c:1199: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. [ 6375.436406] LustreError: 36647:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 4 previous similar messages [ 6388.092415] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6397.893678] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 6399.343203] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 6410.914727] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 6413.550071] Lustre: DEBUG MARKER: test_70f failing OST 2 times [ 6415.725600] Lustre: Failing over lustre-OST0000 [ 6415.778585] Lustre: server umount lustre-OST0000 complete [ 6416.820982] LustreError: 36645:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.203.59@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 6416.860175] LustreError: 36645:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 3 previous similar messages [ 6443.478130] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6453.607175] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 6455.135210] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 6465.376772] Lustre: DEBUG MARKER: == replay-single test 71a: mkdir/rmdir striped dir with 2 mdts recovery ========================================================== 23:45:29 (1790739929) [ 6466.900547] Lustre: DEBUG MARKER: SKIP: replay-single test_71a needs >= 2 MDTs [ 6468.639837] Lustre: DEBUG MARKER: == replay-single test 73a: open(O_CREAT), unlink, replay, reconnect before open replay, close ========================================================== 23:45:32 (1790739932) [ 6472.230263] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 6474.745289] Lustre: Failing over lustre-MDT0000 [ 6474.983708] Lustre: server umount lustre-MDT0000 complete [ 6493.620383] Lustre: *** cfs_fail_loc=302, val=2147483648*** [ 6497.375467] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6510.021291] Lustre: lustre-MDT0000: Client a1582f77-8a80-46a1-972c-dcdc8a9170c9 (at 192.168.203.59@tcp) reconnected, waiting for 1 clients in recovery for 0:53 [ 6510.191499] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6550 to 0x280000400:6593) [ 6510.193793] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6614 to 0x240000400:6657) [ 6515.701628] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6517.265784] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6525.116458] Lustre: DEBUG MARKER: == replay-single test 73b: open(O_CREAT), unlink, replay, reconnect at open_replay reply, close ========================================================== 23:46:29 (1790739989) [ 6528.912141] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 6531.551925] Lustre: Failing over lustre-MDT0000 [ 6531.797077] Lustre: server umount lustre-MDT0000 complete [ 6549.432185] LustreError: MGC192.168.203.159@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 6549.445330] LustreError: Skipped 3 previous similar messages [ 6549.743462] 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 [ 6549.764681] Lustre: Skipped 9 previous similar messages [ 6549.920770] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 6549.926550] Lustre: Skipped 5 previous similar messages [ 6550.047464] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 6550.058450] Lustre: Skipped 5 previous similar messages [ 6550.817132] Lustre: 3314:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790740001/real 1790740001] req@ffffa0cea5924000 x1877720241579520/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1790740017 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6550.846079] Lustre: 3314:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 33 previous similar messages [ 6551.674428] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 6551.691326] Lustre: Skipped 5 previous similar messages [ 6551.814206] Lustre: *** cfs_fail_loc=157, val=2147483648*** [ 6551.816356] LustreError: 159103:0:(ldlm_lib.c:3382:target_send_reply_msg()) @@@ dropping reply req@ffffa0cea5bb9c00 x1877720236113408/t335007449091(335007449091) o101->a1582f77-8a80-46a1-972c-dcdc8a9170c9@192.168.203.59@tcp:74/0 lens 592/608 e 0 to 0 dl 1790740029 ref 1 fl Interpret:/604/0 rc 301/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 6554.668702] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6555.132312] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 6555.149268] Lustre: Skipped 9 previous similar messages [ 6567.885345] Lustre: lustre-MDT0000: Client a1582f77-8a80-46a1-972c-dcdc8a9170c9 (at 192.168.203.59@tcp) reconnected, waiting for 1 clients in recovery for 0:53 [ 6567.908762] Lustre: 159105:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffffa0ceb1fa8a80 x1877720236113408/t335007449091(335007449091) o101->a1582f77-8a80-46a1-972c-dcdc8a9170c9@192.168.203.59@tcp:90/0 lens 592/3488 e 0 to 0 dl 1790740045 ref 1 fl Interpret:/606/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 6568.105979] Lustre: lustre-MDT0000: Recovery over after 0:17, of 1 clients 1 recovered and 0 were evicted. [ 6568.117153] Lustre: Skipped 5 previous similar messages [ 6568.180978] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6595 to 0x280000400:6625) [ 6568.192371] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6614 to 0x240000400:6689) [ 6575.235598] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6576.847944] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6584.538841] Lustre: DEBUG MARKER: == replay-single test 74: Ensure applications don't fail waiting for OST recovery ========================================================== 23:47:28 (1790740048) [ 6587.759403] Lustre: Failing over lustre-OST0000 [ 6587.827566] Lustre: server umount lustre-OST0000 complete [ 6588.903453] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 6588.931328] LustreError: 36646:0:(ldlm_lib.c:1199: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. [ 6588.948691] LustreError: 36646:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 7 previous similar messages [ 6591.772592] Lustre: Failing over lustre-MDT0000 [ 6592.105896] Lustre: server umount lustre-MDT0000 complete [ 6609.442524] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6595 to 0x280000400:6657) [ 6612.615397] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6619.569377] Lustre: lustre-OST0000: Denying connection for new client 01113c3c-809d-4ed6-bab3-df7bdbb1cbf3 (at 192.168.203.59@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:59 [ 6620.996448] Lustre: lustre-OST0000: Denying connection for new client 01113c3c-809d-4ed6-bab3-df7bdbb1cbf3 (at 192.168.203.59@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:58 [ 6624.340651] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6614 to 0x240000400:6721) [ 6625.568902] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6636.141864] Lustre: DEBUG MARKER: == replay-single test 80a: DNE: create remote dir, drop update rep from MDT0, fail MDT0 ========================================================== 23:48:19 (1790740099) [ 6637.749559] Lustre: DEBUG MARKER: SKIP: replay-single test_80a needs >= 2 MDTs [ 6639.306986] Lustre: DEBUG MARKER: == replay-single test 80b: DNE: create remote dir, drop update rep from MDT0, fail MDT1 ========================================================== 23:48:23 (1790740103) [ 6640.937495] Lustre: DEBUG MARKER: SKIP: replay-single test_80b needs >= 2 MDTs [ 6642.733834] Lustre: DEBUG MARKER: == replay-single test 80c: DNE: create remote dir, drop update rep from MDT1, fail MDT[0,1] ========================================================== 23:48:26 (1790740106) [ 6644.113224] Lustre: DEBUG MARKER: SKIP: replay-single test_80c needs >= 2 MDTs [ 6645.669307] Lustre: DEBUG MARKER: == replay-single test 80d: DNE: create remote dir, drop update rep from MDT1, fail 2 MDTs ========================================================== 23:48:29 (1790740109) [ 6647.203823] Lustre: DEBUG MARKER: SKIP: replay-single test_80d needs >= 2 MDTs [ 6648.904788] Lustre: DEBUG MARKER: == replay-single test 80e: DNE: create remote dir, drop MDT1 rep, fail MDT0 ========================================================== 23:48:32 (1790740112) [ 6650.265144] Lustre: DEBUG MARKER: SKIP: replay-single test_80e needs >= 2 MDTs [ 6651.658528] Lustre: DEBUG MARKER: == replay-single test 80f: DNE: create remote dir, drop MDT1 rep, fail MDT1 ========================================================== 23:48:35 (1790740115) [ 6653.120930] Lustre: DEBUG MARKER: SKIP: replay-single test_80f needs >= 2 MDTs [ 6654.500924] Lustre: DEBUG MARKER: == replay-single test 80g: DNE: create remote dir, drop MDT1 rep, fail MDT0, then MDT1 ========================================================== 23:48:38 (1790740118) [ 6656.240487] Lustre: DEBUG MARKER: SKIP: replay-single test_80g needs >= 2 MDTs [ 6657.719089] Lustre: DEBUG MARKER: == replay-single test 80h: DNE: create remote dir, drop MDT1 rep, fail 2 MDTs ========================================================== 23:48:41 (1790740121) [ 6659.086251] Lustre: DEBUG MARKER: SKIP: replay-single test_80h needs >= 2 MDTs [ 6661.113796] Lustre: DEBUG MARKER: == replay-single test 81a: DNE: unlink remote dir, drop MDT0 update rep, fail MDT1 ========================================================== 23:48:44 (1790740124) [ 6662.320554] Lustre: DEBUG MARKER: SKIP: replay-single test_81a needs >= 2 MDTs [ 6664.099271] Lustre: DEBUG MARKER: == replay-single test 81b: DNE: unlink remote dir, drop MDT0 update reply, fail MDT0 ========================================================== 23:48:48 (1790740128) [ 6665.844186] Lustre: DEBUG MARKER: SKIP: replay-single test_81b needs >= 2 MDTs [ 6667.055457] Lustre: DEBUG MARKER: == replay-single test 81c: DNE: unlink remote dir, drop MDT0 update reply, fail MDT0,MDT1 ========================================================== 23:48:51 (1790740131) [ 6668.156296] Lustre: DEBUG MARKER: SKIP: replay-single test_81c needs >= 2 MDTs [ 6669.459449] Lustre: DEBUG MARKER: == replay-single test 81d: DNE: unlink remote dir, drop MDT0 update reply, fail 2 MDTs ========================================================== 23:48:53 (1790740133) [ 6671.361682] Lustre: DEBUG MARKER: SKIP: replay-single test_81d needs >= 2 MDTs [ 6673.398107] Lustre: DEBUG MARKER: == replay-single test 81e: DNE: unlink remote dir, drop MDT1 req reply, fail MDT0 ========================================================== 23:48:57 (1790740137) [ 6675.025567] Lustre: DEBUG MARKER: SKIP: replay-single test_81e needs >= 2 MDTs [ 6677.047566] Lustre: DEBUG MARKER: == replay-single test 81f: DNE: unlink remote dir, drop MDT1 req reply, fail MDT1 ========================================================== 23:49:00 (1790740140) [ 6678.817762] Lustre: DEBUG MARKER: SKIP: replay-single test_81f needs >= 2 MDTs [ 6680.739938] Lustre: DEBUG MARKER: == replay-single test 81g: DNE: unlink remote dir, drop req reply, fail M0, then M1 ========================================================== 23:49:04 (1790740144) [ 6682.423654] Lustre: DEBUG MARKER: SKIP: replay-single test_81g needs >= 2 MDTs [ 6684.113334] Lustre: DEBUG MARKER: == replay-single test 81h: DNE: unlink remote dir, drop request reply, fail 2 MDTs ========================================================== 23:49:08 (1790740148) [ 6685.759104] Lustre: DEBUG MARKER: SKIP: replay-single test_81h needs >= 2 MDTs [ 6688.118951] Lustre: DEBUG MARKER: == replay-single test 84a: stale open during export disconnect ========================================================== 23:49:11 (1790740151) [ 6690.136793] Lustre: 163736:0:(genops.c:1773:obd_export_evict_by_uuid()) lustre-MDT0000: evicting 01113c3c-809d-4ed6-bab3-df7bdbb1cbf3 at adminstrative request [ 6701.022135] Lustre: DEBUG MARKER: == replay-single test 85a: check the cancellation of unused locks during recovery(IBITS) ========================================================== 23:49:24 (1790740164) [ 6709.938333] Lustre: Failing over lustre-MDT0000 [ 6710.321807] Lustre: server umount lustre-MDT0000 complete [ 6737.900465] LustreError: 3310:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffffa0ceb2ea5c00 x1877720241629440/t0(0) o250->MGC192.168.203.159@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 [ 6739.214541] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6709 to 0x280000400:6753) [ 6739.217238] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6773 to 0x240000400:6817) [ 6743.065554] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6753.127716] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6754.789451] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6763.403125] Lustre: DEBUG MARKER: == replay-single test 85b: check the cancellation of unused locks during recovery(EXTENT) ========================================================== 23:50:27 (1790740227) [ 6777.135462] Lustre: Failing over lustre-OST0000 [ 6778.338355] Lustre: lustre-OST0000: Not available for connect from 0@lo (stopping) [ 6779.312957] LustreError: 36642:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.203.59@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 6779.330363] LustreError: 36642:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 4 previous similar messages [ 6779.342329] Lustre: server umount lustre-OST0000 complete [ 6802.443672] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6811.349406] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 6812.780206] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 6822.741366] Lustre: DEBUG MARKER: == replay-single test 86: umount server after clear nid_stats should not hit LBUG ========================================================== 23:51:26 (1790740286) [ 6828.072252] Lustre: Failing over lustre-MDT0000 [ 6828.594344] Lustre: server umount lustre-MDT0000 complete [ 6836.449237] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6918 to 0x240000400:6945) [ 6836.456382] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6709 to 0x280000400:6785) [ 6841.095803] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6848.635840] Lustre: DEBUG MARKER: == replay-single test 87a: write replay ================== 23:51:52 (1790740312) [ 6852.023132] LustreError: 168144:0:(osd_handler.c:720:osd_ro()) lustre-OST0000: *** setting device osd-zfs read-only *** [ 6852.030425] LustreError: 168144:0:(osd_handler.c:720:osd_ro()) Skipped 5 previous similar messages [ 6853.002728] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 6855.712920] Lustre: Failing over lustre-OST0000 [ 6855.760594] Lustre: server umount lustre-OST0000 complete [ 6856.685312] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 6884.614455] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6895.666642] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 6897.215022] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 6905.309435] Lustre: DEBUG MARKER: == replay-single test 87b: write replay with changed data (checksum resend) ========================================================== 23:52:49 (1790740369) [ 6909.984604] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 6913.550741] Lustre: Failing over lustre-OST0000 [ 6913.644956] Lustre: server umount lustre-OST0000 complete [ 6914.529206] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 6914.534555] LustreError: 36644:0:(ldlm_lib.c:1199: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. [ 6914.571314] LustreError: 36644:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 14 previous similar messages [ 6937.992775] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6947.426552] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 6949.008657] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 6957.392882] Lustre: DEBUG MARKER: == replay-single test 88: MDS should not assign same objid to different files ========================================================== 23:53:41 (1790740421) [ 6960.999378] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 6964.664759] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 6970.474095] Lustre: Failing over lustre-MDT0000 [ 6970.877311] Lustre: server umount lustre-MDT0000 complete [ 6974.398597] LustreError: 127692:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1790740441 with bad export cookie 11682138973693160365 [ 6984.677640] Lustre: Failing over lustre-OST0000 [ 6984.739763] Lustre: server umount lustre-OST0000 complete [ 7025.228775] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7032.413025] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6826 to 0x280000400:6849) [ 7050.594354] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7054.158657] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6947 to 0x240000400:6977) [ 7065.198882] Lustre: DEBUG MARKER: == replay-single test 89: no disk space leak on late ost connection ========================================================== 23:55:29 (1790740529) [ 7082.602356] Lustre: Failing over lustre-OST0000 [ 7082.939802] Lustre: lustre-OST0000: Not available for connect from 192.168.203.59@tcp (stopping) [ 7084.744944] Lustre: server umount lustre-OST0000 complete [ 7085.036669] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 7088.755899] Lustre: Failing over lustre-MDT0000 [ 7089.150596] Lustre: server umount lustre-MDT0000 complete [ 7116.256580] LustreError: 3310:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffffa0ce95355180 x1877720241740928/t0(0) o250->MGC192.168.203.159@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 [ 7119.112769] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6826 to 0x280000400:6881) [ 7121.941279] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7135.335482] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7138.155753] Lustre: lustre-OST0000: Denying connection for new client 4f67d381-b4f2-4af7-ac00-98d68c9f2cb7 (at 192.168.203.59@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 1:03 [ 7143.341302] Lustre: lustre-OST0000: Denying connection for new client 4f67d381-b4f2-4af7-ac00-98d68c9f2cb7 (at 192.168.203.59@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 0:58 [ 7153.578760] Lustre: lustre-OST0000: Denying connection for new client 4f67d381-b4f2-4af7-ac00-98d68c9f2cb7 (at 192.168.203.59@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 0:47 [ 7153.612635] Lustre: Skipped 1 previous similar message [ 7174.057920] Lustre: lustre-OST0000: Denying connection for new client 4f67d381-b4f2-4af7-ac00-98d68c9f2cb7 (at 192.168.203.59@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 0:27 [ 7174.079037] Lustre: Skipped 3 previous similar messages [ 7201.500382] Lustre: lustre-OST0000: recovery is timed out, evict stale exports [ 7201.503274] Lustre: 176033:0:(genops.c:1600:class_disconnect_stale_exports()) lustre-OST0000: disconnect stale client ab7b970e-79d5-4ca9-aeb0-0d23c2fb1e8c@ [ 7201.530978] Lustre: lustre-OST0000: disconnecting 1 stale clients [ 7201.578984] Lustre: lustre-OST0000: Recovery over after 1:10, of 2 clients 1 recovered and 1 was evicted. [ 7201.590525] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 7201.594179] Lustre: Skipped 8 previous similar messages [ 7201.627056] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6988 to 0x240000400:7009) [ 7201.627855] Lustre: Skipped 13 previous similar messages [ 7208.004412] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 60 sec [ 7223.565895] Lustre: DEBUG MARKER: free_before: 7520256 free_after: 7520256 [ 7230.297277] Lustre: DEBUG MARKER: == replay-single test 90: lfs find identifies the missing striped file segments ========================================================== 23:58:14 (1790740694) [ 7235.140309] Lustre: Failing over lustre-OST0001 [ 7235.235595] Lustre: server umount lustre-OST0001 complete [ 7235.545961] LustreError: 36644:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-OST0001: not available for connect from 192.168.203.59@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 7235.565068] LustreError: 36644:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 26 previous similar messages [ 7238.626753] Lustre: lustre-OST0001-osc-MDT0000: Connection to lustre-OST0001 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 7238.639330] Lustre: Skipped 12 previous similar messages [ 7255.095715] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 7255.100877] Lustre: Skipped 11 previous similar messages [ 7255.109694] Lustre: lustre-OST0001: in recovery but waiting for the first client to connect [ 7255.115160] Lustre: Skipped 9 previous similar messages [ 7255.977073] Lustre: lustre-OST0001: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 7255.982561] Lustre: Skipped 9 previous similar messages [ 7261.457638] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7271.946574] Lustre: DEBUG MARKER: == replay-single test 93a: replay + reconnect ============ 23:58:55 (1790740735) [ 7276.266403] Lustre: Failing over lustre-OST0000 [ 7276.358293] Lustre: server umount lustre-OST0000 complete [ 7278.567853] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 7296.567929] LustreError: 179109:0:(ldlm_lib.c:2939:target_recovery_thread()) cfs_fail_timeout id 715 sleeping for 40000ms [ 7296.583898] LustreError: 179109:0:(ldlm_lib.c:2939:target_recovery_thread()) Skipped 79 previous similar messages [ 7302.477883] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7302.625684] Lustre: *** cfs_fail_loc=715, val=40*** [ 7311.879362] Lustre: lustre-OST0000: Client 4f67d381-b4f2-4af7-ac00-98d68c9f2cb7 (at 192.168.203.59@tcp) reconnected, waiting for 2 clients in recovery for 1:25 [ 7312.864142] Lustre: 3310:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790740763/real 1790740763] req@ffffa0ce87a1c700 x1877720241789312/t0(0) o400->lustre-OST0000-osc-MDT0000@0@lo:28/4 lens 224/224 e 0 to 1 dl 1790740779 ref 1 fl Rpc:XQr/2c0/ffffffff rc 0/-1 job:'ldlm_lock_repla.0' uid:0 gid:0 projid:4294967295 [ 7312.892975] Lustre: 3310:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 29 previous similar messages [ 7312.917233] Lustre: lustre-OST0000: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnected, waiting for 2 clients in recovery for 1:24 [ 7317.984862] Lustre: *** cfs_fail_loc=715, val=40*** [ 7317.991934] Lustre: Skipped 1 previous similar message [ 7319.009256] Lustre: *** cfs_fail_loc=715, val=40*** [ 7328.176200] Lustre: lustre-OST0000: Client 4f67d381-b4f2-4af7-ac00-98d68c9f2cb7 (at 192.168.203.59@tcp) reconnected, waiting for 2 clients in recovery for 1:09 [ 7334.369502] Lustre: *** cfs_fail_loc=715, val=40*** [ 7336.624169] LustreError: 179109:0:(ldlm_lib.c:2939:target_recovery_thread()) cfs_fail_timeout id 715 awake [ 7336.629855] LustreError: 179109:0:(ldlm_lib.c:2939:target_recovery_thread()) Skipped 79 previous similar messages [ 7343.734279] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 7345.439776] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 7354.956401] Lustre: DEBUG MARKER: == replay-single test 93b: replay + reconnect on mds ===== 00:00:18 (1790740818) [ 7359.789288] Lustre: Failing over lustre-MDT0000 [ 7360.323211] Lustre: server umount lustre-MDT0000 complete [ 7380.382967] LustreError: MGC192.168.203.159@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 7380.395141] LustreError: Skipped 5 previous similar messages [ 7387.152143] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7390.185649] LustreError: 180722:0:(ldlm_lib.c:2939:target_recovery_thread()) cfs_fail_timeout id 715 sleeping for 80000ms [ 7396.320319] Lustre: *** cfs_fail_loc=715, val=80*** [ 7396.329563] Lustre: Skipped 1 previous similar message [ 7406.509971] Lustre: lustre-MDT0000: Client 4f67d381-b4f2-4af7-ac00-98d68c9f2cb7 (at 192.168.203.59@tcp) reconnected, waiting for 1 clients in recovery for 0:53 [ 7406.518991] Lustre: Skipped 1 previous similar message [ 7412.704111] Lustre: *** cfs_fail_loc=715, val=80*** [ 7421.879317] Lustre: lustre-MDT0000: Client 4f67d381-b4f2-4af7-ac00-98d68c9f2cb7 (at 192.168.203.59@tcp) reconnected, waiting for 1 clients in recovery for 0:38 [ 7438.249350] Lustre: lustre-MDT0000: Client 4f67d381-b4f2-4af7-ac00-98d68c9f2cb7 (at 192.168.203.59@tcp) reconnected, waiting for 1 clients in recovery for 0:22 [ 7444.448271] Lustre: *** cfs_fail_loc=715, val=80*** [ 7444.451443] Lustre: Skipped 1 previous similar message [ 7469.994823] 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. [ 7470.227146] LustreError: 180722:0:(ldlm_lib.c:2939:target_recovery_thread()) cfs_fail_timeout id 715 awake [ 7470.270708] Lustre: 180722:0:(ldlm_lib.c:2985:target_recovery_thread()) too long recovery - read logs [ 7470.282575] LustreError: dumping log to /tmp/lustre-log.1790740937.180722 [ 7470.545540] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6894 to 0x280000400:6913) [ 7470.546614] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:7023 to 0x240000400:7041) [ 7477.066106] Lustre: DEBUG MARKER: oleg359-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 7478.818894] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7488.525301] Lustre: DEBUG MARKER: == replay-single test complete, duration 7258 sec ======== 00:02:32 (1790740952) [ 7490.428275] Lustre: DEBUG MARKER: === replay-single: start cleanup 00:02:34 (1790740954) === [ 7500.021867] Lustre: DEBUG MARKER: === replay-single: finish cleanup 00:02:43 (1790740963) === [ 7534.570222] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 7536.172389] Lustre: server umount lustre-MDT0000 complete [ 7540.116772] LustreError: 127692:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1790741006 with bad export cookie 11682138973693172895 [ 7540.136170] LustreError: 127692:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 7540.223282] Lustre: server umount lustre-OST0000 complete [ 7544.037200] Lustre: server umount lustre-OST0001 complete [ 7556.834706] Lustre: DEBUG MARKER: oleg359-server.virtnet: executing unload_modules_local [ 7559.942509] Key type lgssc unregistered [ 7560.322676] LNet: 182873:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 7560.339226] LNetError: 182873:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 7560.366481] LNet: Removed LNI 192.168.203.159@tcp [ 7561.364146] Key type .llcrypt unregistered [ 7561.366605] Key type ._llcrypt unregistered