[ 0.000000] Linux version 4.18.0rh8.10-debug (green@maintenance) (gcc version 8.5.0 20210514 (Red Hat 8.5.0-26) (GCC)) #2 SMP Mon Jul 14 01:24:22 EDT 2025 [ 0.000000] Command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers' [ 0.000000] x86/fpu: xstate_offset[2]: 576, xstate_sizes[2]: 256 [ 0.000000] x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'standard' format. [ 0.000000] signal: max sigframe size: 1776 [ 0.000000] BIOS-provided physical RAM map: [ 0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable [ 0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000000100000-0x00000000bffcdfff] usable [ 0.000000] BIOS-e820: [mem 0x00000000bffce000-0x00000000bfffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000100000000-0x0000000146dfffff] usable [ 0.000000] NX (Execute Disable) protection: active [ 0.000000] SMBIOS 2.8 present. [ 0.000000] DMI: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.17.0-8.fc42 06/10/2025 [ 0.000000] Hypervisor detected: KVM [ 0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00 [ 0.000000] kvm-clock: using sched offset of 493419610 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2399.998 MHz processor [ 0.000000] last_pfn = 0x146e00 max_arch_pfn = 0x400000000 [ 0.000000] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT [ 0.000000] last_pfn = 0xbffce max_arch_pfn = 0x400000000 [ 0.000000] found SMP MP-table at [mem 0x000f54b0-0x000f54bf] [ 0.000000] RAMDISK: [mem 0xbcc54000-0xbffbffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F52D0 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE2439 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE22D5 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 002295 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE2349 000090 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE23D9 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE2411 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe22d5-0xbffe2348] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe22d4] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe2349-0xbffe23d8] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe23d9-0xbffe2410] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe2411-0xbffe2438] [ 0.000000] No NUMA configuration found [ 0.000000] Faking a node at [mem 0x0000000000000000-0x0000000146dfffff] [ 0.000000] NODE_DATA(0) allocated [mem 0x1465a3000-0x1465cdfff] [ 0.000000] Reserving 256MB of memory at 2752MB for crashkernel (System RAM: 4205MB) [ 0.000000] Zone ranges: [ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.000000] DMA32 [mem 0x0000000001000000-0x00000000ffffffff] [ 0.000000] Normal [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Device empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff] [ 0.000000] node 0: [mem 0x0000000000100000-0x00000000bffcdfff] [ 0.000000] node 0: [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Zeroed struct page in unavailable ranges: 4756 pages [ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x0000000146dfffff] [ 0.000000] ACPI: PM-Timer IO Port: 0x608 [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) [ 0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) [ 0.000000] Using ACPI (MADT) for SMP configuration information [ 0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000] TSC deadline timer available [ 0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs [ 0.000000] kvm-guest: KVM setup pv remote TLB flush [ 0.000000] kvm-guest: setup PV sched yield [ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff] [ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff] [ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff] [ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff] [ 0.000000] PM: Registered nosave memory: [mem 0xbffce000-0xbfffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xc0000000-0xfeffbfff] [ 0.000000] PM: Registered nosave memory: [mem 0xfeffc000-0xfeffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xff000000-0xfffbffff] [ 0.000000] PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff] [ 0.000000] [mem 0xc0000000-0xfeffbfff] available for PCI devices [ 0.000000] Booting paravirtualized kernel on KVM [ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns [ 0.000000] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1 [ 0.000000] percpu: Embedded 63 pages/cpu s221184 r8192 d28672 u524288 [ 0.000000] kvm-guest: PV spinlocks enabled [ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1059606 [ 0.000000] Policy zone: Normal [ 0.000000] Kernel command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] Specific versions of hardware are certified with Red Hat Enterprise Linux 8. Please see the list of hardware certified with Red Hat Enterprise Linux 8 at https://catalog.redhat.com. [ 0.000000] audit: disabled (until reboot) [ 0.000000] software IO TLB: area num 4. [ 0.000000] Memory: 2829652K/4306352K available (18435K kernel code, 11221K rwdata, 7248K rodata, 2908K init, 18040K bss, 524580K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] ftrace: allocating 41240 entries in 162 pages [ 0.000000] ftrace: allocated 162 pages with 3 groups [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] rcu: RCU event tracing is enabled. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ 0.000000] rcu: RCU callback double-/use-after-free debug enabled. [ 0.000000] Rude variant of Tasks RCU enabled. [ 0.000000] Tracing variant of Tasks RCU enabled. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 0.000000] NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16 [ 0.000000] random: get_random_bytes called from start_kernel+0x622/0x9a8 with crng_init=0 [ 0.001000] Console: colour *CGA 80x25 [ 0.001000] printk: console [ttyS1] enabled [ 0.001000] ACPI: Core revision 20220331 [ 0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.001009] APIC: Switch to symmetric I/O mode setup [ 0.003165] x2apic enabled [ 0.004007] Switched APIC routing to physical x2apic. [ 0.005014] kvm-guest: setup PV IPIs [ 0.009491] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.010000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.010020] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.011012] pid_max: default: 32768 minimum: 301 [ 0.013218] LSM: Security Framework initializing [ 0.014039] Yama: becoming mindful. [ 0.015025] SELinux: Initializing. [ 0.015930] *** VALIDATE selinux *** [ 0.022627] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.027257] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.028132] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.029088] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.030085] *** VALIDATE tmpfs *** [ 0.031367] *** VALIDATE proc *** [ 0.032153] *** VALIDATE cgroup *** [ 0.033004] *** VALIDATE cgroup2 *** [ 0.035045] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.036100] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.037003] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.038023] Spectre V2 : User space: Vulnerable [ 0.039005] Speculative Store Bypass: Vulnerable [ 0.041896] debug: unmapping init [mem 0xffffffff9b459000-0xffffffff9b460fff] [ 0.043833] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.044479] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.045014] ... version: 2 [ 0.045966] ... bit width: 48 [ 0.046012] ... generic registers: 4 [ 0.046834] ... value mask: 0000ffffffffffff [ 0.047009] ... max period: 00007fffffffffff [ 0.048008] ... fixed-purpose events: 3 [ 0.048974] ... event mask: 000000070000000f [ 0.050205] rcu: Hierarchical SRCU implementation. [ 0.052200] smp: Bringing up secondary CPUs ... [ 0.053470] x86: Booting SMP configuration: [ 0.054024] .... node #0, CPUs: #1 #2 #3 [ 0.061523] smp: Brought up 1 node, 4 CPUs [ 0.063008] smpboot: Max logical packages: 1 [ 0.064007] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.132000] node 0 deferred pages initialised in 65ms [ 0.138018] devtmpfs: initialized [ 0.139423] x86/mm: Memory block size: 128MB [ 0.143412] gcov: version magic: 0x41383552 [ 0.147191] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.148071] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.150202] pinctrl core: initialized pinctrl subsystem [ 0.151314] [ 0.153014] ************************************************************* [ 0.154014] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.155016] ** ** [ 0.156018] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.157016] ** ** [ 0.158014] ** This means that this kernel is built to expose internal ** [ 0.159016] ** IOMMU data structures, which may compromise security on ** [ 0.160018] ** your system. ** [ 0.161018] ** ** [ 0.162016] ** If you see this message and you are not debugging the ** [ 0.163417] ** kernel, report this immediately to your vendor! ** [ 0.164013] ** ** [ 0.165015] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.166013] ************************************************************* [ 0.168101] NET: Registered protocol family 16 [ 0.169555] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.170074] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.171062] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.172758] cpuidle: using governor menu [ 0.175012] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.177778] PCI: Using configuration type 1 for base access [ 0.180142] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.187506] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.188000] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.189770] cryptd: max_cpu_qlen set to 1000 [ 0.192273] ACPI: Added _OSI(Module Device) [ 0.194013] ACPI: Added _OSI(Processor Device) [ 0.195011] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.197087] ACPI: Added _OSI(Processor Aggregator Device) [ 0.203552] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.211246] ACPI: Interpreter enabled [ 0.212051] ACPI: PM: (supports S0 S3 S4 S5) [ 0.214010] ACPI: Using IOAPIC for interrupt routing [ 0.216102] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.219378] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.231974] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.233031] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.235016] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.239075] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.244684] acpiphp: Slot [2] registered [ 0.245317] acpiphp: Slot [5] registered [ 0.247144] acpiphp: Slot [6] registered [ 0.249168] acpiphp: Slot [7] registered [ 0.250163] acpiphp: Slot [8] registered [ 0.252158] acpiphp: Slot [9] registered [ 0.253099] acpiphp: Slot [10] registered [ 0.255129] acpiphp: Slot [3] registered [ 0.256073] acpiphp: Slot [4] registered [ 0.258074] acpiphp: Slot [11] registered [ 0.259306] acpiphp: Slot [12] registered [ 0.261120] acpiphp: Slot [13] registered [ 0.262315] acpiphp: Slot [14] registered [ 0.264085] acpiphp: Slot [15] registered [ 0.266159] acpiphp: Slot [16] registered [ 0.267094] acpiphp: Slot [17] registered [ 0.269110] acpiphp: Slot [18] registered [ 0.270122] acpiphp: Slot [19] registered [ 0.272168] acpiphp: Slot [20] registered [ 0.274110] acpiphp: Slot [21] registered [ 0.275099] acpiphp: Slot [22] registered [ 0.277086] acpiphp: Slot [23] registered [ 0.278090] acpiphp: Slot [24] registered [ 0.280093] acpiphp: Slot [25] registered [ 0.281208] acpiphp: Slot [26] registered [ 0.283096] acpiphp: Slot [27] registered [ 0.285100] acpiphp: Slot [28] registered [ 0.286082] acpiphp: Slot [29] registered [ 0.288098] acpiphp: Slot [30] registered [ 0.289077] acpiphp: Slot [31] registered [ 0.291072] PCI host bridge to bus 0000:00 [ 0.292017] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.295021] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.297019] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.299031] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.302033] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.305047] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.307301] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.310345] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.314385] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.328015] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.332159] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.335016] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.344049] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.359020] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.371031] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.375765] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.378030] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.385234] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.393000] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.407101] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.415016] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.421009] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.429019] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.436016] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.454018] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.466912] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.473013] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.481013] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.502018] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.515775] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.522016] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.531013] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.549018] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.560012] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.567015] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.574015] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.592020] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.601736] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.613015] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.622015] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.638028] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 0.647881] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.651013] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.661017] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.678026] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 0.688597] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.689488] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.692525] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.694468] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.697378] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.701031] iommu: Default domain type: Passthrough [ 0.703603] SCSI subsystem initialized [ 0.706156] ACPI: bus type USB registered [ 0.707000] usbcore: registered new interface driver usbfs [ 0.709113] usbcore: registered new interface driver hub [ 0.711124] usbcore: registered new device driver usb [ 0.713176] pps_core: LinuxPPS API ver. 1 registered [ 0.715012] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.718055] PTP clock support registered [ 0.720351] EDAC MC: Ver: 3.0.0 [ 0.721049] PCI: Using ACPI for IRQ routing [ 0.723440] NetLabel: Initializing [ 0.725011] NetLabel: domain hash size = 128 [ 0.727010] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.733452] NetLabel: unlabeled traffic allowed by default [ 0.738131] vgaarb: loaded [ 0.740581] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.744022] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.751000] clocksource: Switched to clocksource kvm-clock [ 0.984009] VFS: Disk quotas dquot_6.6.0 [ 0.987850] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.996374] *** VALIDATE ramfs *** [ 0.999585] *** VALIDATE hugetlbfs *** [ 1.005325] pnp: PnP ACPI init [ 1.013832] pnp: PnP ACPI: found 6 devices [ 1.043153] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 1.046606] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 1.048765] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 1.050975] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 1.053275] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 1.055578] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 1.058424] NET: Registered protocol family 2 [ 1.061198] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 1.066645] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 1.070405] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 1.075704] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 1.079148] TCP: Hash tables configured (established 65536 bind 65536) [ 1.082207] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 1.085456] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 1.088383] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 1.091400] NET: Registered protocol family 1 [ 1.096878] RPC: Registered named UNIX socket transport module. [ 1.102163] RPC: Registered udp transport module. [ 1.107281] RPC: Registered tcp transport module. [ 1.108837] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 1.111228] NET: Registered protocol family 44 [ 1.112666] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 1.114807] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 1.117111] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 1.119578] PCI: CLS 0 bytes, default 64 [ 1.121282] Unpacking initramfs... [ 3.781270] debug: unmapping init [mem 0xffff8b3a3cc54000-0xffff8b3a3ffbffff] [ 3.802409] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 3.805702] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 3.810726] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 4.516341] Initialise system trusted keyrings [ 4.518474] Key type blacklist registered [ 4.520870] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 4.532391] zbud: loaded [ 4.536677] *** VALIDATE nfs *** [ 4.538615] *** VALIDATE nfs4 *** [ 4.540824] pstore: using deflate compression [ 4.546216] Platform Keyring initialized [ 4.694351] NET: Registered protocol family 38 [ 4.697160] Key type asymmetric registered [ 4.700093] Asymmetric key parser 'x509' registered [ 4.702566] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 4.706366] io scheduler mq-deadline registered [ 4.708232] io scheduler kyber registered [ 4.711557] io scheduler bfq registered [ 4.715246] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 4.720521] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 4.724329] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 4.727649] ACPI: Power Button [PWRF] [ 4.734468] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 4.743749] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 4.758039] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 4.766347] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 4.784232] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 4.813838] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 4.843919] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 4.848616] Non-volatile memory driver v1.3 [ 4.850111] Linux agpgart interface v0.103 [ 4.884244] virtio_blk virtio1: [vda] 67992 512-byte logical blocks (34.8 MB/33.2 MiB) [ 4.887536] vda: detected capacity change from 0 to 34811904 [ 4.909491] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 4.913615] vdb: detected capacity change from 0 to 1073741824 [ 4.936931] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 4.941446] vdc: detected capacity change from 0 to 2621440000 [ 4.960413] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 4.963730] vdd: detected capacity change from 0 to 2621440000 [ 4.977784] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 4.980623] vde: detected capacity change from 0 to 4294967296 [ 4.998513] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 5.002344] vdf: detected capacity change from 0 to 4294967296 [ 5.008544] libphy: Fixed MDIO Bus: probed [ 5.021644] usbcore: registered new interface driver usbserial_generic [ 5.024079] usbserial: USB Serial support registered for generic [ 5.026152] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 5.030289] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 5.031766] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 5.034325] mousedev: PS/2 mouse device common for all mice [ 5.037395] rtc_cmos 00:05: RTC can wake from S4 [ 5.038144] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 5.040188] rtc_cmos 00:05: registered as rtc0 [ 5.044995] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 5.047459] intel_pstate: CPU model not supported [ 5.048440] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 5.055116] hid: raw HID events driver (C) Jiri Kosina [ 5.056569] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 5.057877] usbcore: registered new interface driver usbhid [ 5.062327] usbhid: USB HID core driver [ 5.063458] drop_monitor: Initializing network drop monitor service [ 5.065389] Initializing XFRM netlink socket [ 5.067025] NET: Registered protocol family 10 [ 5.069617] Segment Routing with IPv6 [ 5.070768] NET: Registered protocol family 17 [ 5.072611] mpls_gso: MPLS GSO support [ 5.077834] RAS: Correctable Errors collector initialized. [ 5.079937] AVX version of gcm_enc/dec engaged. [ 5.081202] AES CTR mode by8 optimization enabled [ 5.159760] sched_clock: Marking stable (5159626644, 0)->(6204833175, -1045206531) [ 5.163397] registered taskstats version 1 [ 5.165733] Loading compiled-in X.509 certificates [ 5.167379] zswap: loaded using pool lzo/zbud [ 5.196444] Key type big_key registered [ 5.211552] Key type encrypted registered [ 5.213534] ima: No TPM chip found, activating TPM-bypass! [ 5.215474] ima: Allocated hash algorithm: sha1 [ 5.217202] ima: No architecture policies found [ 5.218563] evm: Initialising EVM extended attributes: [ 5.221281] evm: security.selinux [ 5.222440] evm: security.ima [ 5.223530] evm: security.capability [ 5.224991] evm: HMAC attrs: 0x1 [ 5.227519] rtc_cmos 00:05: setting system clock to 2026-01-08 02:30:38 UTC (1767839438) [ 5.235628] debug: unmapping init [mem 0xffffffff9c403000-0xffffffff9c5fffff] [ 5.239955] debug: unmapping init [mem 0xffffffff9b182000-0xffffffff9b458fff] [ 5.248212] Write protecting the kernel read-only data: 28672k [ 5.252377] debug: unmapping init [mem 0xffffffff99803000-0xffffffff999fffff] [ 5.255125] debug: unmapping init [mem 0xffffffff9a114000-0xffffffff9a1fffff] [ 5.293137] 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) [ 5.303246] systemd[1]: Detected virtualization kvm. [ 5.304192] systemd[1]: Detected architecture x86-64. [ 5.305770] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 5.356022] systemd[1]: No hostname configured. [ 5.368123] systemd[1]: Set hostname to . [ 5.395469] random: systemd: uninitialized urandom read (16 bytes read) [ 5.398532] systemd[1]: Initializing machine ID from random generator. [ 5.527681] random: ln: uninitialized urandom read (6 bytes read) [ 5.983329] random: systemd: uninitialized urandom read (16 bytes read) [ 5.986282] systemd[1]: Started Dispatch Password Requests to Console Directory Watch. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ 5.994351] systemd[1]: Reached target Local Encrypted Volumes. [ OK ] Reached target Local Encrypted Volumes. [ 5.999195] systemd[1]: Listening on Journal Socket. [ OK ] Listening on Journal Socket. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Reached target Initrd Root Device. [ OK ] Reached target Swap. [ OK ] Reached target Timers. [ OK ] Reached target Slices. [ OK ] Listening on udev Kernel Socket. Starting Setup Virtual Console... [ OK ] Reached target Local File Systems. Starting Apply Kernel Variables... [ OK ] Reached target Paths. [ OK ] Listening on udev Control Socket. [ OK ] Listening on Journal Socket (/dev/log). [ OK ] Reached target Sockets. Starting Journal Service... Starting Create Volatile Files and Directories... [ OK ] Started Memstrack Anylazing Service. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Setup Virtual Console. [ OK ] Started Apply Kernel Variables. [ OK ] Started Create Volatile Files and Directories. Starting dracut cmdline hook... Starting Create Static Device Nodes in /dev... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started Journal Service. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 6.956528] device-mapper: uevent: version 1.0.3 [ 6.958579] 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... [ 8.390743] virtio_net virtio0 ens2: renamed from eth0 [ 8.418377] random: fast init done [ 9.112339] scsi host0: ata_piix [ 9.180263] scsi host1: ata_piix [ 9.181713] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 9.185752] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 13.735588] random: crng init done [ 13.736800] random: 7 urandom warning(s) missed due to ratelimiting [ 16.703044] dracut-initqueue[588]: 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... [ 17.485194] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped target Timers. [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Remote File Systems. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Slices. [ OK ] Stopped target Paths. [ OK ] Stopped target Sockets. [ OK ] Stopped target System Initialization. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped target Swap. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. Stopping udev Kernel Device Manager... [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Closed udev Kernel Socket. [ OK ] Closed udev Control Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 20.004942] printk: systemd: 26 output lines suppressed due to ratelimiting [ 21.056164] SELinux: Disabled at runtime. [ 21.137624] 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) [ 21.150969] systemd[1]: Detected virtualization kvm. [ 21.153372] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 22.580232] systemd[1]: initrd-switch-root.service: Succeeded. [ 22.585044] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 22.592473] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 22.598223] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 22.602497] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 22.615948] systemd[1]: Starting Journal Service... Starting Journal Service... [ 22.666783] systemd[1]: Created slice system-getty.slice. [ OK ] Created slice system-getty.slice. [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Reached target rpc_pipefs.target. [ OK ] Listening on Process Core Dump Socket. [ OK ] Started Forward Password Requests to Wall Directory Watch. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. Mounting Kernel Debug File System... Activating swap /dev/disk/by-label/SWAP... Starting Apply Kernel Variables... [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Reached target RPC Port Mapper. [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Created slice system-sshd\x2dkeygen.slice. [ 22.958178] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS Mounting Huge Pages File System... [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd Root File System. [ OK ] Stopped target Initrd File Systems. [ OK ] Listening on udev Kernel Socket. Mounting POSIX Message Queue File System... [ OK ] Created slice User and Session Slice. [ OK ] Reached target Slices. Starting Remount Root and Kernel File Systems... [ OK ] Listening on udev Control Socket. Starting udev Coldplug all Devices... [ OK ] Started Journal Service. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Mounted Kernel Debug File System. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Started Apply Kernel Variables. [ OK ] Mounted Huge Pages File System. [ OK ] Mounted POSIX Message Queue File System. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. Starting Configure read-only root support... [ OK ] Reached target Swap. Starting Create Static Device Nodes in /dev... Starting Flush Journal to Persistent Storage... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Reached target Local File Systems (Pre). Mounting /mnt... Mounting /home/green/git/lustre-release... Starting udev Kernel Device Manager... [ OK ] Started udev Coldplug all Devices. [ OK ] Mounted /mnt. [ 24.197533] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 25.498238] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 25.661514] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 26.354570] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 26.816217] EDAC sbridge: Ver: 1.1.2 [* ] A start job is running for Configur…-only root support (7s / no limit) [** ] A start job is running for Configur…-only root support (8s / no limit)[ 30.845775] Key type dns_resolver registered [*** ] A start job is running for Configur…-only root support (8s / no limit)[ 31.565210] NFS: Registering the id_resolver key type [ 31.569696] Key type id_resolver registered [ 31.572559] Key type id_legacy registered [ *** ] A start job is running for Configur…-only root support (9s / no limit) [ OK ] Started Configure read-only root support. Starting Load/Save Random Seed... [ OK ] Reached target Local File Systems. Starting Mark the need to relabel after reboot... Starting Rebuild Dynamic Linker Cache... Starting Create Volatile Files and Directories... [ OK ] Started Load/Save Random Seed. [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Create Volatile Files and Directories. Starting RPC Bind... Starting Update UTMP about System Boot/Shutdown... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Started dnf makecache --timer. [ OK ] Reached target Timers. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. [ OK ] Reached target sshd-keygen.target. Starting Restore /run/initramfs on shutdown... Starting Login Service... [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Started irqbalance daemon. [ OK ] Started D-Bus System Message Bus. Starting Network Manager... [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Login Service. [ OK ] Started Network Manager. Starting Network Manager Wait Online... [ OK ] Reached target Network. Starting GSSAPI Proxy Daemon... Starting OpenSSH server daemon... Starting Dynamic System Tuning Daemon... Starting Hostname Service... [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Started OpenSSH server daemon. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... [ OK ] Started Permit User Sessions. [ OK ] Started Command Scheduler. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Serial Getty on ttyS1. [ OK ] Started Getty on tty1. [ OK ] Reached target Login Prompts. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting System Logging Service... Starting Crash recovery kernel arming... Starting Notify NFS peers of a restart... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Starting Authorization Manager... Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg214-server login: [ 51.058195] spl: loading out-of-tree module taints kernel. [ 54.164281] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 61.047775] alg: No test for adler32 (adler32-zlib) [ 61.799520] Key type ._llcrypt registered [ 61.801356] Key type .llcrypt registered [ 61.878136] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_hostid [ 69.987413] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing load_modules_local [ 70.639275] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 70.910821] Lustre: Lustre: Build Version: 2.15.8_1_g5e2d639 [ 71.226729] LNet: Added LNI 192.168.202.114@tcp [8/256/0/180] [ 71.228560] LNet: Accept secure, port 988 [ 72.865035] Key type lgssc registered [ 73.416380] Lustre: Echo OBD driver; http://www.lustre.org/ [ 77.591868] vdc: vdc1 vdc9 [ 82.411941] vdd: vdd1 vdd9 [ 86.724372] vde: vde1 vde9 [ 91.201924] vdf: vdf1 vdf9 [ 99.082239] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing load_modules_local [ 103.567489] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall in log lustre-MDT0000 [ 103.698505] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space: rc = -61 [ 103.738783] Lustre: lustre-MDT0000: new disk, initializing [ 103.874515] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 103.900184] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 105.746579] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 110.630466] Lustre: Setting parameter lustre-MDT0001.mdt.identity_upcall in log lustre-MDT0001 [ 110.690102] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space: rc = -61 [ 110.694337] Lustre: Skipped 1 previous similar message [ 110.726265] Lustre: lustre-MDT0001: Not available for connect from 0@lo (not set up) [ 110.751358] Lustre: lustre-MDT0001: new disk, initializing [ 110.923918] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 110.956752] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 110.964424] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 113.191048] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 118.228886] Lustre: lustre-OST0000: new disk, initializing [ 118.231171] Lustre: srv-lustre-OST0000: No data found on store. Initialize space: rc = -61 [ 118.267410] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 120.176965] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 125.086267] Lustre: lustre-OST0001: new disk, initializing [ 125.088727] Lustre: srv-lustre-OST0001: No data found on store. Initialize space: rc = -61 [ 125.124296] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 126.305759] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 126.309785] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 126.991745] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 133.597462] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 138.445702] Lustre: Modifying parameter general.lod.*.mdt_hash in log params [ 145.346924] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing check_logdir /tmp/testlogs/ [ 147.550463] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing yml_node [ 149.806763] Lustre: DEBUG MARKER: Client: 2.15.8.1 [ 151.151678] Lustre: DEBUG MARKER: MDS: 2.15.8.1 [ 152.472371] Lustre: DEBUG MARKER: OSS: 2.15.8.1 [ 153.297348] Lustre: DEBUG MARKER: -----============= acceptance-small: replay-single ============----- Wed Jan 7 21:33:06 EST 2026 [ 157.464900] Lustre: DEBUG MARKER: excepting tests: 59 [ 160.761920] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing check_config_client /mnt/lustre [ 170.237289] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 171.870283] Lustre: Modifying parameter general.lod.*.mdt_hash in log params [ 173.874151] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 174.744365] Lustre: DEBUG MARKER: == replay-single test 0a: empty replay =================== 21:33:28 (1767839608) [ 176.315145] LustreError: 12234:0:(osd_handler.c:698:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 176.778694] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 177.746372] Lustre: Failing over lustre-MDT0000 [ 177.865648] Lustre: server umount lustre-MDT0000 complete [ 181.713541] LustreError: 137-5: lustre-MDT0000_UUID: not available for connect from 192.168.202.14@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 182.752606] LustreError: 11-0: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 182.752819] 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 [ 182.754727] LustreError: 137-5: lustre-MDT0000_UUID: 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. [ 182.771743] Lustre: Skipped 3 previous similar messages [ 186.827364] LustreError: 137-5: lustre-MDT0000_UUID: not available for connect from 192.168.202.14@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 186.834197] LustreError: Skipped 3 previous similar messages [ 188.888202] LustreError: 137-5: lustre-MDT0000_UUID: not available for connect from 192.168.202.14@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 188.894581] LustreError: Skipped 4 previous similar messages [ 189.920709] Lustre: 3140:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1767839616/real 1767839616] req@00000000e1ce49c3 x1853714075780864/t0(0) o400->MGC192.168.202.114@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1767839623 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:4.0' [ 189.932541] LustreError: 166-1: MGC192.168.202.114@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 193.997773] LustreError: 137-5: lustre-MDT0000_UUID: not available for connect from 192.168.202.14@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 194.012620] LustreError: Skipped 4 previous similar messages [ 196.065879] Lustre: Evicted from MGS (at 192.168.202.114@tcp) after server handle changed from 0x50fb2a7c8caaaac6 to 0x50fb2a7c8caab110 [ 196.073922] Lustre: MGC192.168.202.114@tcp: Connection restored to (at 0@lo) [ 196.214441] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 196.906437] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 198.137443] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 201.189767] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to (at 0@lo) [ 201.204622] Lustre: lustre-MDT0000: Recovery over after 0:05, of 2 clients 2 recovered and 0 were evicted. [ 203.905811] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 204.552814] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 208.582266] Lustre: DEBUG MARKER: == replay-single test 0b: ensure object created after recover exists. (3284) ========================================================== 21:34:01 (1767839641) [ 209.525946] Lustre: Failing over lustre-OST0000 [ 209.562493] Lustre: server umount lustre-OST0000 complete [ 210.387509] LustreError: 137-5: lustre-OST0000_UUID: not available for connect from 192.168.202.14@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 210.395160] LustreError: Skipped 9 previous similar messages [ 211.424877] LustreError: 11-0: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 211.428747] 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 [ 222.862681] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 224.556553] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 224.618183] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 224.690284] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 192.168.202.114@tcp (at 0@lo) [ 224.690358] Lustre: lustre-OST0000: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [ 224.692671] Lustre: lustre-OST0000: deleting orphan objects from 0x0:34 to 0x0:65 [ 224.695027] Lustre: Skipped 3 previous similar messages [ 229.233383] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 229.971226] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 234.161467] Lustre: DEBUG MARKER: == replay-single test 0c: check replay-barrier =========== 21:34:27 (1767839667) [ 235.426415] LustreError: 15276:0:(osd_handler.c:698:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 235.827759] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 236.753906] Lustre: Failing over lustre-MDT0000 [ 236.850606] Lustre: server umount lustre-MDT0000 complete [ 237.023912] LustreError: 11-0: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 237.028777] Lustre: lustre-MDT0000-osp-MDT0001: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 237.038178] Lustre: Skipped 1 previous similar message [ 237.041621] LustreError: 137-5: lustre-MDT0000_UUID: 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. [ 237.051883] LustreError: Skipped 8 previous similar messages [ 245.151142] Lustre: 3139:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1767839671/real 1767839671] req@00000000734aef43 x1853714075801728/t0(0) o400->MGC192.168.202.114@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1767839678 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:1.0' [ 245.162873] LustreError: 166-1: MGC192.168.202.114@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 251.363134] Lustre: Evicted from MGS (at 192.168.202.114@tcp) after server handle changed from 0x50fb2a7c8caab110 to 0x50fb2a7c8caabae1 [ 251.370233] Lustre: MGC192.168.202.114@tcp: Connection restored to 192.168.202.114@tcp (at 0@lo) [ 251.373361] Lustre: Skipped 1 previous similar message [ 251.546728] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 253.354389] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 254.392110] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 254.396531] Lustre: lustre-MDT0000: Denying connection for new client b11d34f7-1395-400f-a032-d7a23d25a611 (at 192.168.202.14@tcp), waiting for 2 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:59 [ 256.996277] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to (at 0@lo) [ 259.528528] Lustre: lustre-MDT0000: Denying connection for new client b11d34f7-1395-400f-a032-d7a23d25a611 (at 192.168.202.14@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 1:00 [ 264.648148] Lustre: lustre-MDT0000: Denying connection for new client b11d34f7-1395-400f-a032-d7a23d25a611 (at 192.168.202.14@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 0:55 [ 269.771080] Lustre: lustre-MDT0000: Denying connection for new client b11d34f7-1395-400f-a032-d7a23d25a611 (at 192.168.202.14@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 0:50 [ 274.888925] Lustre: lustre-MDT0000: Denying connection for new client b11d34f7-1395-400f-a032-d7a23d25a611 (at 192.168.202.14@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 0:45 [ 285.128370] Lustre: lustre-MDT0000: Denying connection for new client b11d34f7-1395-400f-a032-d7a23d25a611 (at 192.168.202.14@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 0:34 [ 285.135797] Lustre: Skipped 1 previous similar message [ 305.610096] Lustre: lustre-MDT0000: Denying connection for new client b11d34f7-1395-400f-a032-d7a23d25a611 (at 192.168.202.14@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 0:14 [ 305.619045] Lustre: Skipped 3 previous similar messages [ 320.000173] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 320.003506] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 320.029077] Lustre: lustre-MDT0000: Recovery over after 1:06, of 2 clients 1 recovered and 1 was evicted. [ 320.029132] Lustre: lustre-MDT0000-osp-MDT0001: Connection restored to (at 0@lo) [ 320.038700] Lustre: Skipped 2 previous similar messages [ 320.050105] Lustre: lustre-OST0001: deleting orphan objects from 0x0:44 to 0x0:65 [ 320.050559] Lustre: lustre-OST0000: deleting orphan objects from 0x0:76 to 0x0:97 [ 325.213892] Lustre: DEBUG MARKER: == replay-single test 0d: expired recovery with no clients ========================================================== 21:35:58 (1767839758) [ 326.405515] LustreError: 16700:0:(osd_handler.c:698:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 326.775392] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 327.674349] Lustre: Failing over lustre-MDT0000 [ 327.787160] Lustre: server umount lustre-MDT0000 complete [ 328.676422] 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 [ 328.677722] LustreError: 137-5: lustre-MDT0000_UUID: 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. [ 328.682598] Lustre: Skipped 5 previous similar messages [ 328.697449] LustreError: Skipped 23 previous similar messages [ 334.751431] Lustre: 3141:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1767839761/real 1767839761] req@0000000066ae6d35 x1853714075825216/t0(0) o400->MGC192.168.202.114@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1767839768 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:0.0' [ 334.770396] LustreError: 166-1: MGC192.168.202.114@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 352.227510] Lustre: Evicted from MGS (at 192.168.202.114@tcp) after server handle changed from 0x50fb2a7c8caabae1 to 0x50fb2a7c8caabf25 [ 352.233668] Lustre: MGC192.168.202.114@tcp: Connection restored to (at 0@lo) [ 352.393241] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 354.277155] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 355.149849] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 355.153946] Lustre: lustre-MDT0000: Denying connection for new client 887bfe44-15a6-4ae3-80bd-930b965868a1 (at 192.168.202.14@tcp), waiting for 2 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:59 [ 355.159575] Lustre: Skipped 2 previous similar messages [ 421.000183] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 421.002879] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 421.016796] Lustre: lustre-MDT0000: Recovery over after 1:06, of 2 clients 1 recovered and 1 was evicted. [ 421.016863] Lustre: lustre-MDT0000-osp-MDT0001: Connection restored to (at 0@lo) [ 421.022268] Lustre: Skipped 3 previous similar messages [ 421.034478] Lustre: lustre-OST0000: deleting orphan objects from 0x0:76 to 0x0:129 [ 421.035533] Lustre: lustre-OST0001: deleting orphan objects from 0x0:44 to 0x0:97 [ 425.634555] Lustre: DEBUG MARKER: == replay-single test 1: simple create =================== 21:37:39 (1767839859) [ 426.767046] LustreError: 18134:0:(osd_handler.c:698:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 427.137900] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 427.954347] Lustre: Failing over lustre-MDT0000 [ 428.096908] Lustre: server umount lustre-MDT0000 complete [ 429.535517] Lustre: lustre-MDT0000-osp-MDT0001: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 429.536353] LustreError: 137-5: lustre-MDT0000_UUID: 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. [ 429.539825] Lustre: Skipped 4 previous similar messages [ 429.545850] LustreError: Skipped 30 previous similar messages [ 436.703232] Lustre: 3139:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1767839862/real 1767839862] req@0000000068a7786e x1853714075849344/t0(0) o400->MGC192.168.202.114@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1767839869 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:0.0' [ 436.714679] LustreError: 166-1: MGC192.168.202.114@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 441.825726] Lustre: Evicted from MGS (at 192.168.202.114@tcp) after server handle changed from 0x50fb2a7c8caabf25 to 0x50fb2a7c8caac3a1 [ 441.944598] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 443.698364] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 444.361290] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 446.999888] Lustre: lustre-MDT0000: Recovery over after 0:02, of 2 clients 2 recovered and 0 were evicted. [ 447.022637] Lustre: lustre-OST0001: deleting orphan objects from 0x0:44 to 0x0:129 [ 447.024696] Lustre: lustre-OST0000: deleting orphan objects from 0x0:76 to 0x0:161 [ 449.588720] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 450.286433] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 454.226680] Lustre: DEBUG MARKER: == replay-single test 2a: touch ========================== 21:38:07 (1767839887) [ 455.395060] LustreError: 19748:0:(osd_handler.c:698:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 455.780305] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 456.545505] Lustre: Failing over lustre-MDT0000 [ 456.699757] Lustre: server umount lustre-MDT0000 complete [ 457.183580] Lustre: lustre-MDT0000-lwp-MDT0001: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 457.184100] LustreError: 11-0: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 457.193120] Lustre: Skipped 2 previous similar messages [ 464.351199] Lustre: 3139:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1767839890/real 1767839890] req@0000000081f60e79 x1853714075859968/t0(0) o400->MGC192.168.202.114@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1767839897 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:2.0' [ 464.367693] LustreError: 166-1: MGC192.168.202.114@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 470.496188] Lustre: Evicted from MGS (at 192.168.202.114@tcp) after server handle changed from 0x50fb2a7c8caac3a1 to 0x50fb2a7c8caac878 [ 472.008260] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 472.255304] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 475.668876] Lustre: lustre-MDT0000: Recovery over after 0:03, of 2 clients 2 recovered and 0 were evicted. [ 475.685273] Lustre: lustre-OST0000: deleting orphan objects from 0x0:76 to 0x0:193 [ 475.685274] Lustre: lustre-OST0001: deleting orphan objects from 0x0:131 to 0x0:161 [ 477.639159] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 478.224302] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 482.032401] Lustre: DEBUG MARKER: == replay-single test 2b: touch ========================== 21:38:35 (1767839915) [ 483.238482] LustreError: 21372:0:(osd_handler.c:698:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 483.588042] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 484.373032] Lustre: Failing over lustre-MDT0000 [ 484.503423] Lustre: server umount lustre-MDT0000 complete [ 485.856478] LustreError: 11-0: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 485.856506] Lustre: lustre-MDT0000-osp-MDT0001: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 485.866577] Lustre: Skipped 3 previous similar messages [ 493.023161] Lustre: 3142:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1767839919/real 1767839919] req@0000000023b4bc97 x1853714075870976/t0(0) o400->MGC192.168.202.114@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1767839926 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:0.0' [ 493.032586] LustreError: 166-1: MGC192.168.202.114@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 499.172360] Lustre: Evicted from MGS (at 192.168.202.114@tcp) after server handle changed from 0x50fb2a7c8caac878 to 0x50fb2a7c8caacd79 [ 499.180434] Lustre: MGC192.168.202.114@tcp: Connection restored to (at 0@lo) [ 499.184089] Lustre: Skipped 10 previous similar messages [ 499.656095] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 501.114984] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 504.339092] Lustre: lustre-MDT0000: Recovery over after 0:05, of 2 clients 2 recovered and 0 were evicted. [ 504.356995] Lustre: lustre-OST0001: deleting orphan objects from 0x0:131 to 0x0:193 [ 504.357207] Lustre: lustre-OST0000: deleting orphan objects from 0x0:195 to 0x0:225 [ 506.692539] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 507.317472] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 511.299681] Lustre: DEBUG MARKER: == replay-single test 2c: setstripe replay =============== 21:39:04 (1767839944) [ 512.445132] LustreError: 23006:0:(osd_handler.c:698:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 512.808345] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 514.529695] LustreError: 11-0: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 521.695604] Lustre: 3140:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1767839947/real 1767839947] req@00000000aa9fbfa8 x1853714075882304/t0(0) o400->MGC192.168.202.114@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1767839954 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:1.0' [ 521.704991] LustreError: 166-1: MGC192.168.202.114@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 538.080814] Lustre: Evicted from MGS (at 192.168.202.114@tcp) after server handle changed from 0x50fb2a7c8caacd79 to 0x50fb2a7c8caad28f [ 539.487588] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 539.914820] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 543.245392] Lustre: lustre-MDT0000: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 543.263564] Lustre: lustre-OST0001: deleting orphan objects from 0x0:195 to 0x0:225 [ 543.263567] Lustre: lustre-OST0000: deleting orphan objects from 0x0:227 to 0x0:257 [ 545.255940] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 545.833076] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 549.770241] Lustre: DEBUG MARKER: == replay-single test 2d: setdirstripe replay ============ 21:39:43 (1767839983) [ 550.975276] LustreError: 24642:0:(osd_handler.c:698:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 551.366328] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 552.298208] Lustre: Failing over lustre-MDT0000 [ 552.299571] Lustre: Skipped 1 previous similar message [ 552.507241] Lustre: server umount lustre-MDT0000 complete [ 552.509567] Lustre: Skipped 1 previous similar message [ 553.441516] 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 [ 553.442283] LustreError: 11-0: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 553.446658] Lustre: Skipped 7 previous similar messages [ 558.560205] LustreError: 137-5: lustre-MDT0000_UUID: 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. [ 558.566057] LustreError: Skipped 104 previous similar messages [ 560.543186] Lustre: 3140:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1767839986/real 1767839986] req@000000004943a92a x1853714075895168/t0(0) o400->MGC192.168.202.114@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1767839993 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:1.0' [ 560.556709] LustreError: 166-1: MGC192.168.202.114@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 566.752780] LustreError: 25240:0:(ldlm_resource.c:1127:ldlm_resource_complain()) MGC192.168.202.114@tcp: namespace resource [0x65727473756c:0x5:0x0].0x0 (00000000568d3356) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 568.442070] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 571.928909] Lustre: lustre-OST0001: deleting orphan objects from 0x0:195 to 0x0:257 [ 571.930370] Lustre: lustre-OST0000: deleting orphan objects from 0x0:227 to 0x0:289 [ 574.193682] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 574.864270] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 578.694092] Lustre: DEBUG MARKER: == replay-single test 2e: O_CREAT|O_EXCL create replay === 21:40:12 (1767840012) [ 579.105906] Lustre: *** cfs_fail_loc=13b, val=315*** [ 579.107688] Lustre: *** cfs_fail_loc=13b, val=2147483648*** [ 579.109899] LustreError: 6128:0:(ldlm_lib.c:3224:target_send_reply_msg()) @@@ dropping reply req@00000000ea82502d x1853714068465536/t38654705666(0) o35->887bfe44-15a6-4ae3-80bd-930b965868a1@192.168.202.14@tcp:723/0 lens 392/456 e 0 to 0 dl 1767840018 ref 1 fl Interpret:/0/0 rc 0/0 job:'openfile.0' [ 581.725291] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 582.608825] Lustre: lustre-MDT0000: Not available for connect from 192.168.202.14@tcp (stopping) [ 587.234262] LustreError: 11-0: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 600.549097] Lustre: Evicted from MGS (at 192.168.202.114@tcp) after server handle changed from 0x50fb2a7c8caad782 to 0x50fb2a7c8caadc44 [ 600.556030] Lustre: Skipped 1 previous similar message [ 600.708974] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 600.711699] Lustre: Skipped 4 previous similar messages [ 602.800959] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 606.255333] Lustre: lustre-OST0000: deleting orphan objects from 0x0:227 to 0x0:321 [ 606.256705] Lustre: lustre-OST0001: deleting orphan objects from 0x0:195 to 0x0:289 [ 606.259515] Lustre: 6128:0:(mdt_recovery.c:200:mdt_req_from_lrd()) @@@ restoring transno req@00000000aeb2d46a x1853714068465536/t38654705666(0) o35->887bfe44-15a6-4ae3-80bd-930b965868a1@192.168.202.14@tcp:750/0 lens 392/456 e 0 to 0 dl 1767840045 ref 1 fl Interpret:/2/0 rc 0/0 job:'openfile.0' [ 609.199168] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 610.021946] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 614.698614] Lustre: DEBUG MARKER: == replay-single test 3a: replay failed open(O_DIRECTORY) ========================================================== 21:40:47 (1767840047) [ 616.210684] LustreError: 27931:0:(osd_handler.c:698:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 616.213573] LustreError: 27931:0:(osd_handler.c:698:osd_ro()) Skipped 1 previous similar message [ 616.678606] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 617.550407] Lustre: Failing over lustre-MDT0000 [ 617.551988] Lustre: Skipped 1 previous similar message [ 617.747540] Lustre: server umount lustre-MDT0000 complete [ 617.750922] Lustre: Skipped 1 previous similar message [ 621.535686] Lustre: lustre-MDT0000-osp-MDT0001: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 621.541641] Lustre: Skipped 8 previous similar messages [ 628.687146] Lustre: 3141:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1767840054/real 1767840054] req@00000000600a61b2 x1853714075921280/t0(0) o400->MGC192.168.202.114@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1767840061 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:1.0' [ 628.696469] Lustre: 3141:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 628.699539] LustreError: 166-1: MGC192.168.202.114@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 628.705105] LustreError: Skipped 1 previous similar message [ 633.824696] Lustre: MGC192.168.202.114@tcp: Connection restored to (at 0@lo) [ 633.827827] Lustre: Skipped 19 previous similar messages [ 633.981048] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 634.825158] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 634.832241] Lustre: Skipped 2 previous similar messages [ 635.690585] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 638.989890] Lustre: lustre-MDT0000: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 638.995645] Lustre: Skipped 2 previous similar messages [ 639.010620] Lustre: lustre-OST0000: deleting orphan objects from 0x0:227 to 0x0:353 [ 639.011064] Lustre: lustre-OST0001: deleting orphan objects from 0x0:195 to 0x0:321 [ 641.520658] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 642.382390] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 646.412206] Lustre: DEBUG MARKER: == replay-single test 3b: replay failed open -ENOMEM ===== 21:41:19 (1767840079) [ 648.002599] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 648.407309] Lustre: *** cfs_fail_loc=114, val=0*** [ 654.306786] LustreError: 11-0: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 654.311738] LustreError: Skipped 1 previous similar message [ 667.105314] Lustre: Evicted from MGS (at 192.168.202.114@tcp) after server handle changed from 0x50fb2a7c8caae0d5 to 0x50fb2a7c8caae5b3 [ 667.109801] Lustre: Skipped 1 previous similar message [ 667.303669] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 669.027620] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 672.254919] Lustre: lustre-OST0000: deleting orphan objects from 0x0:227 to 0x0:385 [ 672.254920] Lustre: lustre-OST0001: deleting orphan objects from 0x0:195 to 0x0:353 [ 674.658678] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 675.347141] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 679.983461] Lustre: DEBUG MARKER: == replay-single test 3c: replay failed open -ENOMEM ===== 21:41:53 (1767840113) [ 681.818421] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 682.276128] Lustre: *** cfs_fail_loc=128, val=0*** [ 701.055960] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 702.641820] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 706.050127] Lustre: lustre-OST0001: deleting orphan objects from 0x0:195 to 0x0:385 [ 706.050878] Lustre: lustre-OST0000: deleting orphan objects from 0x0:227 to 0x0:417 [ 708.248375] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 708.946310] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 712.872561] Lustre: DEBUG MARKER: == replay-single test 4a: |x| 10 open(O_CREAT)s ========== 21:42:26 (1767840146) [ 714.488832] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 729.571453] LustreError: 33603:0:(ldlm_resource.c:1127:ldlm_resource_complain()) MGC192.168.202.114@tcp: namespace resource [0x65727473756c:0x5:0x0].0x0 (0000000009b092a5) refcount nonzero (2) after lock cleanup; forcing cleanup. [ 729.692960] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 731.280862] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 734.771377] Lustre: lustre-OST0001: deleting orphan objects from 0x0:391 to 0x0:417 [ 734.772674] Lustre: lustre-OST0000: deleting orphan objects from 0x0:423 to 0x0:449 [ 736.886396] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 737.534046] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 741.548045] Lustre: DEBUG MARKER: == replay-single test 4b: |x| rm 10 files ================ 21:42:54 (1767840174) [ 743.023660] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 758.362583] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 759.923751] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 763.438345] Lustre: lustre-OST0000: deleting orphan objects from 0x0:455 to 0x0:481 [ 763.438448] Lustre: lustre-OST0001: deleting orphan objects from 0x0:423 to 0x0:449 [ 765.566814] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 766.151597] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 769.698285] Lustre: DEBUG MARKER: == replay-single test 5: |x| 220 open(O_CREAT) =========== 21:43:23 (1767840203) [ 770.712156] LustreError: 36265:0:(osd_handler.c:698:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 770.715535] LustreError: 36265:0:(osd_handler.c:698:osd_ro()) Skipped 4 previous similar messages [ 771.052458] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 772.984279] Lustre: Failing over lustre-MDT0000 [ 772.985771] Lustre: Skipped 4 previous similar messages [ 773.134303] Lustre: server umount lustre-MDT0000 complete [ 773.136814] Lustre: Skipped 4 previous similar messages [ 773.599570] Lustre: lustre-MDT0000-osp-MDT0001: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 773.604312] Lustre: Skipped 17 previous similar messages [ 780.703136] Lustre: 3141:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1767840206/real 1767840206] req@000000002dc2955b x1853714075982720/t0(0) o400->MGC192.168.202.114@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1767840213 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:1.0' [ 780.712810] Lustre: 3141:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 4 previous similar messages [ 780.717129] LustreError: 166-1: MGC192.168.202.114@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 780.721744] LustreError: Skipped 4 previous similar messages [ 797.154081] Lustre: Evicted from MGS (at 192.168.202.114@tcp) after server handle changed from 0x50fb2a7c8caafab3 to 0x50fb2a7c8cab2419 [ 797.160377] Lustre: Skipped 3 previous similar messages [ 797.299099] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 797.643030] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 797.646213] Lustre: Skipped 4 previous similar messages [ 798.846572] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 803.078579] Lustre: lustre-MDT0000: Recovery over after 0:06, of 2 clients 2 recovered and 0 were evicted. [ 803.081457] Lustre: Skipped 4 previous similar messages [ 803.096404] Lustre: lustre-OST0000: deleting orphan objects from 0x0:592 to 0x0:609 [ 803.096670] Lustre: lustre-OST0001: deleting orphan objects from 0x0:560 to 0x0:577 [ 805.141604] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 805.728963] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 815.259728] Lustre: DEBUG MARKER: == replay-single test 6a: mkdir + contained create ======= 21:44:08 (1767840248) [ 816.727497] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 817.633563] LustreError: 137-5: lustre-MDT0000_UUID: 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. [ 817.639025] LustreError: Skipped 193 previous similar messages [ 836.223728] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 837.801267] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 841.248061] Lustre: lustre-OST0000: deleting orphan objects from 0x0:592 to 0x0:641 [ 841.248069] Lustre: lustre-OST0001: deleting orphan objects from 0x0:560 to 0x0:609 [ 843.328424] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 844.037605] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 849.633946] Lustre: DEBUG MARKER: == replay-single test 6b: |X| rmdir ====================== 21:44:43 (1767840283) [ 851.031983] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 868.835052] LustreError: 40156:0:(ldlm_resource.c:1127:ldlm_resource_complain()) MGC192.168.202.114@tcp: namespace resource [0x65727473756c:0x5:0x0].0x0 (00000000f28ed4a2) refcount nonzero (2) after lock cleanup; forcing cleanup. [ 868.947781] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 868.950635] Lustre: Skipped 7 previous similar messages [ 868.972423] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 870.454226] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 873.996148] Lustre: lustre-OST0000: deleting orphan objects from 0x0:592 to 0x0:673 [ 873.996153] Lustre: lustre-OST0001: deleting orphan objects from 0x0:560 to 0x0:641 [ 876.033961] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 876.573449] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 880.043906] Lustre: DEBUG MARKER: == replay-single test 7: mkdir |X| contained create ====== 21:45:13 (1767840313) [ 881.501465] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 884.192111] LustreError: 11-0: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 884.196528] LustreError: Skipped 4 previous similar messages [ 897.505344] Lustre: MGC192.168.202.114@tcp: Connection restored to (at 0@lo) [ 897.508582] Lustre: Skipped 39 previous similar messages [ 899.052902] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 902.685054] Lustre: lustre-OST0000: deleting orphan objects from 0x0:592 to 0x0:705 [ 902.686256] Lustre: lustre-OST0001: deleting orphan objects from 0x0:560 to 0x0:673 [ 904.762367] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 905.357724] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 908.937462] Lustre: DEBUG MARKER: == replay-single test 8: creat open |X| close ============ 21:45:42 (1767840342) [ 910.379616] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 926.177316] LustreError: 43421:0:(ldlm_resource.c:1127:ldlm_resource_complain()) MGC192.168.202.114@tcp: namespace resource [0x65727473756c:0x5:0x0].0x0 (0000000069f121e5) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 927.943206] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 931.365049] Lustre: lustre-OST0000: deleting orphan objects from 0x0:592 to 0x0:737 [ 931.365065] Lustre: lustre-OST0001: deleting orphan objects from 0x0:560 to 0x0:705 [ 933.302763] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 933.934981] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 937.560649] Lustre: DEBUG MARKER: == replay-single test 9: |X| create (same inum/gen) ====== 21:46:11 (1767840371) [ 939.018438] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 953.928770] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 953.931010] Lustre: Skipped 2 previous similar messages [ 955.557295] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 959.016436] Lustre: lustre-OST0001: deleting orphan objects from 0x0:560 to 0x0:737 [ 959.016483] Lustre: lustre-OST0000: deleting orphan objects from 0x0:592 to 0x0:769 [ 961.606482] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 962.302672] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 966.857676] Lustre: DEBUG MARKER: == replay-single test 10: create |X| rename unlink ======= 21:46:40 (1767840400) [ 968.704212] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 989.374119] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 992.822668] Lustre: lustre-OST0000: deleting orphan objects from 0x0:592 to 0x0:801 [ 992.822926] Lustre: lustre-OST0001: deleting orphan objects from 0x0:560 to 0x0:769 [ 994.972591] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 995.683714] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 999.547421] Lustre: DEBUG MARKER: == replay-single test 11: create open write rename |X| create-old-name read ========================================================== 21:47:12 (1767840432) [ 1001.450285] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1022.907559] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 1026.578359] Lustre: lustre-OST0000: deleting orphan objects from 0x0:803 to 0x0:833 [ 1026.580737] Lustre: lustre-OST0001: deleting orphan objects from 0x0:771 to 0x0:801 [ 1028.362833] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1028.995601] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1032.790904] Lustre: DEBUG MARKER: == replay-single test 12: open, unlink |X| close ========= 21:47:46 (1767840466) [ 1033.818235] LustreError: 49336:0:(osd_handler.c:698:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 1033.821539] LustreError: 49336:0:(osd_handler.c:698:osd_ro()) Skipped 7 previous similar messages [ 1034.144674] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1034.762761] Lustre: Failing over lustre-MDT0000 [ 1034.764085] Lustre: Skipped 7 previous similar messages [ 1034.917280] Lustre: server umount lustre-MDT0000 complete [ 1034.918686] Lustre: Skipped 7 previous similar messages [ 1036.768574] Lustre: lustre-MDT0000-osp-MDT0001: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 1036.777248] Lustre: Skipped 32 previous similar messages [ 1043.807104] Lustre: 3140:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1767840470/real 1767840470] req@000000005a301741 x1853714076124160/t0(0) o400->MGC192.168.202.114@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1767840477 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:1.0' [ 1043.816072] Lustre: 3140:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 7 previous similar messages [ 1043.819021] LustreError: 166-1: MGC192.168.202.114@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1043.823495] LustreError: Skipped 7 previous similar messages [ 1050.081577] LustreError: 49926:0:(ldlm_resource.c:1127:ldlm_resource_complain()) MGC192.168.202.114@tcp: namespace resource [0x65727473756c:0x5:0x0].0x0 (00000000928878f1) refcount nonzero (2) after lock cleanup; forcing cleanup. [ 1051.512485] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 1055.262769] Lustre: lustre-OST0000: deleting orphan objects from 0x0:803 to 0x0:865 [ 1055.262833] Lustre: lustre-OST0001: deleting orphan objects from 0x0:771 to 0x0:833 [ 1057.385504] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1058.080203] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1062.417212] Lustre: DEBUG MARKER: == replay-single test 13: open chmod 0 |x| write close === 21:48:15 (1767840495) [ 1064.205891] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1078.752572] Lustre: Evicted from MGS (at 192.168.202.114@tcp) after server handle changed from 0x50fb2a7c8cabad2c to 0x50fb2a7c8cabb234 [ 1078.759074] Lustre: Skipped 8 previous similar messages [ 1079.753752] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 1079.759627] Lustre: Skipped 8 previous similar messages [ 1081.069476] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 1084.422340] Lustre: lustre-MDT0000: Recovery over after 0:05, of 2 clients 2 recovered and 0 were evicted. [ 1084.427640] Lustre: Skipped 8 previous similar messages [ 1084.455046] Lustre: lustre-OST0000: deleting orphan objects from 0x0:867 to 0x0:897 [ 1084.455061] Lustre: lustre-OST0001: deleting orphan objects from 0x0:771 to 0x0:865 [ 1087.032663] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1087.668997] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1091.673159] Lustre: DEBUG MARKER: == replay-single test 14: open(O_CREAT), unlink |X| close ========================================================== 21:48:45 (1767840525) [ 1093.222601] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1118.316487] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1118.318845] Lustre: Skipped 4 previous similar messages [ 1119.860243] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 1123.343780] Lustre: lustre-OST0000: deleting orphan objects from 0x0:899 to 0x0:929 [ 1123.343788] Lustre: lustre-OST0001: deleting orphan objects from 0x0:771 to 0x0:897 [ 1125.942541] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1126.757412] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1131.177447] Lustre: DEBUG MARKER: == replay-single test 15: open(O_CREAT), unlink |X| touch new, close ========================================================== 21:49:24 (1767840564) [ 1132.924512] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1154.228810] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 1157.670944] Lustre: lustre-OST0000: deleting orphan objects from 0x0:931 to 0x0:961 [ 1157.672318] Lustre: lustre-OST0001: deleting orphan objects from 0x0:899 to 0x0:929 [ 1160.184938] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1160.999167] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1164.587420] Lustre: DEBUG MARKER: == replay-single test 16: |X| open(O_CREAT), unlink, touch new, unlink new ========================================================== 21:49:58 (1767840598) [ 1166.121275] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1167.839841] LustreError: 11-0: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1167.842335] LustreError: Skipped 8 previous similar messages [ 1183.300034] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 1186.317452] Lustre: lustre-OST0001: deleting orphan objects from 0x0:899 to 0x0:961 [ 1186.317488] Lustre: lustre-OST0000: deleting orphan objects from 0x0:963 to 0x0:993 [ 1188.596863] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1189.273015] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1193.555434] Lustre: DEBUG MARKER: == replay-single test 17: |X| open(O_CREAT), |replay| close ========================================================== 21:50:26 (1767840626) [ 1195.406610] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1196.512685] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1196.514566] Lustre: Skipped 3 previous similar messages [ 1215.829480] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 1219.101408] Lustre: lustre-OST0000: deleting orphan objects from 0x0:995 to 0x0:1025 [ 1219.101437] Lustre: lustre-OST0001: deleting orphan objects from 0x0:899 to 0x0:993 [ 1221.704716] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1222.442821] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1226.618940] Lustre: DEBUG MARKER: == replay-single test 18: open(O_CREAT), unlink, touch new, close, touch, unlink ========================================================== 21:51:00 (1767840660) [ 1228.065903] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1254.877518] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 1258.032968] Lustre: lustre-OST0000: deleting orphan objects from 0x0:1027 to 0x0:1057 [ 1258.033071] Lustre: lustre-OST0001: deleting orphan objects from 0x0:995 to 0x0:1025 [ 1260.552335] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1261.315648] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1265.432684] Lustre: DEBUG MARKER: == replay-single test 19: mcreate, open, write, rename === 21:51:38 (1767840698) [ 1267.284555] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1286.626668] LustreError: 61361:0:(ldlm_resource.c:1127:ldlm_resource_complain()) MGC192.168.202.114@tcp: namespace resource [0x65727473756c:0x5:0x0].0x0 (00000000f70cc513) refcount nonzero (2) after lock cleanup; forcing cleanup. [ 1288.796673] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 1292.327117] Lustre: lustre-OST0001: deleting orphan objects from 0x0:1027 to 0x0:1057 [ 1292.327117] Lustre: lustre-OST0000: deleting orphan objects from 0x0:1059 to 0x0:1089 [ 1294.705302] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1295.378735] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1299.247284] Lustre: DEBUG MARKER: == replay-single test 20a: |X| open(O_CREAT), unlink, replay, close (test mds_cleanup_orphans) ========================================================== 21:52:12 (1767840732) [ 1300.839133] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1328.196198] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 1331.753052] Lustre: lustre-OST0001: deleting orphan objects from 0x0:1027 to 0x0:1089 [ 1331.753074] Lustre: lustre-OST0000: deleting orphan objects from 0x0:1091 to 0x0:1121 [ 1334.421795] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1335.186070] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1339.847608] Lustre: DEBUG MARKER: == replay-single test 20b: write, unlink, eviction, replay (test mds_cleanup_orphans) ========================================================== 21:52:53 (1767840773) [ 1341.758659] Lustre: 64014:0:(genops.c:1710:obd_export_evict_by_uuid()) lustre-MDT0000: evicting 887bfe44-15a6-4ae3-80bd-930b965868a1 at adminstrative request [ 1347.018669] LustreError: 137-5: lustre-MDT0000_UUID: not available for connect from 192.168.202.14@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1347.023957] LustreError: Skipped 420 previous similar messages [ 1361.944484] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 1365.516585] Lustre: lustre-OST0001: deleting orphan objects from 0x0:1027 to 0x0:1121 [ 1365.517175] Lustre: lustre-OST0000: deleting orphan objects from 0x0:1123 to 0x0:1153 [ 1368.168695] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1368.774174] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1371.792474] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 1380.726575] Lustre: DEBUG MARKER: before 6144, after 6144 [ 1383.341651] Lustre: DEBUG MARKER: == replay-single test 20c: check that client eviction does not affect file content ========================================================== 21:53:36 (1767840816) [ 1383.801168] Lustre: 66029:0:(genops.c:1710:obd_export_evict_by_uuid()) lustre-MDT0000: evicting 887bfe44-15a6-4ae3-80bd-930b965868a1 at adminstrative request [ 1389.183519] Lustre: DEBUG MARKER: == replay-single test 21: |X| open(O_CREAT), unlink touch new, replay, close (test mds_cleanup_orphans) ========================================================== 21:53:42 (1767840822) [ 1390.613220] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1409.620034] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1409.622563] Lustre: Skipped 15 previous similar messages [ 1409.647227] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1409.649802] Lustre: Skipped 7 previous similar messages [ 1411.324109] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 1414.625138] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to (at 0@lo) [ 1414.628567] Lustre: Skipped 75 previous similar messages [ 1414.686659] Lustre: lustre-OST0000: deleting orphan objects from 0x0:1155 to 0x0:1185 [ 1414.687206] Lustre: lustre-OST0001: deleting orphan objects from 0x0:1124 to 0x0:1153 [ 1416.447930] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1416.954565] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1420.197580] Lustre: DEBUG MARKER: == replay-single test 22: open(O_CREAT), |X| unlink, replay, close (test mds_cleanup_orphans) ========================================================== 21:54:13 (1767840853) [ 1421.577536] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1438.178136] LustreError: 68613:0:(ldlm_resource.c:1127:ldlm_resource_complain()) MGC192.168.202.114@tcp: namespace resource [0x65727473756c:0x5:0x0].0x0 (00000000d8f3d6d9) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 1439.902495] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 1443.851073] Lustre: lustre-OST0000: deleting orphan objects from 0x0:1187 to 0x0:1217 [ 1443.851097] Lustre: lustre-OST0001: deleting orphan objects from 0x0:1155 to 0x0:1185 [ 1445.872902] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1446.506270] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1450.289954] Lustre: DEBUG MARKER: == replay-single test 23: open(O_CREAT), |X| unlink touch new, replay, close (test mds_cleanup_orphans) ========================================================== 21:54:43 (1767840883) [ 1452.037795] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1469.648808] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 1473.060836] Lustre: lustre-OST0001: deleting orphan objects from 0x0:1187 to 0x0:1217 [ 1473.060846] Lustre: lustre-OST0000: deleting orphan objects from 0x0:1219 to 0x0:1249 [ 1475.818420] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1476.621819] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1480.892145] Lustre: DEBUG MARKER: == replay-single test 24: open(O_CREAT), replay, unlink, close (test mds_cleanup_orphans) ========================================================== 21:55:14 (1767840914) [ 1482.764872] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1503.342776] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 1506.843385] Lustre: lustre-OST0001: deleting orphan objects from 0x0:1219 to 0x0:1249 [ 1506.843400] Lustre: lustre-OST0000: deleting orphan objects from 0x0:1251 to 0x0:1281 [ 1508.980320] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1509.801430] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1514.239217] Lustre: DEBUG MARKER: == replay-single test 25: open(O_CREAT), unlink, replay, close (test mds_cleanup_orphans) ========================================================== 21:55:47 (1767840947) [ 1515.748857] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1531.740980] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 1535.541703] Lustre: lustre-OST0001: deleting orphan objects from 0x0:1219 to 0x0:1281 [ 1535.543871] Lustre: lustre-OST0000: deleting orphan objects from 0x0:1283 to 0x0:1313 [ 1538.388539] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1539.255652] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1543.881772] Lustre: DEBUG MARKER: == replay-single test 26: |X| open(O_CREAT), unlink two, close one, replay, close one (test mds_cleanup_orphans) ========================================================== 21:56:17 (1767840977) [ 1545.825891] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1546.849839] Lustre: Failing over lustre-MDT0000 [ 1546.851317] Lustre: Skipped 14 previous similar messages [ 1546.994054] Lustre: server umount lustre-MDT0000 complete [ 1546.995672] Lustre: Skipped 14 previous similar messages [ 1550.818243] Lustre: lustre-MDT0000-osp-MDT0001: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 1550.829589] Lustre: Skipped 58 previous similar messages [ 1557.983173] Lustre: 3139:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1767840984/real 1767840984] req@00000000d4a3a27b x1853714076316608/t0(0) o400->MGC192.168.202.114@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1767840991 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:0.0' [ 1557.992306] Lustre: 3139:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 14 previous similar messages [ 1557.995547] LustreError: 166-1: MGC192.168.202.114@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1557.999381] LustreError: Skipped 14 previous similar messages [ 1566.157603] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 1569.351729] Lustre: lustre-OST0001: deleting orphan objects from 0x0:1283 to 0x0:1313 [ 1569.351984] Lustre: lustre-OST0000: deleting orphan objects from 0x0:1315 to 0x0:1345 [ 1571.859993] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1572.598050] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1577.043507] Lustre: DEBUG MARKER: == replay-single test 27: |X| open(O_CREAT), unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 21:56:50 (1767841010) [ 1578.387222] LustreError: 76165:0:(osd_handler.c:698:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 1578.390210] LustreError: 76165:0:(osd_handler.c:698:osd_ro()) Skipped 14 previous similar messages [ 1578.766225] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1596.896738] Lustre: Evicted from MGS (at 192.168.202.114@tcp) after server handle changed from 0x50fb2a7c8cabfc94 to 0x50fb2a7c8cac0213 [ 1596.903044] Lustre: Skipped 14 previous similar messages [ 1597.896246] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 1597.898484] Lustre: Skipped 14 previous similar messages [ 1598.229834] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 1602.046104] Lustre: lustre-MDT0000: Recovery over after 0:05, of 2 clients 2 recovered and 0 were evicted. [ 1602.048957] Lustre: Skipped 14 previous similar messages [ 1602.061871] Lustre: lustre-OST0000: deleting orphan objects from 0x0:1347 to 0x0:1377 [ 1602.063221] Lustre: lustre-OST0001: deleting orphan objects from 0x0:1315 to 0x0:1345 [ 1603.970325] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1604.521311] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1608.094283] Lustre: DEBUG MARKER: == replay-single test 28: open(O_CREAT), |X| unlink two, close one, replay, close one (test mds_cleanup_orphans) ========================================================== 21:57:21 (1767841041) [ 1609.388347] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1627.030688] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 1630.730288] Lustre: lustre-OST0001: deleting orphan objects from 0x0:1347 to 0x0:1377 [ 1630.730316] Lustre: lustre-OST0000: deleting orphan objects from 0x0:1379 to 0x0:1409 [ 1632.640560] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1633.190954] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1636.561170] Lustre: DEBUG MARKER: == replay-single test 29: open(O_CREAT), |X| unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 21:57:50 (1767841070) [ 1637.802546] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1655.706700] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 1659.395056] Lustre: lustre-OST0000: deleting orphan objects from 0x0:1411 to 0x0:1441 [ 1659.396159] Lustre: lustre-OST0001: deleting orphan objects from 0x0:1379 to 0x0:1409 [ 1661.113103] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1661.674422] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1665.371733] Lustre: DEBUG MARKER: == replay-single test 30: open(O_CREAT) two, unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 21:58:18 (1767841098) [ 1666.701471] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1683.479276] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 1687.046403] Lustre: lustre-OST0001: deleting orphan objects from 0x0:1411 to 0x0:1441 [ 1687.046436] Lustre: lustre-OST0000: deleting orphan objects from 0x0:1443 to 0x0:1473 [ 1688.910366] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1689.453031] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1693.203828] Lustre: DEBUG MARKER: == replay-single test 31: open(O_CREAT) two, unlink one, |X| unlink one, close two (test mds_cleanup_orphans) ========================================================== 21:58:46 (1767841126) [ 1694.631475] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1697.248086] LustreError: 11-0: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1697.252968] LustreError: Skipped 15 previous similar messages [ 1711.900344] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 1715.710686] Lustre: lustre-OST0000: deleting orphan objects from 0x0:1475 to 0x0:1505 [ 1715.710686] Lustre: lustre-OST0001: deleting orphan objects from 0x0:1443 to 0x0:1473 [ 1717.440195] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1717.933958] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1721.352689] Lustre: DEBUG MARKER: == replay-single test 32: close() notices client eviction; close() after client eviction ========================================================== 21:59:14 (1767841154) [ 1721.706359] Lustre: 84214:0:(genops.c:1710:obd_export_evict_by_uuid()) lustre-MDT0000: evicting 887bfe44-15a6-4ae3-80bd-930b965868a1 at adminstrative request [ 1726.214699] Lustre: DEBUG MARKER: == replay-single test 33a: fid seq shouldn't be reused after abort recovery ========================================================== 21:59:19 (1767841159) [ 1727.065713] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1730.127831] LustreError: 85078:0:(mdt_handler.c:7428:mdt_iocontrol()) lustre-MDT0000: Aborting recovery for device [ 1730.131111] LustreError: 85078:0:(ldlm_lib.c:2882:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 1730.134059] Lustre: 85112:0:(ldlm_lib.c:2288:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 1730.136366] Lustre: lustre-MDT0000: disconnecting 2 stale clients [ 1730.159977] Lustre: lustre-OST0000: deleting orphan objects from 0x0:1512 to 0x0:1537 [ 1730.159979] Lustre: lustre-OST0001: deleting orphan objects from 0x0:1479 to 0x0:1505 [ 1731.382819] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 1735.137391] LustreError: lustre-MDT0000-osp-MDT0001: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 1742.520280] Lustre: DEBUG MARKER: == replay-single test 33b: test fid seq allocation ======= 21:59:36 (1767841176) [ 1743.602562] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1746.646666] Lustre: *** cfs_fail_loc=1311, val=0*** [ 1746.657076] LustreError: 86576:0:(mdt_handler.c:7428:mdt_iocontrol()) lustre-MDT0000: Aborting recovery for device [ 1746.659710] LustreError: 86576:0:(ldlm_lib.c:2882:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 1746.662172] Lustre: 86608:0:(ldlm_lib.c:2288:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 1746.665502] Lustre: 86608:0:(ldlm_lib.c:2288:target_recovery_overseer()) Skipped 2 previous similar messages [ 1746.667621] Lustre: lustre-MDT0000: disconnecting 2 stale clients [ 1746.690951] Lustre: lustre-OST0001: deleting orphan objects from 0x0:1516 to 0x0:1537 [ 1746.690960] Lustre: lustre-OST0000: deleting orphan objects from 0x0:1548 to 0x0:1569 [ 1747.902412] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 1752.032573] LustreError: lustre-MDT0000-osp-MDT0001: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 1757.179839] Lustre: *** cfs_fail_loc=1311, val=0*** [ 1759.499389] Lustre: DEBUG MARKER: == replay-single test 34: abort recovery before client does replay (test mds_cleanup_orphans) ========================================================== 21:59:52 (1767841192) [ 1760.798953] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1763.973492] LustreError: 88078:0:(mdt_handler.c:7428:mdt_iocontrol()) lustre-MDT0000: Aborting recovery for device [ 1763.976814] LustreError: 88078:0:(ldlm_lib.c:2882:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 1763.979783] Lustre: 88112:0:(ldlm_lib.c:2288:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 1763.983140] Lustre: 88112:0:(ldlm_lib.c:2288:target_recovery_overseer()) Skipped 2 previous similar messages [ 1763.986039] Lustre: lustre-MDT0000: disconnecting 2 stale clients [ 1764.008445] Lustre: lustre-OST0000: deleting orphan objects from 0x0:1575 to 0x0:1601 [ 1764.011858] Lustre: lustre-OST0001: deleting orphan objects from 0x0:1544 to 0x0:1569 [ 1765.256394] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 1768.929159] LustreError: lustre-MDT0000-osp-MDT0001: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 1777.178139] Lustre: DEBUG MARKER: == replay-single test 35: test recovery from llog for unlink op ========================================================== 22:00:10 (1767841210) [ 1777.494856] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 1777.496245] LustreError: 23614:0:(ldlm_lib.c:3224:target_send_reply_msg()) @@@ dropping reply req@00000000844dc986 x1853714068941056/t201863462916(0) o36->887bfe44-15a6-4ae3-80bd-930b965868a1@192.168.202.14@tcp:411/0 lens 504/456 e 0 to 0 dl 1767841216 ref 1 fl Interpret:/0/0 rc 0/0 job:'rm.0' [ 1782.677347] LustreError: 89428:0:(mdt_handler.c:7428:mdt_iocontrol()) lustre-MDT0000: Aborting recovery for device [ 1782.679868] LustreError: 89428:0:(ldlm_lib.c:2882:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 1782.682130] Lustre: 89460:0:(ldlm_lib.c:2288:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 1782.684597] Lustre: 89460:0:(ldlm_lib.c:2288:target_recovery_overseer()) Skipped 2 previous similar messages [ 1782.687309] Lustre: lustre-MDT0000: disconnecting 2 stale clients [ 1782.712338] Lustre: lustre-OST0001: deleting orphan objects from 0x0:1571 to 0x0:1601 [ 1782.712342] Lustre: lustre-OST0000: deleting orphan objects from 0x0:1575 to 0x0:1633 [ 1783.989500] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 1787.875445] LustreError: lustre-MDT0000-osp-MDT0001: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 1795.229844] Lustre: DEBUG MARKER: == replay-single test 36: don't resend cancel ============ 22:00:28 (1767841228) [ 1796.409777] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1812.928125] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 1816.586811] Lustre: lustre-OST0000: deleting orphan objects from 0x0:1575 to 0x0:1665 [ 1816.586812] Lustre: lustre-OST0001: deleting orphan objects from 0x0:1603 to 0x0:1633 [ 1818.881782] Lustre: DEBUG MARKER: == replay-single test 37: abort recovery before client does replay (test mds_cleanup_orphans for directories) ========================================================== 22:00:52 (1767841252) [ 1820.140919] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1823.539565] LustreError: 92360:0:(mdt_handler.c:7428:mdt_iocontrol()) lustre-MDT0000: Aborting recovery for device [ 1823.541975] LustreError: 92360:0:(ldlm_lib.c:2882:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 1823.544388] Lustre: 92392:0:(ldlm_lib.c:2288:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 1823.548717] Lustre: 92392:0:(ldlm_lib.c:2288:target_recovery_overseer()) Skipped 2 previous similar messages [ 1823.552596] Lustre: lustre-MDT0000: disconnecting 2 stale clients [ 1823.578257] Lustre: lustre-OST0001: deleting orphan objects from 0x0:1603 to 0x0:1665 [ 1823.578464] Lustre: lustre-OST0000: deleting orphan objects from 0x0:1575 to 0x0:1697 [ 1824.881505] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 1828.835413] LustreError: lustre-MDT0000-osp-MDT0001: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 1837.177284] Lustre: DEBUG MARKER: == replay-single test 38: test recovery from unlink llog (test llog_gen_rec) ========================================================== 22:01:10 (1767841270) [ 1843.005113] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1859.051574] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 1862.680064] Lustre: lustre-OST0000: deleting orphan objects from 0x0:2098 to 0x0:2113 [ 1862.680345] Lustre: lustre-OST0001: deleting orphan objects from 0x0:2066 to 0x0:2081 [ 1864.504180] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1865.019267] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1872.690231] Lustre: DEBUG MARKER: == replay-single test 39: test recovery from unlink llog (test llog_gen_rec) ========================================================== 22:01:46 (1767841306) [ 1877.797983] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1880.522171] Lustre: lustre-MDT0000: Not available for connect from 192.168.202.14@tcp (stopping) [ 1897.812938] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 1902.735606] Lustre: lustre-OST0001: deleting orphan objects from 0x0:2482 to 0x0:2497 [ 1902.738071] Lustre: lustre-OST0000: deleting orphan objects from 0x0:2514 to 0x0:2529 [ 1905.024771] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1905.704294] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1913.790751] Lustre: DEBUG MARKER: == replay-single test 40: cause recovery in ptlrpc, ensure IO continues ========================================================== 22:02:27 (1767841347) [ 1914.255415] Lustre: DEBUG MARKER: SKIP: replay-single test_40 layout_lock needs MDS connection for IO [ 1914.779990] Lustre: DEBUG MARKER: == replay-single test 41: read from a valid osc while other oscs are invalid ========================================================== 22:02:28 (1767841348) [ 1915.577714] Lustre: setting import lustre-OST0001_UUID INACTIVE by administrator request [ 1915.974055] Lustre: lustre-OST0001: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnecting [ 1915.977202] LustreError: lustre-OST0001-osc-MDT0000: This client was evicted by lustre-OST0001; in progress operations using this service will fail. [ 1915.980925] Lustre: lustre-OST0001: deleting orphan objects from 0x0:2482 to 0x0:2529 [ 1918.573680] Lustre: DEBUG MARKER: == replay-single test 42: recovery after ost failure ===== 22:02:32 (1767841352) [ 1923.437822] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 1940.168321] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 1940.172965] Lustre: Skipped 28 previous similar messages [ 1941.758317] Lustre: lustre-OST0000: deleting orphan objects from 0x280000400:34 to 0x280000400:65 [ 1941.760832] Lustre: lustre-OST0000: deleting orphan objects from 0x0:2931 to 0x0:2977 [ 1941.824765] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 1986.808792] Lustre: DEBUG MARKER: == replay-single test 43: mds osc import failure during recovery; don't LBUG ========================================================== 22:03:40 (1767841420) [ 1988.431804] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1990.090930] LustreError: 137-5: lustre-MDT0000_UUID: not available for connect from 192.168.202.14@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1990.099390] LustreError: Skipped 404 previous similar messages [ 2003.937341] LustreError: 100511:0:(ldlm_resource.c:1127:ldlm_resource_complain()) MGC192.168.202.114@tcp: namespace resource [0x65727473756c:0x5:0x0].0x0 (0000000086ad00a4) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 2005.568987] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 2009.638730] Lustre: *** cfs_fail_loc=204, val=2147483648*** [ 2009.638816] Lustre: lustre-OST0000: deleting orphan objects from 0x0:2931 to 0x0:3009 [ 2012.166806] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2012.634497] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2016.735195] LustreError: 100524:0:(osp_precreate.c:967:osp_precreate_cleanup_orphans()) lustre-OST0001-osc-MDT0000: cannot cleanup orphans: rc = -11 [ 2016.736377] Lustre: lustre-OST0001: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnecting [ 2016.741286] Lustre: lustre-OST0001-osc-MDT0000: Connection restored to (at 0@lo) [ 2016.743248] Lustre: Skipped 101 previous similar messages [ 2017.759396] Lustre: lustre-OST0001: deleting orphan objects from 0x0:2930 to 0x0:2945 [ 2026.716587] Lustre: DEBUG MARKER: == replay-single test 44a: race in target handle connect ========================================================== 22:04:20 (1767841460) [ 2029.151874] LustreError: 15083:0:(libcfs_fail.h:169:cfs_race()) cfs_race id 701 sleeping [ 2034.655113] LustreError: 15083:0:(libcfs_fail.h:178:cfs_race()) cfs_fail_race id 701 awake: rc=0 [ 2034.659055] Lustre: lustre-MDT0000: Client 887bfe44-15a6-4ae3-80bd-930b965868a1 (at 192.168.202.14@tcp) reconnecting [ 2034.680603] LustreError: 37920:0:(libcfs_fail.h:180:cfs_race()) cfs_fail_race id 701 waking [ 2035.591719] LustreError: 15083:0:(libcfs_fail.h:169:cfs_race()) cfs_race id 701 sleeping [ 2040.799158] LustreError: 15083:0:(libcfs_fail.h:178:cfs_race()) cfs_fail_race id 701 awake: rc=0 [ 2040.803875] Lustre: lustre-MDT0000: Client 887bfe44-15a6-4ae3-80bd-930b965868a1 (at 192.168.202.14@tcp) reconnecting [ 2041.692593] LustreError: 15083:0:(libcfs_fail.h:169:cfs_race()) cfs_race id 701 sleeping [ 2046.943091] LustreError: 15083:0:(libcfs_fail.h:178:cfs_race()) cfs_fail_race id 701 awake: rc=0 [ 2046.948868] Lustre: lustre-MDT0000: Client 887bfe44-15a6-4ae3-80bd-930b965868a1 (at 192.168.202.14@tcp) reconnecting [ 2047.764431] LustreError: 23614:0:(libcfs_fail.h:169:cfs_race()) cfs_race id 701 sleeping [ 2053.064984] LustreError: 7457:0:(libcfs_fail.h:180:cfs_race()) cfs_fail_race id 701 waking [ 2053.070035] LustreError: 7457:0:(libcfs_fail.h:180:cfs_race()) Skipped 1 previous similar message [ 2053.074801] LustreError: 23614:0:(libcfs_fail.h:178:cfs_race()) cfs_fail_race id 701 awake: rc=1 [ 2053.855795] LustreError: 23614:0:(libcfs_fail.h:169:cfs_race()) cfs_race id 701 sleeping [ 2059.208893] LustreError: 7457:0:(libcfs_fail.h:180:cfs_race()) cfs_fail_race id 701 waking [ 2059.212269] Lustre: lustre-MDT0000: Client 887bfe44-15a6-4ae3-80bd-930b965868a1 (at 192.168.202.14@tcp) reconnecting [ 2059.212320] LustreError: 23614:0:(libcfs_fail.h:178:cfs_race()) cfs_fail_race id 701 awake: rc=1 [ 2059.216142] Lustre: Skipped 2 previous similar messages [ 2059.219486] Lustre: lustre-MDT0000: Export 000000009d6766bb already connecting from 192.168.202.14@tcp [ 2065.352750] LustreError: 7457:0:(libcfs_fail.h:180:cfs_race()) cfs_fail_race id 701 waking [ 2065.355631] Lustre: lustre-MDT0000: Export 000000009d6766bb already connecting from 192.168.202.14@tcp [ 2066.139075] LustreError: 23614:0:(libcfs_fail.h:169:cfs_race()) cfs_race id 701 sleeping [ 2066.143398] LustreError: 23614:0:(libcfs_fail.h:169:cfs_race()) Skipped 1 previous similar message [ 2071.519146] LustreError: 23614:0:(libcfs_fail.h:178:cfs_race()) cfs_fail_race id 701 awake: rc=0 [ 2071.521399] LustreError: 23614:0:(libcfs_fail.h:178:cfs_race()) Skipped 1 previous similar message [ 2077.663552] Lustre: lustre-MDT0000: Client 887bfe44-15a6-4ae3-80bd-930b965868a1 (at 192.168.202.14@tcp) reconnecting [ 2077.673055] Lustre: Skipped 2 previous similar messages [ 2086.443360] LustreError: 23614:0:(libcfs_fail.h:169:cfs_race()) cfs_race id 701 sleeping [ 2086.449474] LustreError: 23614:0:(libcfs_fail.h:169:cfs_race()) Skipped 2 previous similar messages [ 2091.487294] LustreError: 23614:0:(libcfs_fail.h:178:cfs_race()) cfs_fail_race id 701 awake: rc=0 [ 2091.493362] LustreError: 23614:0:(libcfs_fail.h:178:cfs_race()) Skipped 2 previous similar messages [ 2099.296571] Lustre: DEBUG MARKER: == replay-single test 44b: race in target handle connect ========================================================== 22:05:31 (1767841531) [ 2101.424076] LustreError: 6124:0:(fail.c:138:__cfs_fail_timeout_set()) cfs_fail_timeout id 704 sleeping for 40000ms [ 2107.849963] Lustre: lustre-MDT0000: Export 000000009d6766bb already connecting from 192.168.202.14@tcp [ 2110.284570] Lustre: lustre-MDT0000: Export 000000009d6766bb already connecting from 192.168.202.14@tcp [ 2110.289438] Lustre: Skipped 1 previous similar message [ 2114.791514] Lustre: lustre-MDT0000: Export 000000009d6766bb already connecting from 192.168.202.14@tcp [ 2114.796502] Lustre: Skipped 3 previous similar messages [ 2119.322094] LustreError: 6124:0:(fail.c:144:__cfs_fail_timeout_set()) cfs_fail_timeout interrupted [ 2121.803292] Lustre: DEBUG MARKER: == replay-single test 44c: race in target handle connect ========================================================== 22:05:54 (1767841554) [ 2122.698145] Lustre: lustre-MDT0000: Client 887bfe44-15a6-4ae3-80bd-930b965868a1 (at 192.168.202.14@tcp) reconnecting [ 2122.705387] Lustre: Skipped 3 previous similar messages [ 2124.250643] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2130.405917] Lustre: *** cfs_fail_loc=712, val=0*** [ 2130.410537] LustreError: 15892:0:(service.c:1226:ptlrpc_check_req()) @@@ Invalid replay without recovery req@000000008ac26c7c x1853714076754560/t0(0) o400->lustre-MDT0000-mdtlov_UUID@0@lo:0/0 lens 224/0 e 0 to 0 dl 0 ref 1 fl New:/c0/ffffffff rc 0/-1 job:'ptlrpcd_rcv.0' [ 2130.420098] LustreError: lustre-OST0000-osc-MDT0000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 2130.482199] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 2130.485539] Lustre: Skipped 20 previous similar messages [ 2130.530334] LustreError: 104793:0:(mdt_handler.c:7428:mdt_iocontrol()) lustre-MDT0000: Aborting recovery for device [ 2130.534973] LustreError: 104793:0:(ldlm_lib.c:2882:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 2130.539947] Lustre: 104826:0:(ldlm_lib.c:2288:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 2130.542740] Lustre: 104826:0:(ldlm_lib.c:2288:target_recovery_overseer()) Skipped 2 previous similar messages [ 2130.545326] Lustre: lustre-MDT0000: disconnecting 2 stale clients [ 2130.580642] Lustre: lustre-OST0000: deleting orphan objects from 0x0:2931 to 0x0:3041 [ 2130.581084] Lustre: lustre-OST0001: deleting orphan objects from 0x0:2930 to 0x0:2977 [ 2132.721077] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 2135.526806] LustreError: lustre-MDT0000-osp-MDT0001: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 2150.879500] Lustre: lustre-MDT0000-osp-MDT0001: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 2150.885070] Lustre: Skipped 66 previous similar messages [ 2158.559389] Lustre: 3141:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1767841584/real 1767841584] req@00000000a71bdb9f x1853714076763072/t0(0) o400->MGC192.168.202.114@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1767841591 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:3.0' [ 2158.570504] Lustre: 3141:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 10 previous similar messages [ 2158.574102] LustreError: 166-1: MGC192.168.202.114@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2158.579786] LustreError: Skipped 15 previous similar messages [ 2164.705584] LustreError: 105953:0:(ldlm_resource.c:1127:ldlm_resource_complain()) MGC192.168.202.114@tcp: namespace resource [0x65727473756c:0x5:0x0].0x0 (00000000a54c3415) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 2166.578028] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 2169.886595] Lustre: lustre-OST0001: deleting orphan objects from 0x0:2930 to 0x0:3009 [ 2169.891182] Lustre: lustre-OST0000: deleting orphan objects from 0x0:2931 to 0x0:3073 [ 2172.517556] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2173.230231] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2177.617613] Lustre: DEBUG MARKER: == replay-single test 45: Handle failed close ============ 22:06:50 (1767841610) [ 2181.625415] Lustre: DEBUG MARKER: == replay-single test 46: Don't leak file handle after open resend (3325) ========================================================== 22:06:54 (1767841614) [ 2182.067648] Lustre: *** cfs_fail_loc=122, val=2147483648*** [ 2182.070101] LustreError: 65992:0:(ldlm_lib.c:3224:target_send_reply_msg()) @@@ dropping reply req@0000000059de7191 x1853714069978752/t0(0) o700->887bfe44-15a6-4ae3-80bd-930b965868a1@192.168.202.14@tcp:61/0 lens 264/248 e 0 to 0 dl 1767841621 ref 1 fl Interpret:/0/0 rc 0/0 job:'touch.0' [ 2189.259199] Lustre: lustre-MDT0000: Client 887bfe44-15a6-4ae3-80bd-930b965868a1 (at 192.168.202.14@tcp) reconnecting [ 2189.265496] Lustre: Skipped 2 previous similar messages [ 2190.506533] Lustre: Failing over lustre-MDT0000 [ 2190.507850] Lustre: Skipped 17 previous similar messages [ 2190.721408] Lustre: server umount lustre-MDT0000 complete [ 2190.723507] Lustre: Skipped 17 previous similar messages [ 2208.736695] Lustre: Evicted from MGS (at 192.168.202.114@tcp) after server handle changed from 0x50fb2a7c8caf6a42 to 0x50fb2a7c8caf6ecc [ 2208.741161] Lustre: Skipped 15 previous similar messages [ 2209.756074] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 2209.758545] Lustre: Skipped 10 previous similar messages [ 2210.353231] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 2213.880482] Lustre: lustre-MDT0000: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 2213.883514] Lustre: Skipped 10 previous similar messages [ 2213.899662] Lustre: lustre-OST0000: deleting orphan objects from 0x0:3075 to 0x0:3105 [ 2213.899913] Lustre: lustre-OST0001: deleting orphan objects from 0x0:3011 to 0x0:3041 [ 2216.434976] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2217.096537] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2221.295289] Lustre: DEBUG MARKER: == replay-single test 47: MDS->OSC failure during precreate cleanup (2824) ========================================================== 22:07:34 (1767841654) [ 2237.204381] Lustre: lustre-OST0000: deleting orphan objects from 0x280000400:34 to 0x280000400:97 [ 2237.209425] Lustre: lustre-OST0000: deleting orphan objects from 0x0:3116 to 0x0:3137 [ 2237.417129] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 2242.618427] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 2243.480541] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 2311.154223] Lustre: DEBUG MARKER: == replay-single test 48: MDS->OSC failure during precreate cleanup (2824) ========================================================== 22:09:04 (1767841744) [ 2312.803515] LustreError: 110186:0:(osd_handler.c:698:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 2312.807266] LustreError: 110186:0:(osd_handler.c:698:osd_ro()) Skipped 14 previous similar messages [ 2313.333025] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2316.257654] LustreError: 11-0: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 2316.262482] LustreError: Skipped 15 previous similar messages [ 2333.406454] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 2336.536913] Lustre: *** cfs_fail_loc=216, val=0*** [ 2336.537266] Lustre: lustre-OST0000: deleting orphan objects from 0x0:3148 to 0x0:3169 [ 2336.540922] LustreError: 110804:0:(osp_precreate.c:967:osp_precreate_cleanup_orphans()) lustre-OST0001-osc-MDT0000: cannot cleanup orphans: rc = -30 [ 2337.567521] Lustre: lustre-OST0001: deleting orphan objects from 0x0:3062 to 0x0:3105 [ 2400.186867] Lustre: DEBUG MARKER: == replay-single test 50: Double OSC recovery, don't LASSERT (3812) ========================================================== 22:10:33 (1767841833) [ 2401.047573] Lustre: lustre-OST0000: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnecting [ 2401.053128] Lustre: lustre-OST0000: deleting orphan objects from 0x0:3180 to 0x0:3201 [ 2401.538785] Lustre: lustre-OST0000: deleting orphan objects from 0x0:3180 to 0x0:3233 [ 2409.564890] Lustre: DEBUG MARKER: == replay-single test 52: time out lock replay (3764) ==== 22:10:42 (1767841842) [ 2428.542719] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 2431.981177] Lustre: *** cfs_fail_loc=157, val=2147483648*** [ 2431.984939] LustreError: 112496:0:(ldlm_lib.c:3224:target_send_reply_msg()) @@@ dropping reply req@0000000080fdbdab x1853714070031040/t0(0) o101->887bfe44-15a6-4ae3-80bd-930b965868a1@192.168.202.14@tcp:327/0 lens 328/344 e 0 to 0 dl 1767841887 ref 1 fl Complete:/40/0 rc 0/0 job:'ldlm_lock_repla.0' [ 2454.984916] Lustre: lustre-MDT0000: Client 887bfe44-15a6-4ae3-80bd-930b965868a1 (at 192.168.202.14@tcp) reconnected, waiting for 2 clients in recovery for 0:57 [ 2455.053750] Lustre: lustre-OST0001: deleting orphan objects from 0x0:3117 to 0x0:3137 [ 2455.053811] Lustre: lustre-OST0000: deleting orphan objects from 0x0:3180 to 0x0:3265 [ 2458.531030] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2459.438700] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2465.118390] Lustre: DEBUG MARKER: == replay-single test 53a: |X| close request while two MDC requests in flight ========================================================== 22:11:38 (1767841898) [ 2466.752955] Lustre: *** cfs_fail_loc=115, val=2147483648*** [ 2469.110354] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2488.463666] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 2491.423853] Lustre: lustre-OST0000: deleting orphan objects from 0x0:3267 to 0x0:3297 [ 2491.424337] Lustre: lustre-OST0001: deleting orphan objects from 0x0:3117 to 0x0:3169 [ 2494.135984] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2494.847732] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2499.581910] Lustre: DEBUG MARKER: == replay-single test 53b: |X| open request while two MDC requests in flight ========================================================== 22:12:12 (1767841932) [ 2500.162424] Lustre: *** cfs_fail_loc=107, val=2147483648*** [ 2503.652685] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2521.091785] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 2524.218113] Lustre: lustre-OST0000: deleting orphan objects from 0x0:3267 to 0x0:3329 [ 2524.219990] Lustre: lustre-OST0001: deleting orphan objects from 0x0:3171 to 0x0:3201 [ 2527.092710] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2527.834486] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2532.149446] Lustre: DEBUG MARKER: == replay-single test 53c: |X| open request and close request while two MDC requests in flight ========================================================== 22:12:45 (1767841965) [ 2532.645902] Lustre: *** cfs_fail_loc=107, val=2147483648*** [ 2535.633113] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2551.900760] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 2551.903612] Lustre: Skipped 11 previous similar messages [ 2553.313341] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 2556.949693] Lustre: lustre-OST0000: deleting orphan objects from 0x0:3331 to 0x0:3361 [ 2556.949702] Lustre: lustre-OST0001: deleting orphan objects from 0x0:3171 to 0x0:3233 [ 2561.712951] Lustre: DEBUG MARKER: == replay-single test 53d: close reply while two MDC requests in flight ========================================================== 22:13:15 (1767841995) [ 2563.154611] Lustre: *** cfs_fail_loc=13b, val=315*** [ 2563.156208] Lustre: *** cfs_fail_loc=13b, val=2147483648*** [ 2563.157969] LustreError: 14941:0:(ldlm_lib.c:3224:target_send_reply_msg()) @@@ dropping reply req@00000000215feb18 x1853714070058176/t261993005073(0) o35->887bfe44-15a6-4ae3-80bd-930b965868a1@192.168.202.14@tcp:442/0 lens 392/456 e 0 to 0 dl 1767842002 ref 1 fl Interpret:/0/0 rc 0/0 job:'multiop.0' [ 2582.851876] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 2586.118922] Lustre: 14941:0:(mdt_recovery.c:200:mdt_req_from_lrd()) @@@ restoring transno req@00000000259bc12c x1853714070058176/t261993005073(0) o35->887bfe44-15a6-4ae3-80bd-930b965868a1@192.168.202.14@tcp:465/0 lens 392/456 e 0 to 0 dl 1767842025 ref 1 fl Interpret:/2/0 rc 0/0 job:'multiop.0' [ 2586.121178] Lustre: lustre-OST0000: deleting orphan objects from 0x0:3363 to 0x0:3393 [ 2586.121395] Lustre: lustre-OST0001: deleting orphan objects from 0x0:3171 to 0x0:3265 [ 2588.436315] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2589.054193] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2593.054877] Lustre: DEBUG MARKER: == replay-single test 53e: |X| open reply while two MDC requests in flight ========================================================== 22:13:46 (1767842026) [ 2593.563525] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 2593.566113] LustreError: 6125:0:(ldlm_lib.c:3224:target_send_reply_msg()) @@@ dropping reply req@00000000608f4f97 x1853714070065536/t266287972368(0) o36->887bfe44-15a6-4ae3-80bd-930b965868a1@192.168.202.14@tcp:493/0 lens 504/448 e 0 to 0 dl 1767842053 ref 1 fl Interpret:/0/0 rc 0/0 job:'mcreate.0' [ 2596.375426] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2601.441406] LustreError: 137-5: lustre-MDT0000_UUID: 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. [ 2601.446203] LustreError: Skipped 239 previous similar messages [ 2616.428587] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 2619.873089] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to (at 0@lo) [ 2619.879025] Lustre: Skipped 51 previous similar messages [ 2619.911994] Lustre: 15083:0:(mdt_recovery.c:200:mdt_req_from_lrd()) @@@ restoring transno req@00000000b54a77b7 x1853714070065536/t266287972368(0) o36->887bfe44-15a6-4ae3-80bd-930b965868a1@192.168.202.14@tcp:520/0 lens 504/448 e 0 to 0 dl 1767842080 ref 1 fl Interpret:/2/0 rc 0/0 job:'mcreate.0' [ 2619.916808] Lustre: lustre-OST0000: deleting orphan objects from 0x0:3363 to 0x0:3425 [ 2619.916816] Lustre: lustre-OST0001: deleting orphan objects from 0x0:3267 to 0x0:3297 [ 2622.113654] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2622.757805] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2626.748557] Lustre: DEBUG MARKER: == replay-single test 53f: |X| open reply and close reply while two MDC requests in flight ========================================================== 22:14:20 (1767842060) [ 2627.195105] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 2627.196919] LustreError: 15083:0:(ldlm_lib.c:3224:target_send_reply_msg()) @@@ dropping reply req@00000000ae01a718 x1853714070073344/t270582939664(0) o36->887bfe44-15a6-4ae3-80bd-930b965868a1@192.168.202.14@tcp:527/0 lens 504/448 e 0 to 0 dl 1767842087 ref 1 fl Interpret:/0/0 rc 0/0 job:'mcreate.0' [ 2628.558053] Lustre: *** cfs_fail_loc=13b, val=315*** [ 2630.067988] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2650.392317] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 2653.721257] Lustre: 6124:0:(mdt_recovery.c:200:mdt_req_from_lrd()) @@@ restoring transno req@0000000031767f73 x1853714070073344/t270582939664(0) o36->887bfe44-15a6-4ae3-80bd-930b965868a1@192.168.202.14@tcp:553/0 lens 504/448 e 0 to 0 dl 1767842113 ref 1 fl Interpret:/2/0 rc 0/0 job:'mcreate.0' [ 2653.723490] Lustre: lustre-OST0000: deleting orphan objects from 0x0:3363 to 0x0:3457 [ 2653.726422] Lustre: lustre-OST0001: deleting orphan objects from 0x0:3299 to 0x0:3329 [ 2653.729928] Lustre: 6124:0:(mdt_recovery.c:200:mdt_req_from_lrd()) Skipped 1 previous similar message [ 2659.378738] Lustre: DEBUG MARKER: == replay-single test 53g: |X| drop open reply and close request while close and open are both in flight ========================================================== 22:14:52 (1767842092) [ 2659.954757] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 2659.956770] Lustre: Skipped 1 previous similar message [ 2659.958363] LustreError: 6126:0:(ldlm_lib.c:3224:target_send_reply_msg()) @@@ dropping reply req@00000000a54d78e5 x1853714070080576/t274877906960(0) o36->887bfe44-15a6-4ae3-80bd-930b965868a1@192.168.202.14@tcp:559/0 lens 504/448 e 0 to 0 dl 1767842119 ref 1 fl Interpret:/0/0 rc 0/0 job:'mcreate.0' [ 2659.965423] LustreError: 6126:0:(ldlm_lib.c:3224:target_send_reply_msg()) Skipped 1 previous similar message [ 2661.377109] Lustre: *** cfs_fail_loc=115, val=2147483648*** [ 2661.378272] Lustre: Skipped 1 previous similar message [ 2663.551308] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2684.030446] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 2687.500699] Lustre: 6126:0:(mdt_recovery.c:200:mdt_req_from_lrd()) @@@ restoring transno req@00000000d267c94f x1853714070080576/t274877906960(0) o36->887bfe44-15a6-4ae3-80bd-930b965868a1@192.168.202.14@tcp:586/0 lens 504/448 e 0 to 0 dl 1767842146 ref 1 fl Interpret:/2/0 rc 0/0 job:'mcreate.0' [ 2687.502077] Lustre: lustre-OST0000: deleting orphan objects from 0x0:3459 to 0x0:3489 [ 2687.502170] Lustre: lustre-OST0001: deleting orphan objects from 0x0:3299 to 0x0:3361 [ 2691.973068] Lustre: DEBUG MARKER: == replay-single test 53h: open request and close reply while two MDC requests in flight ========================================================== 22:15:25 (1767842125) [ 2692.394953] Lustre: *** cfs_fail_loc=107, val=2147483648*** [ 2693.725321] Lustre: *** cfs_fail_loc=13b, val=315*** [ 2693.727031] LustreError: 6128:0:(ldlm_lib.c:3224:target_send_reply_msg()) @@@ dropping reply req@00000000fbb73a4e x1853714070087424/t279172874256(0) o35->887bfe44-15a6-4ae3-80bd-930b965868a1@192.168.202.14@tcp:572/0 lens 392/456 e 0 to 0 dl 1767842132 ref 1 fl Interpret:/0/0 rc 0/0 job:'multiop.0' [ 2696.084793] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2711.546482] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 2715.140551] Lustre: 6128:0:(mdt_recovery.c:200:mdt_req_from_lrd()) @@@ restoring transno req@0000000047e9f03a x1853714070087424/t279172874256(0) o35->887bfe44-15a6-4ae3-80bd-930b965868a1@192.168.202.14@tcp:594/0 lens 392/456 e 0 to 0 dl 1767842154 ref 1 fl Interpret:/2/0 rc 0/0 job:'multiop.0' [ 2715.145106] Lustre: lustre-OST0000: deleting orphan objects from 0x0:3491 to 0x0:3521 [ 2715.145551] Lustre: lustre-OST0001: deleting orphan objects from 0x0:3299 to 0x0:3393 [ 2719.901079] Lustre: DEBUG MARKER: == replay-single test 55: let MDS_CHECK_RESENT return the original return code instead of 0 ========================================================== 22:15:53 (1767842153) [ 2720.261528] Lustre: *** cfs_fail_loc=12b, val=2147483991*** [ 2747.336366] Lustre: lustre-MDT0000: Client 887bfe44-15a6-4ae3-80bd-930b965868a1 (at 192.168.202.14@tcp) reconnecting [ 2747.340567] Lustre: Skipped 1 previous similar message [ 2747.345428] Lustre: 7457:0:(mdt_recovery.c:200:mdt_req_from_lrd()) @@@ restoring transno req@000000006ce43bfb x1853714070093248/t283467841550(0) o101->887bfe44-15a6-4ae3-80bd-930b965868a1@192.168.202.14@tcp:646/0 lens 664/3424 e 0 to 0 dl 1767842206 ref 1 fl Interpret:/2/0 rc 0/0 job:'touch.0' [ 2750.121542] Lustre: DEBUG MARKER: == replay-single test 56: don't replay a symlink open request (3440) ========================================================== 22:16:23 (1767842183) [ 2751.567484] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2756.063920] Lustre: lustre-MDT0000-lwp-MDT0001: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 2756.068545] Lustre: Skipped 54 previous similar messages [ 2763.231186] Lustre: 3140:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1767842189/real 1767842189] req@000000003723dd5a x1853714076971904/t0(0) o400->MGC192.168.202.114@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1767842196 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:3.0' [ 2763.240960] Lustre: 3140:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 11 previous similar messages [ 2763.243382] LustreError: 166-1: MGC192.168.202.114@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2763.248752] LustreError: Skipped 11 previous similar messages [ 2769.494977] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 2769.497019] Lustre: Skipped 13 previous similar messages [ 2771.062365] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 2774.544305] Lustre: lustre-OST0001: deleting orphan objects from 0x0:3299 to 0x0:3425 [ 2774.544370] Lustre: lustre-OST0000: deleting orphan objects from 0x0:3523 to 0x0:3553 [ 2776.600501] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2777.229988] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2791.202211] Lustre: DEBUG MARKER: == replay-single test 57: test recovery from llog for setattr op ========================================================== 22:17:04 (1767842224) [ 2793.089171] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2793.812189] Lustre: Failing over lustre-MDT0000 [ 2793.814175] Lustre: Skipped 12 previous similar messages [ 2793.945467] Lustre: server umount lustre-MDT0000 complete [ 2793.947090] Lustre: Skipped 12 previous similar messages [ 2808.289537] LustreError: 129057:0:(ldlm_resource.c:1127:ldlm_resource_complain()) MGC192.168.202.114@tcp: namespace resource [0x65727473756c:0x5:0x0].0x0 (000000001319c62e) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 2809.800341] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 2809.803749] Lustre: Skipped 12 previous similar messages [ 2810.243381] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 2813.444534] Lustre: lustre-OST0000: deleting orphan objects from 0x0:3555 to 0x0:3585 [ 2813.447309] Lustre: lustre-OST0001: deleting orphan objects from 0x0:3299 to 0x0:3457 [ 2815.694678] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2816.378584] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2818.936512] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 2824.439322] Lustre: DEBUG MARKER: == replay-single test 58a: test recovery from llog for setattr op (test llog_gen_rec) ========================================================== 22:17:37 (1767842257) [ 2834.777025] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2852.321269] Lustre: Evicted from MGS (at 192.168.202.114@tcp) after server handle changed from 0x50fb2a7c8cafcf0c to 0x50fb2a7c8cb129e0 [ 2852.325752] Lustre: Skipped 12 previous similar messages [ 2853.980946] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 2857.459808] Lustre: lustre-MDT0000: Recovery over after 0:05, of 2 clients 2 recovered and 0 were evicted. [ 2857.463196] Lustre: Skipped 13 previous similar messages [ 2857.480499] Lustre: lustre-OST0000: deleting orphan objects from 0x0:4836 to 0x0:4865 [ 2857.480504] Lustre: lustre-OST0001: deleting orphan objects from 0x0:4708 to 0x0:4737 [ 2859.529346] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2860.118366] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2880.289577] Lustre: DEBUG MARKER: == replay-single test 58b: test replay of setxattr op ==== 22:18:33 (1767842313) [ 2881.988744] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2909.189337] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 2912.284694] Lustre: lustre-OST0000: deleting orphan objects from 0x0:4867 to 0x0:4897 [ 2912.284763] Lustre: lustre-OST0001: deleting orphan objects from 0x0:4708 to 0x0:4769 [ 2914.747687] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2915.459920] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2919.494550] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount FULL mgc.*.mgs_server_uuid [ 2920.198808] Lustre: DEBUG MARKER: mgc.*.mgs_server_uuid in FULL state after 0 sec [ 2922.742469] Lustre: DEBUG MARKER: == replay-single test 58c: resend/reconstruct setxattr op ========================================================== 22:19:16 (1767842356) [ 2928.452690] Lustre: *** cfs_fail_loc=123, val=2147483648*** [ 2957.674477] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 2957.676738] Lustre: Skipped 2 previous similar messages [ 2957.678801] LustreError: 6124:0:(ldlm_lib.c:3224:target_send_reply_msg()) @@@ dropping reply req@000000009026bfd1 x1853714071572864/t300647710728(0) o36->887bfe44-15a6-4ae3-80bd-930b965868a1@192.168.202.14@tcp:101/0 lens 66040/440 e 0 to 0 dl 1767842416 ref 1 fl Interpret:/0/0 rc 0/0 job:'setfattr.0' [ 2957.685633] LustreError: 6124:0:(ldlm_lib.c:3224:target_send_reply_msg()) Skipped 1 previous similar message [ 2984.905627] Lustre: 23614:0:(mdt_recovery.c:200:mdt_req_from_lrd()) @@@ restoring transno req@00000000fa821c46 x1853714071572864/t300647710728(0) o36->887bfe44-15a6-4ae3-80bd-930b965868a1@192.168.202.14@tcp:129/0 lens 66040/440 e 0 to 0 dl 1767842444 ref 1 fl Interpret:/2/0 rc 0/0 job:'setfattr.0' [ 2988.255613] Lustre: DEBUG MARKER: SKIP: replay-single test_59 skipping ALWAYS excluded test 59 [ 2988.818174] Lustre: DEBUG MARKER: == replay-single test 60: test llog post recovery init vs llog unlink ========================================================== 22:20:22 (1767842422) [ 2991.568394] LustreError: 135085:0:(osd_handler.c:698:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 2991.571586] LustreError: 135085:0:(osd_handler.c:698:osd_ro()) Skipped 11 previous similar messages [ 2991.876223] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2994.143882] LustreError: 11-0: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 2994.147512] LustreError: Skipped 11 previous similar messages [ 3009.042214] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 3012.793914] Lustre: lustre-OST0001: deleting orphan objects from 0x0:4870 to 0x0:4897 [ 3012.793925] Lustre: lustre-OST0000: deleting orphan objects from 0x0:4999 to 0x0:5025 [ 3014.642269] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3015.206287] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3019.253995] Lustre: DEBUG MARKER: == replay-single test 61a: test race llog recovery vs llog cleanup ========================================================== 22:20:52 (1767842452) [ 3024.404570] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 3042.435977] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 3042.449036] Lustre: lustre-OST0000: deleting orphan objects from 0x280000400:34 to 0x280000400:129 [ 3042.450626] Lustre: lustre-OST0000: deleting orphan objects from 0x0:5426 to 0x0:5441 [ 3068.352373] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 3069.001498] Lustre: lustre-OST0000: deleting orphan objects from 0x280000400:34 to 0x280000400:161 [ 3069.003382] Lustre: lustre-OST0000: deleting orphan objects from 0x0:5426 to 0x0:5473 [ 3072.209581] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 3072.778845] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 3106.688529] Lustre: DEBUG MARKER: == replay-single test 61b: test race mds llog sync vs llog cleanup ========================================================== 22:22:20 (1767842540) [ 3107.807962] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3127.799659] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 3131.393978] Lustre: lustre-OST0001: deleting orphan objects from 0x0:5298 to 0x0:5313 [ 3131.393978] Lustre: lustre-OST0000: deleting orphan objects from 0x0:5426 to 0x0:5505 [ 3154.540449] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 3154.543718] Lustre: Skipped 13 previous similar messages [ 3155.996798] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 3159.545805] Lustre: lustre-OST0000: deleting orphan objects from 0x0:5426 to 0x0:5537 [ 3159.545969] Lustre: lustre-OST0001: deleting orphan objects from 0x0:5298 to 0x0:5345 [ 3161.540299] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3162.171612] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3165.684607] Lustre: DEBUG MARKER: == replay-single test 61c: test race mds llog sync vs llog cleanup ========================================================== 22:23:19 (1767842599) [ 3190.782868] Lustre: lustre-OST0000: deleting orphan objects from 0x280000400:34 to 0x280000400:193 [ 3190.783862] Lustre: lustre-OST0000: deleting orphan objects from 0x0:5539 to 0x0:5569 [ 3190.832531] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 3194.437674] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 3194.929295] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 3198.644959] Lustre: DEBUG MARKER: == replay-single test 61d: error in llog_setup should cleanup the llog context correctly ========================================================== 22:23:52 (1767842632) [ 3202.361518] Lustre: *** cfs_fail_loc=605, val=0*** [ 3202.362464] LustreError: 144116:0:(llog_obd.c:207:llog_setup()) MGS: ctxt 0 lop_setup=00000000b9fd0825 failed: rc = -95 [ 3202.364674] LustreError: 144116:0:(obd_config.c:774:class_setup()) setup MGS failed (-95) [ 3202.367248] LustreError: 144116:0:(obd_mount.c:200:lustre_start_simple()) MGS setup error -95 [ 3202.369487] LustreError: 144116:0:(obd_mount_server.c:131:server_deregister_mount()) MGS not registered [ 3202.371798] LustreError: 15e-a: Failed to start MGS 'MGS' (-95). Is the 'mgs' module loaded? [ 3202.373986] LustreError: 144116:0:(obd_mount_server.c:1644:server_put_super()) no obd lustre-MDT0000 [ 3202.390370] LustreError: 144116:0:(super25.c:183:lustre_fill_super()) llite: Unable to mount : rc = -95 [ 3204.221477] LustreError: 137-5: lustre-MDT0000_UUID: 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. [ 3204.228895] LustreError: Skipped 307 previous similar messages [ 3205.823438] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 3208.527070] Lustre: DEBUG MARKER: == replay-single test 62: don't mis-drop resent replay === 22:24:02 (1767842642) [ 3209.731298] Lustre: lustre-OST0001: deleting orphan objects from 0x0:5347 to 0x0:5377 [ 3209.731346] Lustre: lustre-OST0000: deleting orphan objects from 0x0:5539 to 0x0:5601 [ 3210.940984] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3228.129448] Lustre: MGC192.168.202.114@tcp: Connection restored to (at 0@lo) [ 3228.136188] Lustre: Skipped 64 previous similar messages [ 3228.616948] Lustre: *** cfs_fail_loc=707, val=0*** [ 3229.717020] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 3254.223680] Lustre: lustre-MDT0000: Client 887bfe44-15a6-4ae3-80bd-930b965868a1 (at 192.168.202.14@tcp) reconnected, waiting for 2 clients in recovery for 0:58 [ 3254.332619] Lustre: lustre-OST0000: deleting orphan objects from 0x0:5615 to 0x0:5633 [ 3254.332623] Lustre: lustre-OST0001: deleting orphan objects from 0x0:5390 to 0x0:5409 [ 3256.322556] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3256.875807] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3260.467284] Lustre: DEBUG MARKER: == replay-single test 65a: AT: verify early replies ====== 22:24:53 (1767842693) [ 3283.792839] LustreError: 6124:0:(fail.c:138:__cfs_fail_timeout_set()) cfs_fail_timeout id 50a sleeping for 6000ms [ 3289.831141] LustreError: 6124:0:(fail.c:149:__cfs_fail_timeout_set()) cfs_fail_timeout id 50a awake [ 3301.280107] Lustre: DEBUG MARKER: == replay-single test 65b: AT: verify early replies on packed reply / bulk ========================================================== 22:25:34 (1767842734) [ 3324.603468] LustreError: 36325:0:(fail.c:138:__cfs_fail_timeout_set()) cfs_fail_timeout id 224 sleeping for 6000ms [ 3330.639110] LustreError: 36325:0:(fail.c:149:__cfs_fail_timeout_set()) cfs_fail_timeout id 224 awake [ 3333.294051] Lustre: DEBUG MARKER: == replay-single test 66a: AT: verify MDT service time adjusts with no early replies ========================================================== 22:26:06 (1767842766) [ 3356.192517] LustreError: 6125:0:(fail.c:138:__cfs_fail_timeout_set()) cfs_fail_timeout id 50a sleeping for 5000ms [ 3361.295103] LustreError: 6125:0:(fail.c:149:__cfs_fail_timeout_set()) cfs_fail_timeout id 50a awake [ 3361.983597] LustreError: 7457:0:(fail.c:138:__cfs_fail_timeout_set()) cfs_fail_timeout id 50a sleeping for 10000ms [ 3372.071176] LustreError: 7457:0:(fail.c:149:__cfs_fail_timeout_set()) cfs_fail_timeout id 50a awake [ 3383.660458] Lustre: DEBUG MARKER: == replay-single test 66b: AT: verify net latency adjusts ========================================================== 22:26:57 (1767842817) [ 3436.351658] Lustre: DEBUG MARKER: == replay-single test 67a: AT: verify slow request processing doesn't induce reconnects ========================================================== 22:27:49 (1767842869) [ 3459.398316] LustreError: 23614:0:(fail.c:138:__cfs_fail_timeout_set()) cfs_fail_timeout id 50a sleeping for 400ms [ 3459.815170] LustreError: 23614:0:(fail.c:149:__cfs_fail_timeout_set()) cfs_fail_timeout id 50a awake [ 3467.729355] LustreError: 6125:0:(fail.c:138:__cfs_fail_timeout_set()) cfs_fail_timeout id 50a sleeping for 400ms [ 3467.731652] LustreError: 6125:0:(fail.c:138:__cfs_fail_timeout_set()) Skipped 26 previous similar messages [ 3468.151057] LustreError: 6125:0:(fail.c:149:__cfs_fail_timeout_set()) cfs_fail_timeout id 50a awake [ 3468.153900] LustreError: 6125:0:(fail.c:149:__cfs_fail_timeout_set()) Skipped 26 previous similar messages [ 3483.977720] LustreError: 6125:0:(fail.c:138:__cfs_fail_timeout_set()) cfs_fail_timeout id 50a sleeping for 400ms [ 3483.979960] LustreError: 6125:0:(fail.c:138:__cfs_fail_timeout_set()) Skipped 71 previous similar messages [ 3484.399124] LustreError: 6125:0:(fail.c:149:__cfs_fail_timeout_set()) cfs_fail_timeout id 50a awake [ 3484.401481] LustreError: 6125:0:(fail.c:149:__cfs_fail_timeout_set()) Skipped 70 previous similar messages [ 3484.848106] LustreError: 7727:0:(fail.c:144:__cfs_fail_timeout_set()) cfs_fail_timeout interrupted [ 3486.785755] Lustre: DEBUG MARKER: == replay-single test 67b: AT: verify instant slowdown doesn't induce reconnects ========================================================== 22:28:40 (1767842920) [ 3511.140144] Lustre: DEBUG MARKER: phase 2 [ 3514.028252] Lustre: DEBUG MARKER: == replay-single test 68: AT: verify slowing locks ======= 22:29:07 (1767842947) [ 3584.402311] Lustre: DEBUG MARKER: == replay-single test 70a: check multi client t-f ======== 22:30:17 (1767843017) [ 3584.928828] Lustre: DEBUG MARKER: SKIP: replay-single test_70a Need two or more clients, have 1 [ 3585.485183] Lustre: DEBUG MARKER: == replay-single test 70b: dbench 2mdts recovery; 1 clients ========================================================== 22:30:18 (1767843018) [ 3587.306964] Lustre: DEBUG MARKER: Started rundbench load pid=133511 ... [ 3589.690451] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3591.196636] Lustre: DEBUG MARKER: test_70b fail mds1 1 times [ 3591.907138] Lustre: Failing over lustre-MDT0000 [ 3591.908467] Lustre: Skipped 10 previous similar messages [ 3591.942194] Lustre: lustre-MDT0000: Not available for connect from 192.168.202.14@tcp (stopping) [ 3591.944098] Lustre: Skipped 3 previous similar messages [ 3592.164232] Lustre: server umount lustre-MDT0000 complete [ 3592.165705] Lustre: Skipped 11 previous similar messages [ 3594.207486] LustreError: 11-0: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3594.210042] LustreError: Skipped 6 previous similar messages [ 3594.211352] Lustre: lustre-MDT0000-osp-MDT0001: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 3594.214880] Lustre: Skipped 38 previous similar messages [ 3603.935213] Lustre: 3142:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1767843030/real 1767843030] req@000000003c484e41 x1853714077830080/t0(0) o400->MGC192.168.202.114@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1767843037 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:2.0' [ 3603.942774] Lustre: 3142:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 7 previous similar messages [ 3603.945072] LustreError: 166-1: MGC192.168.202.114@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3603.947767] LustreError: Skipped 8 previous similar messages [ 3610.080868] Lustre: Evicted from MGS (at 192.168.202.114@tcp) after server handle changed from 0x50fb2a7c8cb523b1 to 0x50fb2a7c8cb5cf15 [ 3610.085462] Lustre: Skipped 6 previous similar messages [ 3610.220164] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3610.222455] Lustre: Skipped 11 previous similar messages [ 3611.592374] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 3611.594775] Lustre: Skipped 10 previous similar messages [ 3611.835041] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 3615.408086] Lustre: lustre-MDT0000: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 3615.410780] Lustre: Skipped 9 previous similar messages [ 3615.424802] Lustre: lustre-OST0001: deleting orphan objects from 0x0:5519 to 0x0:5537 [ 3615.426156] Lustre: lustre-OST0000: deleting orphan objects from 0x0:5762 to 0x0:5793 [ 3617.416965] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3618.044370] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3621.382481] LustreError: 154071:0:(osd_handler.c:698:osd_ro()) lustre-MDT0001: *** setting device osd-zfs read-only *** [ 3621.387470] LustreError: 154071:0:(osd_handler.c:698:osd_ro()) Skipped 3 previous similar messages [ 3621.690087] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 3623.274606] Lustre: DEBUG MARKER: test_70b fail mds2 2 times [ 3638.406611] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 3642.385871] Lustre: lustre-OST0000: deleting orphan objects from 0x280000400:197 to 0x280000400:225 [ 3642.385871] Lustre: lustre-OST0001: deleting orphan objects from 0x2c0000400:4 to 0x2c0000400:33 [ 3644.406159] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 3645.037826] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3648.656325] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3650.210276] Lustre: DEBUG MARKER: test_70b fail mds1 3 times [ 3667.523142] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 3671.240117] Lustre: lustre-OST0001: deleting orphan objects from 0x0:5846 to 0x0:5889 [ 3671.240154] Lustre: lustre-OST0000: deleting orphan objects from 0x0:6102 to 0x0:6145 [ 3673.209826] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3673.776403] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3677.448721] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 3678.977643] Lustre: DEBUG MARKER: test_70b fail mds2 4 times [ 3694.232419] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 3698.172363] Lustre: lustre-OST0001: deleting orphan objects from 0x2c0000400:4 to 0x2c0000400:65 [ 3698.172364] Lustre: lustre-OST0000: deleting orphan objects from 0x280000400:197 to 0x280000400:257 [ 3700.086844] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 3700.716511] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3704.395936] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3705.905819] Lustre: DEBUG MARKER: test_70b fail mds1 5 times [ 3723.185945] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 3727.216365] Lustre: lustre-OST0001: deleting orphan objects from 0x0:6229 to 0x0:6273 [ 3727.216371] Lustre: lustre-OST0000: deleting orphan objects from 0x0:6485 to 0x0:6529 [ 3729.131467] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3729.727103] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3733.292283] Lustre: DEBUG MARKER: == replay-single test 70c: tar 2mdts recovery ============ 22:32:46 (1767843166) [ 3855.038548] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 3865.773980] Lustre: DEBUG MARKER: test_70c fail mds2 1 times [ 3866.466126] Lustre: lustre-MDT0001: Not available for connect from 192.168.202.14@tcp (stopping) [ 3870.176224] LustreError: 137-5: lustre-MDT0001_UUID: 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. [ 3870.179580] LustreError: Skipped 122 previous similar messages [ 3879.231149] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 3879.233544] Lustre: Skipped 8 previous similar messages [ 3880.493776] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 3884.513081] Lustre: lustre-MDT0001-lwp-OST0001: Connection restored to (at 0@lo) [ 3884.518791] Lustre: Skipped 25 previous similar messages [ 3886.320267] Lustre: lustre-OST0001: deleting orphan objects from 0x2c0000400:1277 to 0x2c0000400:1313 [ 3886.334458] Lustre: lustre-OST0000: deleting orphan objects from 0x280000400:1469 to 0x280000400:1505 [ 3888.121489] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 3888.678565] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4011.510297] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 4022.237971] Lustre: DEBUG MARKER: test_70c fail mds2 2 times [ 4037.335620] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 4043.544171] Lustre: lustre-OST0000: deleting orphan objects from 0x280000400:2839 to 0x280000400:2881 [ 4043.546920] Lustre: lustre-OST0001: deleting orphan objects from 0x2c0000400:2648 to 0x2c0000400:2689 [ 4045.345400] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 4045.904801] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4066.289227] Lustre: DEBUG MARKER: == replay-single test 70d: mkdir/rmdir striped dir 2mdts recovery ========================================================== 22:38:19 (1767843499) [ 4188.069123] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4198.895364] Lustre: DEBUG MARKER: test_70d fail mds1 1 times [ 4199.603224] Lustre: Failing over lustre-MDT0000 [ 4199.603760] LustreError: 11-0: lustre-MDT0000-osp-MDT0001: operation ldlm_enqueue to node 0@lo failed: rc = -19 [ 4199.604945] Lustre: Skipped 6 previous similar messages [ 4199.612601] LustreError: Skipped 6 previous similar messages [ 4199.615058] Lustre: lustre-MDT0000-osp-MDT0001: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 4199.620625] Lustre: Skipped 23 previous similar messages [ 4199.622928] Lustre: lustre-MDT0000: Not available for connect from 192.168.202.14@tcp (stopping) [ 4199.814733] Lustre: server umount lustre-MDT0000 complete [ 4199.817296] Lustre: Skipped 6 previous similar messages [ 4212.191166] Lustre: 3139:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1767843638/real 1767843638] req@00000000826f8743 x1853714084837632/t0(0) o400->MGC192.168.202.114@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1767843645 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:3.0' [ 4212.197842] Lustre: 3139:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 4212.201575] LustreError: 166-1: MGC192.168.202.114@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4212.207015] LustreError: Skipped 2 previous similar messages [ 4218.337186] Lustre: Evicted from MGS (at 192.168.202.114@tcp) after server handle changed from 0x50fb2a7c8cbbdf78 to 0x50fb2a7c8cf06cc2 [ 4218.340185] Lustre: Skipped 2 previous similar messages [ 4218.434319] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4218.436348] Lustre: Skipped 6 previous similar messages [ 4219.537736] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4219.540065] Lustre: Skipped 6 previous similar messages [ 4219.783836] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 4224.347449] Lustre: lustre-MDT0000: Recovery over after 0:05, of 2 clients 2 recovered and 0 were evicted. [ 4224.351299] Lustre: Skipped 6 previous similar messages [ 4224.373709] Lustre: lustre-OST0001: deleting orphan objects from 0x0:9179 to 0x0:9217 [ 4224.373784] Lustre: lustre-OST0000: deleting orphan objects from 0x0:9436 to 0x0:9473 [ 4226.498447] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4227.162169] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4349.707474] LustreError: 165458:0:(osd_handler.c:698:osd_ro()) lustre-MDT0001: *** setting device osd-zfs read-only *** [ 4349.710459] LustreError: 165458:0:(osd_handler.c:698:osd_ro()) Skipped 6 previous similar messages [ 4350.012035] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 4360.718234] Lustre: DEBUG MARKER: test_70d fail mds2 2 times [ 4361.368622] Lustre: lustre-MDT0001: Not available for connect from 192.168.202.14@tcp (stopping) [ 4361.371611] Lustre: Skipped 1 previous similar message [ 4375.536732] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 4380.044089] Lustre: lustre-OST0000: deleting orphan objects from 0x280000400:3673 to 0x280000400:3713 [ 4380.050461] Lustre: lustre-OST0001: deleting orphan objects from 0x2c0000400:3481 to 0x2c0000400:3521 [ 4382.084833] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 4382.634938] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4386.106686] Lustre: DEBUG MARKER: == replay-single test 70e: rename cross-MDT with random fails ========================================================== 22:43:39 (1767843819) [ 4507.956556] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4518.662282] Lustre: DEBUG MARKER: test_70e fail mds1 1 times [ 4522.464279] LustreError: 137-5: lustre-MDT0000_UUID: 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. [ 4522.471904] LustreError: Skipped 54 previous similar messages [ 4534.754151] Lustre: MGC192.168.202.114@tcp: Connection restored to (at 0@lo) [ 4534.757587] Lustre: Skipped 13 previous similar messages [ 4534.885195] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4534.888574] Lustre: Skipped 3 previous similar messages [ 4536.373633] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 4543.100164] Lustre: lustre-OST0001: deleting orphan objects from 0x0:11647 to 0x0:11681 [ 4543.111320] Lustre: lustre-OST0000: deleting orphan objects from 0x0:11903 to 0x0:11937 [ 4544.990575] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4545.688456] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4668.437466] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4679.245735] Lustre: DEBUG MARKER: test_70e fail mds1 2 times [ 4698.100366] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 4705.107318] Lustre: lustre-OST0001: deleting orphan objects from 0x0:13839 to 0x0:13857 [ 4705.107765] Lustre: lustre-OST0000: deleting orphan objects from 0x0:14095 to 0x0:14113 [ 4707.232665] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4707.760947] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4711.171105] Lustre: DEBUG MARKER: == replay-single test 70f: OSS O_DIRECT recovery with 1 clients ========================================================== 22:49:04 (1767844144) [ 4715.846136] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 4717.304048] Lustre: DEBUG MARKER: test_70f failing OST 1 times [ 4731.873913] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 4732.329582] Lustre: lustre-OST0000: deleting orphan objects from 0x0:14197 to 0x0:14241 [ 4732.330381] Lustre: lustre-OST0000: deleting orphan objects from 0x280000400:3723 to 0x280000400:3745 [ 4735.929933] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 4736.586677] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4744.320783] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 4745.831543] Lustre: DEBUG MARKER: test_70f failing OST 2 times [ 4760.553374] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 4760.752618] Lustre: lustre-OST0000: deleting orphan objects from 0x280000400:3723 to 0x280000400:3777 [ 4760.754301] Lustre: lustre-OST0000: deleting orphan objects from 0x0:14197 to 0x0:14273 [ 4764.661747] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 4765.302572] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4772.957297] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 4774.456197] Lustre: DEBUG MARKER: test_70f failing OST 3 times [ 4789.067395] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 4789.628492] Lustre: lustre-OST0000: deleting orphan objects from 0x0:14197 to 0x0:14305 [ 4789.632592] Lustre: lustre-OST0000: deleting orphan objects from 0x280000400:3723 to 0x280000400:3809 [ 4792.913074] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 4793.514606] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4798.854144] Lustre: DEBUG MARKER: == replay-single test 71a: mkdir/rmdir striped dir with 2 mdts recovery ========================================================== 22:50:32 (1767844232) [ 4920.619041] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 4922.026770] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4932.826917] Lustre: DEBUG MARKER: fail mds2 mds1 1 times [ 4933.520440] Lustre: Failing over lustre-MDT0001 [ 4933.521824] Lustre: Skipped 6 previous similar messages [ 4933.522946] LustreError: 11-0: lustre-MDT0001-osp-MDT0000: operation out_update to node 0@lo failed: rc = -19 [ 4933.527306] LustreError: Skipped 9 previous similar messages [ 4933.529030] Lustre: lustre-MDT0001-osp-MDT0000: Connection to lustre-MDT0001 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 4933.534197] Lustre: Skipped 20 previous similar messages [ 4933.535958] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 4933.708652] Lustre: server umount lustre-MDT0001 complete [ 4933.710026] Lustre: Skipped 6 previous similar messages [ 4948.383128] Lustre: 3142:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1767844374/real 1767844374] req@000000005c52c85a x1853714092755968/t0(0) o400->MGC192.168.202.114@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1767844381 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:3.0' [ 4948.389524] Lustre: 3142:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 4948.391832] LustreError: 166-1: MGC192.168.202.114@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4948.394665] LustreError: Skipped 2 previous similar messages [ 5055.015110] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 5055.019542] Lustre: Skipped 6 previous similar messages [ 5056.527608] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 5058.504395] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 5058.507361] Lustre: Skipped 6 previous similar messages [ 5077.472305] Lustre: Evicted from MGS (at 192.168.202.114@tcp) after server handle changed from 0x50fb2a7c8d1add8d to 0x50fb2a7c8d253e29 [ 5077.475346] Lustre: Skipped 2 previous similar messages [ 5079.038319] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 5082.672292] Lustre: lustre-MDT0001: Recovery over after 0:24, of 2 clients 2 recovered and 0 were evicted. [ 5082.675795] Lustre: Skipped 6 previous similar messages [ 5082.690341] Lustre: lustre-OST0001: deleting orphan objects from 0x2c0000400:3530 to 0x2c0000400:3553 [ 5082.693477] Lustre: lustre-OST0000: deleting orphan objects from 0x280000400:3723 to 0x280000400:3841 [ 5090.715335] Lustre: lustre-OST0001: deleting orphan objects from 0x0:13940 to 0x0:13985 [ 5090.715388] Lustre: lustre-OST0000: deleting orphan objects from 0x0:14197 to 0x0:14337 [ 5092.980306] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 5093.577815] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5094.122665] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5097.398522] Lustre: DEBUG MARKER: == replay-single test 73a: open(O_CREAT), unlink, replay, reconnect before open replay, close ========================================================== 22:55:30 (1767844530) [ 5098.374617] LustreError: 178342:0:(osd_handler.c:698:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 5098.377402] LustreError: 178342:0:(osd_handler.c:698:osd_ro()) Skipped 7 previous similar messages [ 5098.668565] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5116.872957] Lustre: *** cfs_fail_loc=302, val=2147483648*** [ 5117.787588] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 5124.046451] Lustre: lustre-MDT0000: Client 887bfe44-15a6-4ae3-80bd-930b965868a1 (at 192.168.202.14@tcp) reconnected, waiting for 2 clients in recovery for 0:57 [ 5124.056651] Lustre: 176442:0:(mdt_recovery.c:200:mdt_req_from_lrd()) @@@ restoring transno req@00000000a0451880 x1853714111975232/t347892352388(347892352388) o101->887bfe44-15a6-4ae3-80bd-930b965868a1@192.168.202.14@tcp:738/0 lens 648/3424 e 0 to 0 dl 1767844563 ref 1 fl Interpret:/6/0 rc 0/0 job:'lfs.0' [ 5124.091289] Lustre: lustre-OST0000: deleting orphan objects from 0x0:14197 to 0x0:14369 [ 5124.091297] Lustre: lustre-OST0001: deleting orphan objects from 0x0:13987 to 0x0:14017 [ 5125.875254] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 5126.362625] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5129.718667] Lustre: DEBUG MARKER: == replay-single test 73b: open(O_CREAT), unlink, replay, reconnect at open_replay reply, close ========================================================== 22:56:03 (1767844563) [ 5131.020631] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5133.258236] LustreError: 137-5: lustre-MDT0000_UUID: not available for connect from 192.168.202.14@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 5133.263516] LustreError: Skipped 220 previous similar messages [ 5150.177262] Lustre: MGC192.168.202.114@tcp: Connection restored to (at 0@lo) [ 5150.180139] Lustre: Skipped 27 previous similar messages [ 5150.294114] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 5150.296523] Lustre: Skipped 7 previous similar messages [ 5151.635274] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 5151.697714] Lustre: *** cfs_fail_loc=157, val=2147483648*** [ 5151.699192] LustreError: 176896:0:(ldlm_lib.c:3224:target_send_reply_msg()) @@@ dropping reply req@000000003c2616fd x1853714111975232/t347892352388(347892352388) o101->887bfe44-15a6-4ae3-80bd-930b965868a1@192.168.202.14@tcp:10/0 lens 648/600 e 0 to 0 dl 1767844590 ref 1 fl Interpret:/4/0 rc 301/0 job:'lfs.0' [ 5158.863469] Lustre: lustre-MDT0000: Client 887bfe44-15a6-4ae3-80bd-930b965868a1 (at 192.168.202.14@tcp) reconnected, waiting for 2 clients in recovery for 0:58 [ 5158.869967] Lustre: 176422:0:(mdt_recovery.c:200:mdt_req_from_lrd()) @@@ restoring transno req@00000000d1669784 x1853714111975232/t347892352388(347892352388) o101->887bfe44-15a6-4ae3-80bd-930b965868a1@192.168.202.14@tcp:18/0 lens 648/3424 e 0 to 0 dl 1767844598 ref 1 fl Interpret:/6/0 rc 0/0 job:'lfs.0' [ 5158.913447] Lustre: lustre-OST0000: deleting orphan objects from 0x0:14197 to 0x0:14401 [ 5158.913455] Lustre: lustre-OST0001: deleting orphan objects from 0x0:14019 to 0x0:14049 [ 5160.820285] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 5161.404613] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5164.902402] Lustre: DEBUG MARKER: == replay-single test 74: Ensure applications don't fail waiting for OST recovery ========================================================== 22:56:38 (1767844598) [ 5184.534143] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 5185.342322] Lustre: lustre-MDT0000: Denying connection for new client a652ea96-3308-4861-8bb0-bf3dff24c8bc (at 192.168.202.14@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:59 [ 5185.351518] Lustre: Skipped 13 previous similar messages [ 5188.099996] Lustre: lustre-OST0001: deleting orphan objects from 0x0:14019 to 0x0:14081 [ 5193.474020] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 5193.746846] Lustre: lustre-OST0000: Denying connection for new client a652ea96-3308-4861-8bb0-bf3dff24c8bc (at 192.168.202.14@tcp), waiting for 2 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:59 [ 5193.754881] Lustre: Skipped 1 previous similar message [ 5193.935495] Lustre: lustre-OST0000: deleting orphan objects from 0x280000400:3723 to 0x280000400:3873 [ 5193.937030] Lustre: lustre-OST0000: deleting orphan objects from 0x0:14197 to 0x0:14433 [ 5197.789074] Lustre: DEBUG MARKER: == replay-single test 80a: DNE: create remote dir, drop update rep from MDT0, fail MDT0 ========================================================== 22:57:11 (1767844631) [ 5198.177819] Lustre: *** cfs_fail_loc=1701, val=2147483648*** [ 5198.179928] LustreError: 176425:0:(ldlm_lib.c:3224:target_send_reply_msg()) @@@ dropping reply req@00000000435bf334 x1853714093068864/t365072220167(0) o1000->lustre-MDT0001-mdtlov_UUID@0@lo:57/0 lens 1056/4320 e 0 to 0 dl 1767844637 ref 1 fl Interpret:/0/0 rc 0/0 job:'osp_up0-1.0' [ 5199.417673] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5217.237575] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 5220.867393] Lustre: lustre-OST0000: deleting orphan objects from 0x0:14197 to 0x0:14465 [ 5220.868144] Lustre: lustre-OST0001: deleting orphan objects from 0x0:14083 to 0x0:14113 [ 5222.737195] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 5223.306654] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5226.897972] Lustre: DEBUG MARKER: == replay-single test 80b: DNE: create remote dir, drop update rep from MDT0, fail MDT1 ========================================================== 22:57:40 (1767844660) [ 5228.497575] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5229.818519] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 5230.466995] Lustre: lustre-MDT0001: Not available for connect from 192.168.202.14@tcp (stopping) [ 5230.469063] Lustre: Skipped 4 previous similar messages [ 5250.039250] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 5254.148604] Lustre: 176441:0:(mdt_recovery.c:200:mdt_req_from_lrd()) @@@ restoring transno req@00000000be9f0663 x1853714114043264/t30064772535(0) o36->a652ea96-3308-4861-8bb0-bf3dff24c8bc@192.168.202.14@tcp:140/0 lens 560/448 e 0 to 0 dl 1767844720 ref 1 fl Interpret:/2/0 rc 0/0 job:'lfs.0' [ 5254.155532] Lustre: lustre-OST0000: deleting orphan objects from 0x280000400:3884 to 0x280000400:3905 [ 5254.155564] Lustre: lustre-OST0001: deleting orphan objects from 0x2c0000400:3564 to 0x2c0000400:3585 [ 5256.149369] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 5256.695253] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5260.333354] Lustre: DEBUG MARKER: == replay-single test 80c: DNE: create remote dir, drop update rep from MDT1, fail MDT[0,1] ========================================================== 22:58:13 (1767844693) [ 5260.721072] LustreError: 177699:0:(ldlm_lib.c:3224:target_send_reply_msg()) @@@ dropping reply req@000000002a63a598 x1853714093100032/t369367187488(0) o1000->lustre-MDT0001-mdtlov_UUID@0@lo:119/0 lens 2200/4320 e 0 to 0 dl 1767844699 ref 1 fl Interpret:/0/0 rc 0/0 job:'osp_up0-1.0' [ 5260.728622] LustreError: 177699:0:(ldlm_lib.c:3224:target_send_reply_msg()) Skipped 1 previous similar message [ 5261.983513] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5263.296127] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 5279.158720] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 5282.872560] Lustre: lustre-OST0000: deleting orphan objects from 0x0:14197 to 0x0:14497 [ 5282.873105] Lustre: lustre-OST0001: deleting orphan objects from 0x0:14083 to 0x0:14145 [ 5284.797274] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 5285.343186] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5301.789786] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 5305.358617] Lustre: lustre-OST0001: deleting orphan objects from 0x2c0000400:3596 to 0x2c0000400:3617 [ 5305.358666] Lustre: lustre-OST0000: deleting orphan objects from 0x280000400:3916 to 0x280000400:3937 [ 5307.267619] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 5307.832761] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5311.589923] Lustre: DEBUG MARKER: == replay-single test 80d: DNE: create remote dir, drop update rep from MDT1, fail 2 MDTs ========================================================== 22:59:05 (1767844745) [ 5311.978099] Lustre: *** cfs_fail_loc=1701, val=2147483648*** [ 5311.980138] Lustre: Skipped 2 previous similar messages [ 5316.264615] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5317.652838] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 5319.866480] LustreError: 132255:0:(ldlm_lockd.c:2526:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1767844753 with bad export cookie 5835304456621005208 [ 5319.871614] LustreError: 132255:0:(ldlm_lockd.c:2526:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 5319.878354] Lustre: lustre-MDT0001: Not available for connect from 192.168.202.14@tcp (stopping) [ 5319.881135] Lustre: Skipped 4 previous similar messages [ 5325.288870] LustreError: 191020:0:(client.c:1256:ptlrpc_import_delay_req()) @@@ IMP_CLOSED req@00000000ca6dc3e0 x1853714093129280/t0(0) o1000->lustre-MDT0000-osp-MDT0001@0@lo:24/4 lens 304/4320 e 0 to 0 dl 0 ref 2 fl Rpc:QU/0/ffffffff rc 0/-1 job:'umount.0' [ 5325.295066] LustreError: 191020:0:(osp_object.c:629:osp_attr_get()) lustre-MDT0000-osp-MDT0001: osp_attr_get update error [0x200000401:0x1:0x0]: rc = -5 [ 5354.420604] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 5368.105678] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 5372.565553] Lustre: lustre-OST0001: deleting orphan objects from 0x0:14083 to 0x0:14177 [ 5372.566040] Lustre: lustre-OST0000: deleting orphan objects from 0x0:14197 to 0x0:14529 [ 5372.601714] Lustre: 191485:0:(mdt_recovery.c:200:mdt_req_from_lrd()) @@@ restoring transno req@00000000d9311a02 x1853714114076096/t38654705732(0) o36->a652ea96-3308-4861-8bb0-bf3dff24c8bc@192.168.202.14@tcp:256/0 lens 560/448 e 0 to 0 dl 1767844836 ref 1 fl Interpret:/2/0 rc 0/0 job:'lfs.0' [ 5372.602782] Lustre: lustre-OST0000: deleting orphan objects from 0x280000400:3948 to 0x280000400:3969 [ 5372.610385] Lustre: lustre-OST0001: deleting orphan objects from 0x2c0000400:3628 to 0x2c0000400:3649 [ 5374.476556] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 5375.026457] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5375.596343] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5379.156093] Lustre: DEBUG MARKER: == replay-single test 80e: DNE: create remote dir, drop MDT1 rep, fail MDT0 ========================================================== 23:00:12 (1767844812) [ 5379.528595] LustreError: 191486:0:(ldlm_lib.c:3224:target_send_reply_msg()) @@@ dropping reply req@00000000fa3cd8de x1853714114093120/t42949673028(0) o36->a652ea96-3308-4861-8bb0-bf3dff24c8bc@192.168.202.14@tcp:238/0 lens 560/448 e 0 to 0 dl 1767844818 ref 1 fl Interpret:/0/0 rc 0/0 job:'lfs.0' [ 5379.538457] LustreError: 191486:0:(ldlm_lib.c:3224:target_send_reply_msg()) Skipped 1 previous similar message [ 5383.769495] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5386.696431] Lustre: lustre-MDT0001: Client a652ea96-3308-4861-8bb0-bf3dff24c8bc (at 192.168.202.14@tcp) reconnecting [ 5386.699378] Lustre: Skipped 2 previous similar messages [ 5403.105481] LustreError: 194013:0:(ldlm_resource.c:1127:ldlm_resource_complain()) MGC192.168.202.114@tcp: namespace resource [0x65727473756c:0x5:0x0].0x0 (000000006fc8ad96) refcount nonzero (2) after lock cleanup; forcing cleanup. [ 5404.625198] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 5408.258862] Lustre: lustre-OST0000: deleting orphan objects from 0x0:14197 to 0x0:14561 [ 5408.258882] Lustre: lustre-OST0001: deleting orphan objects from 0x0:14083 to 0x0:14209 [ 5410.148964] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 5410.734430] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5414.395224] Lustre: DEBUG MARKER: == replay-single test 80f: DNE: create remote dir, drop MDT1 rep, fail MDT1 ========================================================== 23:00:47 (1767844847) [ 5415.958216] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 5430.999592] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 5434.887079] Lustre: 191486:0:(mdt_recovery.c:200:mdt_req_from_lrd()) @@@ restoring transno req@00000000f3760aa2 x1853714114109184/t42949673096(0) o36->a652ea96-3308-4861-8bb0-bf3dff24c8bc@192.168.202.14@tcp:294/0 lens 560/448 e 0 to 0 dl 1767844874 ref 1 fl Interpret:/2/0 rc 0/0 job:'lfs.0' [ 5434.892462] Lustre: lustre-OST0000: deleting orphan objects from 0x280000400:3990 to 0x280000400:4033 [ 5434.892783] Lustre: lustre-OST0001: deleting orphan objects from 0x2c0000400:3670 to 0x2c0000400:3713 [ 5434.896066] Lustre: 191486:0:(mdt_recovery.c:200:mdt_req_from_lrd()) Skipped 1 previous similar message [ 5436.737600] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 5437.251725] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5440.827738] Lustre: DEBUG MARKER: == replay-single test 80g: DNE: create remote dir, drop MDT1 rep, fail MDT0, then MDT1 ========================================================== 23:01:14 (1767844874) [ 5441.201912] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 5441.203587] Lustre: Skipped 2 previous similar messages [ 5445.468371] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5446.700392] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 5465.028793] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 5468.679830] Lustre: lustre-OST0000: deleting orphan objects from 0x0:14197 to 0x0:14593 [ 5468.679850] Lustre: lustre-OST0001: deleting orphan objects from 0x0:14083 to 0x0:14241 [ 5470.488602] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 5471.109503] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5487.216689] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 5491.206991] Lustre: lustre-OST0000: deleting orphan objects from 0x280000400:4044 to 0x280000400:4065 [ 5491.207455] Lustre: lustre-OST0001: deleting orphan objects from 0x2c0000400:3724 to 0x2c0000400:3745 [ 5492.953408] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 5493.456085] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5496.980068] Lustre: DEBUG MARKER: == replay-single test 80h: DNE: create remote dir, drop MDT1 rep, fail 2 MDTs ========================================================== 23:02:10 (1767844930) [ 5501.486048] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5502.674944] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 5504.457021] Lustre: lustre-MDT0001: Client a652ea96-3308-4861-8bb0-bf3dff24c8bc (at 192.168.202.14@tcp) reconnecting [ 5504.459839] Lustre: Skipped 1 previous similar message [ 5504.461961] Lustre: 191902:0:(mdt_recovery.c:200:mdt_req_from_lrd()) @@@ restoring transno req@0000000012bd48c3 x1853714114141696/t51539607620(0) o36->a652ea96-3308-4861-8bb0-bf3dff24c8bc@192.168.202.14@tcp:363/0 lens 560/448 e 0 to 0 dl 1767844943 ref 1 fl Interpret:/2/0 rc 0/0 job:'lfs.0' [ 5504.468187] Lustre: 191902:0:(mdt_recovery.c:200:mdt_req_from_lrd()) Skipped 1 previous similar message [ 5504.726611] LustreError: 6109:0:(ldlm_lockd.c:2526:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1767844937 with bad export cookie 5835304456621018711 [ 5504.731026] LustreError: 6109:0:(ldlm_lockd.c:2526:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 5523.879572] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 5536.675969] LustreError: 11-0: lustre-MDT0000-osp-MDT0001: operation mds_connect to node 0@lo failed: rc = -114 [ 5536.678874] LustreError: Skipped 14 previous similar messages [ 5538.123615] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 5541.957892] Lustre: lustre-OST0001: deleting orphan objects from 0x2c0000400:3756 to 0x2c0000400:3777 [ 5541.957955] Lustre: lustre-OST0000: deleting orphan objects from 0x280000400:4076 to 0x280000400:4097 [ 5542.009186] Lustre: lustre-OST0001: deleting orphan objects from 0x0:14083 to 0x0:14273 [ 5542.009192] Lustre: lustre-OST0000: deleting orphan objects from 0x0:14197 to 0x0:14625 [ 5543.844383] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 5544.364813] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5544.875594] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5548.498369] Lustre: DEBUG MARKER: == replay-single test 81a: DNE: unlink remote dir, drop MDT0 update rep, fail MDT1 ========================================================== 23:03:01 (1767844981) [ 5548.910922] LustreError: 7734:0:(ldlm_lib.c:3224:target_send_reply_msg()) @@@ dropping reply req@00000000562796cc x1853714093228032/t390842023949(0) o1000->lustre-MDT0001-mdtlov_UUID@0@lo:408/0 lens 640/4320 e 0 to 0 dl 1767844988 ref 1 fl Interpret:/0/0 rc 0/0 job:'osp_up0-1.0' [ 5548.917519] LustreError: 7734:0:(ldlm_lib.c:3224:target_send_reply_msg()) Skipped 3 previous similar messages [ 5550.188736] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 5550.807862] Lustre: Failing over lustre-MDT0001 [ 5550.809188] Lustre: Skipped 17 previous similar messages [ 5550.819192] Lustre: lustre-MDT0001: Not available for connect from 192.168.202.14@tcp (stopping) [ 5550.821449] Lustre: Skipped 3 previous similar messages [ 5552.095867] Lustre: lustre-MDT0001-lwp-OST0000: Connection to lustre-MDT0001 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 5552.099665] Lustre: Skipped 56 previous similar messages [ 5556.199127] LustreError: 202926:0:(client.c:1256:ptlrpc_import_delay_req()) @@@ IMP_CLOSED req@000000003974fc17 x1853714093229632/t0(0) o1000->lustre-MDT0000-osp-MDT0001@0@lo:24/4 lens 304/4320 e 0 to 0 dl 0 ref 2 fl Rpc:QU/0/ffffffff rc 0/-1 job:'umount.0' [ 5556.204468] LustreError: 202926:0:(osp_object.c:629:osp_attr_get()) lustre-MDT0000-osp-MDT0001: osp_attr_get update error [0x200000401:0x1:0x0]: rc = -5 [ 5556.260499] Lustre: server umount lustre-MDT0001 complete [ 5556.261849] Lustre: Skipped 17 previous similar messages [ 5569.040400] LustreError: 203393:0:(llog_cat.c:418:llog_cat_id2handle()) lustre-MDT0000-osp-MDT0001: error opening log id [0x1:0x2c321:0x2]:0: rc = -2 [ 5570.559990] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 5574.208873] Lustre: lustre-OST0000: deleting orphan objects from 0x280000400:4108 to 0x280000400:4129 [ 5574.208873] Lustre: lustre-OST0001: deleting orphan objects from 0x2c0000400:3788 to 0x2c0000400:3809 [ 5576.088040] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 5576.668856] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5580.168624] Lustre: DEBUG MARKER: == replay-single test 81b: DNE: unlink remote dir, drop MDT0 update reply, fail MDT0 ========================================================== 23:03:33 (1767845013) [ 5581.725801] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5591.007151] Lustre: 203368:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1767845013/real 1767845013] req@000000000d10657e x1853714093242560/t0(0) o1000->lustre-MDT0000-osp-MDT0001@0@lo:24/4 lens 488/4320 e 0 to 1 dl 1767845024 ref 2 fl Rpc:XQr/0/ffffffff rc 0/-1 job:'osp_up0-1.0' [ 5591.018980] Lustre: 203368:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 22 previous similar messages [ 5591.519159] LustreError: 166-1: MGC192.168.202.114@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5591.523816] LustreError: Skipped 9 previous similar messages [ 5599.262541] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 5602.822452] Lustre: lustre-OST0001: deleting orphan objects from 0x0:14083 to 0x0:14305 [ 5602.822463] Lustre: lustre-OST0000: deleting orphan objects from 0x0:14197 to 0x0:14657 [ 5604.662285] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 5605.211894] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5608.719806] Lustre: DEBUG MARKER: == replay-single test 81c: DNE: unlink remote dir, drop MDT0 update reply, fail MDT0,MDT1 ========================================================== 23:04:02 (1767845042) [ 5610.288778] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5611.561528] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 5626.336553] LustreError: 206901:0:(ldlm_resource.c:1127:ldlm_resource_complain()) MGC192.168.202.114@tcp: namespace resource [0x65727473756c:0x5:0x0].0x0 (0000000021e67bf0) refcount nonzero (2) after lock cleanup; forcing cleanup. [ 5627.726341] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 5631.504483] Lustre: lustre-OST0000: deleting orphan objects from 0x0:14197 to 0x0:14689 [ 5631.504489] Lustre: lustre-OST0001: deleting orphan objects from 0x0:14083 to 0x0:14337 [ 5633.366399] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 5633.965503] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5649.948627] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 5654.036095] Lustre: lustre-OST0000: deleting orphan objects from 0x280000400:4108 to 0x280000400:4161 [ 5654.036150] Lustre: lustre-OST0001: deleting orphan objects from 0x2c0000400:3788 to 0x2c0000400:3841 [ 5655.971439] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 5656.518357] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5659.911119] Lustre: DEBUG MARKER: == replay-single test 81d: DNE: unlink remote dir, drop MDT0 update reply, fail 2 MDTs ========================================================== 23:04:53 (1767845093) [ 5661.451810] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5662.649592] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 5664.735736] LustreError: 6953:0:(ldlm_lockd.c:2526:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1767845098 with bad export cookie 5835304456621028882 [ 5664.741343] LustreError: 6953:0:(ldlm_lockd.c:2526:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 5682.655674] Lustre: Evicted from MGS (at 192.168.202.114@tcp) after server handle changed from 0x50fb2a7c8d267612 to 0x50fb2a7c8d267f57 [ 5682.659708] Lustre: Skipped 11 previous similar messages [ 5682.803095] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 5682.805502] Lustre: Skipped 21 previous similar messages [ 5684.181350] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 5697.952442] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 5697.955089] Lustre: Skipped 22 previous similar messages [ 5698.371306] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 5698.790073] Lustre: lustre-MDT0001: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 5698.793942] Lustre: Skipped 21 previous similar messages [ 5698.798361] Lustre: 210202:0:(mdt_recovery.c:200:mdt_req_from_lrd()) @@@ restoring transno req@000000005fa65b64 x1853714114181248/t64424509442(0) o36->a652ea96-3308-4861-8bb0-bf3dff24c8bc@192.168.202.14@tcp:583/0 lens 496/2888 e 0 to 0 dl 1767845163 ref 1 fl Interpret:/2/0 rc 0/0 job:'rmdir.0' [ 5698.803703] Lustre: 210202:0:(mdt_recovery.c:200:mdt_req_from_lrd()) Skipped 1 previous similar message [ 5698.811399] Lustre: lustre-OST0001: deleting orphan objects from 0x2c0000400:3788 to 0x2c0000400:3873 [ 5698.811400] Lustre: lustre-OST0000: deleting orphan objects from 0x280000400:4108 to 0x280000400:4193 [ 5699.828732] Lustre: lustre-OST0000: deleting orphan objects from 0x0:14197 to 0x0:14721 [ 5699.829236] Lustre: lustre-OST0001: deleting orphan objects from 0x0:14083 to 0x0:14369 [ 5702.181203] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 5702.685098] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5703.168216] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5706.417709] Lustre: DEBUG MARKER: == replay-single test 81e: DNE: unlink remote dir, drop MDT1 req reply, fail MDT0 ========================================================== 23:05:39 (1767845139) [ 5706.848355] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 5706.849781] Lustre: Skipped 5 previous similar messages [ 5707.978622] LustreError: 212156:0:(osd_handler.c:698:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 5707.981147] LustreError: 212156:0:(osd_handler.c:698:osd_ro()) Skipped 20 previous similar messages [ 5708.273320] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5713.864436] Lustre: lustre-MDT0001: Client a652ea96-3308-4861-8bb0-bf3dff24c8bc (at 192.168.202.14@tcp) reconnecting [ 5728.232352] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 5731.846462] Lustre: lustre-OST0001: deleting orphan objects from 0x0:14083 to 0x0:14401 [ 5731.846553] Lustre: lustre-OST0000: deleting orphan objects from 0x0:14197 to 0x0:14753 [ 5733.666879] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 5734.205110] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5737.690721] Lustre: DEBUG MARKER: == replay-single test 81f: DNE: unlink remote dir, drop MDT1 req reply, fail MDT1 ========================================================== 23:06:11 (1767845171) [ 5739.329927] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 5742.048829] LustreError: 137-5: lustre-MDT0001_UUID: 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. [ 5742.053161] LustreError: Skipped 334 previous similar messages [ 5752.909062] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 5752.911342] Lustre: Skipped 21 previous similar messages [ 5754.199478] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 5757.921537] Lustre: lustre-MDT0001-lwp-OST0001: Connection restored to (at 0@lo) [ 5757.925778] Lustre: Skipped 84 previous similar messages [ 5757.959665] Lustre: lustre-OST0000: deleting orphan objects from 0x280000400:4108 to 0x280000400:4225 [ 5757.960137] Lustre: lustre-OST0001: deleting orphan objects from 0x2c0000400:3788 to 0x2c0000400:3905 [ 5759.859748] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 5760.436811] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5763.716591] Lustre: DEBUG MARKER: == replay-single test 81g: DNE: unlink remote dir, drop req reply, fail M0, then M1 ========================================================== 23:06:37 (1767845197) [ 5765.323492] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5766.567285] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 5783.182365] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 5787.150556] Lustre: lustre-OST0001: deleting orphan objects from 0x0:14083 to 0x0:14433 [ 5787.150585] Lustre: lustre-OST0000: deleting orphan objects from 0x0:14197 to 0x0:14785 [ 5788.949988] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 5789.492196] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5805.603249] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 5809.686729] Lustre: lustre-OST0000: deleting orphan objects from 0x280000400:4108 to 0x280000400:4257 [ 5811.481693] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 5811.996112] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5815.351210] Lustre: DEBUG MARKER: == replay-single test 81h: DNE: unlink remote dir, drop request reply, fail 2 MDTs ========================================================== 23:07:28 (1767845248) [ 5815.767924] LustreError: 210201:0:(ldlm_lib.c:3224:target_send_reply_msg()) @@@ dropping reply req@00000000e3e495ee x1853714114209536/t77309411330(0) o36->a652ea96-3308-4861-8bb0-bf3dff24c8bc@192.168.202.14@tcp:675/0 lens 496/456 e 0 to 0 dl 1767845255 ref 1 fl Interpret:/0/0 rc 0/0 job:'rmdir.0' [ 5815.774276] LustreError: 210201:0:(ldlm_lib.c:3224:target_send_reply_msg()) Skipped 6 previous similar messages [ 5816.910749] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5818.211143] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 5820.216624] LustreError: 6111:0:(ldlm_lockd.c:2526:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1767845253 with bad export cookie 5835304456621036218 [ 5820.222593] LustreError: 6111:0:(ldlm_lockd.c:2526:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 5838.689695] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 5851.592283] Lustre: lustre-MDT0001: Not available for connect from 192.168.202.14@tcp (not set up) [ 5851.595720] Lustre: Skipped 8 previous similar messages [ 5852.989415] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 5853.772665] Lustre: lustre-OST0001: deleting orphan objects from 0x2c0000400:3788 to 0x2c0000400:3937 [ 5853.772667] Lustre: lustre-OST0000: deleting orphan objects from 0x280000400:4108 to 0x280000400:4289 [ 5853.814273] Lustre: lustre-OST0001: deleting orphan objects from 0x0:14083 to 0x0:14465 [ 5853.814289] Lustre: lustre-OST0000: deleting orphan objects from 0x0:14197 to 0x0:14817 [ 5856.909980] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 5857.413399] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5857.887984] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5861.237741] Lustre: DEBUG MARKER: == replay-single test 84a: stale open during export disconnect ========================================================== 23:08:14 (1767845294) [ 5861.842724] Lustre: 221400:0:(genops.c:1710:obd_export_evict_by_uuid()) lustre-MDT0000: evicting a652ea96-3308-4861-8bb0-bf3dff24c8bc at adminstrative request [ 5866.467934] Lustre: DEBUG MARKER: == replay-single test 85a: check the cancellation of unused locks during recovery(IBITS) ========================================================== 23:08:19 (1767845299) [ 5887.846938] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 5891.619053] Lustre: lustre-OST0001: deleting orphan objects from 0x0:14516 to 0x0:14561 [ 5891.619053] Lustre: lustre-OST0000: deleting orphan objects from 0x0:14869 to 0x0:14913 [ 5893.434078] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 5893.946715] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5897.271849] Lustre: DEBUG MARKER: == replay-single test 85b: check the cancellation of unused locks during recovery(EXTENT) ========================================================== 23:08:50 (1767845330) [ 5914.763832] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 5915.200228] Lustre: lustre-OST0000: deleting orphan objects from 0x0:15014 to 0x0:15041 [ 5915.201672] Lustre: lustre-OST0000: deleting orphan objects from 0x280000400:4108 to 0x280000400:4321 [ 5918.547086] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 5919.185597] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 5922.686181] Lustre: DEBUG MARKER: == replay-single test 86: umount server after clear nid_stats should not hit LBUG ========================================================== 23:09:16 (1767845356) [ 5927.704832] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 5928.431331] Lustre: lustre-MDT0000: Denying connection for new client fe4f4fac-795d-495a-9632-9657c17b51bb (at 192.168.202.14@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:59 [ 5931.537750] Lustre: lustre-OST0000: deleting orphan objects from 0x0:15014 to 0x0:15073 [ 5931.537819] Lustre: lustre-OST0001: deleting orphan objects from 0x0:14516 to 0x0:14593 [ 5935.723158] Lustre: DEBUG MARKER: == replay-single test 87a: write replay ================== 23:09:29 (1767845369) [ 5937.259410] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 5952.315813] Lustre: lustre-OST0000: deleting orphan objects from 0x0:15075 to 0x0:15105 [ 5952.318571] Lustre: lustre-OST0000: deleting orphan objects from 0x280000400:4108 to 0x280000400:4353 [ 5952.404708] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 5956.189988] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 5956.718673] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 5960.184287] Lustre: DEBUG MARKER: == replay-single test 87b: write replay with changed data (checksum resend) ========================================================== 23:09:53 (1767845393) [ 5961.652327] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 5977.247240] LustreError: 168-f: lustre-OST0000: BAD WRITE CHECKSUM: from 12345-192.168.202.14@tcp inode [0x200030971:0x5:0x0] object 0x0:15106 extent [0-1048575]: client csum f88b1, server csum d3d2a36b [ 5977.315036] Lustre: lustre-OST0000: deleting orphan objects from 0x0:15107 to 0x0:15137 [ 5977.319153] Lustre: lustre-OST0000: deleting orphan objects from 0x280000400:4108 to 0x280000400:4385 [ 5977.424484] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 5981.166419] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 5981.718789] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 5985.014810] Lustre: DEBUG MARKER: == replay-single test 88: MDS should not assign same objid to different files ========================================================== 23:10:18 (1767845418) [ 5986.267217] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 5987.498566] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5990.980716] LustreError: 132256:0:(ldlm_lockd.c:2526:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1767845424 with bad export cookie 5835304456621061908 [ 5990.985506] LustreError: 132256:0:(ldlm_lockd.c:2526:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 6009.304139] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 6013.036545] Lustre: lustre-OST0001: deleting orphan objects from 0x0:14634 to 0x0:14657 [ 6023.314170] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 6023.692609] Lustre: lustre-OST0000: deleting orphan objects from 0x280000400:4108 to 0x280000400:4417 [ 6023.697114] Lustre: lustre-OST0000: deleting orphan objects from 0x0:15107 to 0x0:15169 [ 6028.824952] Lustre: DEBUG MARKER: == replay-single test 89: no disk space leak on late ost connection ========================================================== 23:11:02 (1767845462) [ 6056.277750] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 6060.036944] Lustre: lustre-OST0001: deleting orphan objects from 0x0:14634 to 0x0:14689 [ 6063.046377] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 6063.776227] Lustre: lustre-OST0000: Denying connection for new client 3209b1b3-7594-43a0-a728-1ed899e0c304 (at 192.168.202.14@tcp), waiting for 3 known clients (2 recovered, 0 in progress, and 0 evicted) to recover in 1:09 [ 6069.192319] Lustre: lustre-OST0000: Denying connection for new client 3209b1b3-7594-43a0-a728-1ed899e0c304 (at 192.168.202.14@tcp), waiting for 3 known clients (2 recovered, 0 in progress, and 0 evicted) to recover in 1:03 [ 6069.197722] Lustre: Skipped 1 previous similar message [ 6079.432097] Lustre: lustre-OST0000: Denying connection for new client 3209b1b3-7594-43a0-a728-1ed899e0c304 (at 192.168.202.14@tcp), waiting for 3 known clients (2 recovered, 0 in progress, and 0 evicted) to recover in 0:53 [ 6079.437011] Lustre: Skipped 1 previous similar message [ 6099.912354] Lustre: lustre-OST0000: Denying connection for new client 3209b1b3-7594-43a0-a728-1ed899e0c304 (at 192.168.202.14@tcp), waiting for 3 known clients (2 recovered, 0 in progress, and 0 evicted) to recover in 0:33 [ 6099.917353] Lustre: Skipped 3 previous similar messages [ 6133.000081] Lustre: lustre-OST0000: recovery is timed out, evict stale exports [ 6133.002439] Lustre: lustre-OST0000: disconnecting 1 stale clients [ 6133.017219] Lustre: lustre-OST0000: deleting orphan objects from 0x0:15180 to 0x0:15201 [ 6133.018818] Lustre: lustre-OST0000: deleting orphan objects from 0x280000400:4108 to 0x280000400:4449 [ 6137.415303] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 70 sec [ 6147.431128] Lustre: DEBUG MARKER: free_before: 7518208 free_after: 7518208 [ 6149.364631] Lustre: DEBUG MARKER: == replay-single test 90: lfs find identifies the missing striped file segments ========================================================== 23:13:02 (1767845582) [ 6150.866351] Lustre: Failing over lustre-OST0000 [ 6150.868758] Lustre: Skipped 20 previous similar messages [ 6153.695718] LustreError: 11-0: lustre-OST0000-osc-MDT0001: operation ost_statfs to node 0@lo failed: rc = -107 [ 6153.695747] 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 [ 6153.700851] LustreError: Skipped 19 previous similar messages [ 6153.706563] Lustre: Skipped 59 previous similar messages [ 6164.957938] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 6165.617736] Lustre: lustre-OST0000: deleting orphan objects from 0x0:15204 to 0x0:15233 [ 6165.620292] Lustre: lustre-OST0000: deleting orphan objects from 0x280000400:4108 to 0x280000400:4481 [ 6168.822557] Lustre: DEBUG MARKER: == replay-single test 93a: replay + reconnect ============ 23:13:22 (1767845602) [ 6170.207474] Lustre: server umount lustre-OST0000 complete [ 6170.208742] Lustre: Skipped 21 previous similar messages [ 6184.886450] LustreError: 236216:0:(fail.c:138:__cfs_fail_timeout_set()) cfs_fail_timeout id 715 sleeping for 40000ms [ 6184.889847] LustreError: 236216:0:(fail.c:138:__cfs_fail_timeout_set()) Skipped 1 previous similar message [ 6184.977723] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 6185.759112] Lustre: *** cfs_fail_loc=715, val=0*** [ 6192.008125] Lustre: lustre-OST0000: Client 3209b1b3-7594-43a0-a728-1ed899e0c304 (at 192.168.202.14@tcp) reconnected, waiting for 3 clients in recovery for 0:57 [ 6192.095174] Lustre: 3138:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1767845618/real 1767845618] req@00000000746eb81f x1853714093476864/t0(0) o400->lustre-OST0000-osc-MDT0001@0@lo:28/4 lens 224/224 e 0 to 1 dl 1767845625 ref 1 fl Rpc:XQr/c0/ffffffff rc 0/-1 job:'ldlm_lock_repla.0' [ 6192.106799] Lustre: 3138:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 16 previous similar messages [ 6193.055151] Lustre: *** cfs_fail_loc=715, val=0*** [ 6193.056465] Lustre: Skipped 2 previous similar messages [ 6198.225142] Lustre: lustre-OST0000: Client 3209b1b3-7594-43a0-a728-1ed899e0c304 (at 192.168.202.14@tcp) reconnected, waiting for 3 clients in recovery for 0:51 [ 6198.228104] Lustre: Skipped 2 previous similar messages [ 6199.263114] Lustre: *** cfs_fail_loc=715, val=0*** [ 6199.263541] Lustre: lustre-OST0000: Client lustre-MDT0001-mdtlov_UUID (at 0@lo) reconnected, waiting for 3 clients in recovery for 0:50 [ 6199.264558] Lustre: Skipped 2 previous similar messages [ 6199.268370] Lustre: Skipped 1 previous similar message [ 6205.384140] Lustre: lustre-OST0000: Client 3209b1b3-7594-43a0-a728-1ed899e0c304 (at 192.168.202.14@tcp) reconnected, waiting for 3 clients in recovery for 0:44 [ 6206.431105] Lustre: *** cfs_fail_loc=715, val=0*** [ 6206.432430] Lustre: Skipped 2 previous similar messages [ 6212.552197] Lustre: lustre-OST0000: Client 3209b1b3-7594-43a0-a728-1ed899e0c304 (at 192.168.202.14@tcp) reconnected, waiting for 3 clients in recovery for 0:37 [ 6212.555632] Lustre: Skipped 2 previous similar messages [ 6213.599209] Lustre: *** cfs_fail_loc=715, val=0*** [ 6213.600675] Lustre: Skipped 2 previous similar messages [ 6224.935112] LustreError: 236216:0:(fail.c:149:__cfs_fail_timeout_set()) cfs_fail_timeout id 715 awake [ 6224.950308] Lustre: lustre-OST0000: deleting orphan objects from 0x280000400:4108 to 0x280000400:4513 [ 6224.951429] Lustre: lustre-OST0000: deleting orphan objects from 0x0:15235 to 0x0:15265 [ 6227.062690] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 6227.618449] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 6231.104766] Lustre: DEBUG MARKER: == replay-single test 93b: replay + reconnect on mds ===== 23:14:24 (1767845664) [ 6241.759178] LustreError: 166-1: MGC192.168.202.114@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 6241.763240] LustreError: Skipped 9 previous similar messages [ 6249.375330] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 6249.439102] Lustre: *** cfs_fail_loc=715, val=0*** [ 6249.440704] Lustre: Skipped 5 previous similar messages [ 6253.034915] LustreError: 237770:0:(fail.c:138:__cfs_fail_timeout_set()) cfs_fail_timeout id 715 sleeping for 80000ms [ 6255.560157] Lustre: lustre-MDT0000: Client 3209b1b3-7594-43a0-a728-1ed899e0c304 (at 192.168.202.14@tcp) reconnected, waiting for 2 clients in recovery for 0:58 [ 6255.564194] Lustre: Skipped 5 previous similar messages [ 6260.191461] Lustre: lustre-MDT0000: Received new MDS connection from 0@lo, keep former export from same NID [ 6267.359474] Lustre: lustre-MDT0000: Received new MDS connection from 0@lo, keep former export from same NID [ 6268.383103] Lustre: *** cfs_fail_loc=715, val=0*** [ 6268.385779] Lustre: Skipped 4 previous similar messages [ 6274.527468] Lustre: lustre-MDT0000: Received new MDS connection from 0@lo, keep former export from same NID [ 6277.064142] Lustre: lustre-MDT0000: Client 3209b1b3-7594-43a0-a728-1ed899e0c304 (at 192.168.202.14@tcp) reconnected, waiting for 2 clients in recovery for 0:36 [ 6277.067307] Lustre: Skipped 2 previous similar messages [ 6281.695639] Lustre: lustre-MDT0000: Received new MDS connection from 0@lo, keep former export from same NID [ 6287.839759] Lustre: lustre-MDT0000: Received new MDS connection from 0@lo, keep former export from same NID [ 6302.175508] Lustre: lustre-MDT0000: Received new MDS connection from 0@lo, keep former export from same NID [ 6302.177666] Lustre: Skipped 1 previous similar message [ 6303.199138] Lustre: *** cfs_fail_loc=715, val=0*** [ 6303.201097] Lustre: Skipped 9 previous similar messages [ 6312.904277] Lustre: lustre-MDT0000: Client 3209b1b3-7594-43a0-a728-1ed899e0c304 (at 192.168.202.14@tcp) reconnected, waiting for 2 clients in recovery for 0:01 [ 6312.907816] Lustre: Skipped 4 previous similar messages [ 6319.048057] Lustre: lustre-MDT0000: Recovery already passed deadline 0:05. If you do not want to wait more, you may force taget eviction via 'lctl --device lustre-MDT0000 abort_recovery. [ 6323.679592] Lustre: lustre-MDT0000: Received new MDS connection from 0@lo, keep former export from same NID [ 6323.683116] Lustre: Skipped 2 previous similar messages [ 6326.216142] Lustre: lustre-MDT0000: Recovery already passed deadline 0:12. If you do not want to wait more, you may force taget eviction via 'lctl --device lustre-MDT0000 abort_recovery. [ 6333.119073] LustreError: 237770:0:(fail.c:149:__cfs_fail_timeout_set()) cfs_fail_timeout id 715 awake [ 6333.132480] Lustre: 237770:0:(ldlm_lib.c:2829:target_recovery_thread()) too long recovery - read logs [ 6333.135129] LustreError: dumping log to /tmp/lustre-log.1767845766.237770 [ 6333.158294] Lustre: lustre-MDT0000: Recovery over after 1:25, of 2 clients 2 recovered and 0 were evicted. [ 6333.160377] Lustre: Skipped 18 previous similar messages [ 6333.177045] Lustre: lustre-OST0001: deleting orphan objects from 0x0:14702 to 0x0:14721 [ 6333.177073] Lustre: lustre-OST0000: deleting orphan objects from 0x0:15276 to 0x0:15297 [ 6335.223974] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 6335.800280] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6339.410654] Lustre: DEBUG MARKER: == replay-single test complete, duration 6185 sec ======== 23:16:12 (1767845772) [ 6343.648512] LustreError: 137-5: lustre-MDT0000_UUID: 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. [ 6343.657616] LustreError: Skipped 228 previous similar messages [ 6357.472433] Lustre: Evicted from MGS (at 192.168.202.114@tcp) after server handle changed from 0x50fb2a7c8d273175 to 0x50fb2a7c8d2774b2 [ 6357.475223] Lustre: Skipped 8 previous similar messages [ 6357.663661] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 6357.666387] Lustre: Skipped 19 previous similar messages [ 6357.736833] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 6357.739524] Lustre: Skipped 16 previous similar messages [ 6358.984561] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 6358.987589] Lustre: Skipped 18 previous similar messages [ 6359.250236] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 6362.598173] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to (at 0@lo) [ 6362.600855] Lustre: Skipped 55 previous similar messages [ 6362.648849] Lustre: lustre-OST0001: deleting orphan objects from 0x0:14702 to 0x0:14753 [ 6362.648849] Lustre: lustre-OST0000: deleting orphan objects from 0x0:15276 to 0x0:15329 [ 6364.551768] Lustre: DEBUG MARKER: oleg214-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 6365.088319] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6367.712769] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 6367.716534] Lustre: Skipped 3 previous similar messages [ 6370.643681] LustreError: 132254:0:(ldlm_lockd.c:2526:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1767845803 with bad export cookie 5835304456621094066 [ 6370.647348] LustreError: 132254:0:(ldlm_lockd.c:2526:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 6391.183806] Lustre: DEBUG MARKER: oleg214-server.virtnet: executing unload_modules_local [ 6392.242531] Key type lgssc unregistered [ 6392.348325] LNet: 241209:0:(lib-ptl.c:992:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 6392.351580] LNet: Removed LNI 192.168.202.114@tcp [ 6392.619191] Key type .llcrypt unregistered [ 6392.620165] Key type ._llcrypt unregistered