[ 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 494519212 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: 2895240K/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.001012] APIC: Switch to symmetric I/O mode setup [ 0.002376] x2apic enabled [ 0.003009] Switched APIC routing to physical x2apic. [ 0.004020] kvm-guest: setup PV IPIs [ 0.007000] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.007000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.007025] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.008014] pid_max: default: 32768 minimum: 301 [ 0.009182] LSM: Security Framework initializing [ 0.010078] Yama: becoming mindful. [ 0.011044] SELinux: Initializing. [ 0.013039] *** VALIDATE selinux *** [ 0.021706] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.026642] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.027181] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.028142] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.029136] *** VALIDATE tmpfs *** [ 0.030496] *** VALIDATE proc *** [ 0.032181] *** VALIDATE cgroup *** [ 0.033013] *** VALIDATE cgroup2 *** [ 0.034280] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.035175] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.036008] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.037042] Spectre V2 : User space: Vulnerable [ 0.038011] Speculative Store Bypass: Vulnerable [ 0.042053] debug: unmapping init [mem 0xffffffff93e59000-0xffffffff93e60fff] [ 0.045000] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.045798] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.046029] ... version: 2 [ 0.047016] ... bit width: 48 [ 0.048017] ... generic registers: 4 [ 0.049019] ... value mask: 0000ffffffffffff [ 0.050019] ... max period: 00007fffffffffff [ 0.051031] ... fixed-purpose events: 3 [ 0.052018] ... event mask: 000000070000000f [ 0.053329] rcu: Hierarchical SRCU implementation. [ 0.055532] smp: Bringing up secondary CPUs ... [ 0.056698] x86: Booting SMP configuration: [ 0.057028] .... node #0, CPUs: #1 #2 #3 [ 0.060794] smp: Brought up 1 node, 4 CPUs [ 0.062016] smpboot: Max logical packages: 1 [ 0.063020] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.148925] node 0 deferred pages initialised in 83ms [ 0.153112] devtmpfs: initialized [ 0.154346] x86/mm: Memory block size: 128MB [ 0.157737] gcov: version magic: 0x41383552 [ 0.160193] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.163084] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.166368] pinctrl core: initialized pinctrl subsystem [ 0.169172] [ 0.169712] ************************************************************* [ 0.172012] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.175025] ** ** [ 0.177019] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.180020] ** ** [ 0.182019] ** This means that this kernel is built to expose internal ** [ 0.185024] ** IOMMU data structures, which may compromise security on ** [ 0.188023] ** your system. ** [ 0.190019] ** ** [ 0.192023] ** If you see this message and you are not debugging the ** [ 0.194020] ** kernel, report this immediately to your vendor! ** [ 0.197021] ** ** [ 0.199017] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.201020] ************************************************************* [ 0.204804] NET: Registered protocol family 16 [ 0.207490] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.210085] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.212092] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.216146] cpuidle: using governor menu [ 0.217667] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.221074] PCI: Using configuration type 1 for base access [ 0.223108] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.231082] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.234094] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.239085] cryptd: max_cpu_qlen set to 1000 [ 0.241098] ACPI: Added _OSI(Module Device) [ 0.242031] ACPI: Added _OSI(Processor Device) [ 0.244045] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.246027] ACPI: Added _OSI(Processor Aggregator Device) [ 0.250947] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.256573] ACPI: Interpreter enabled [ 0.259090] ACPI: PM: (supports S0 S3 S4 S5) [ 0.260013] ACPI: Using IOAPIC for interrupt routing [ 0.262123] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.267417] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.277534] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.280046] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.283029] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.286119] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.291964] acpiphp: Slot [2] registered [ 0.293226] acpiphp: Slot [5] registered [ 0.295249] acpiphp: Slot [6] registered [ 0.296191] acpiphp: Slot [7] registered [ 0.298246] acpiphp: Slot [8] registered [ 0.300214] acpiphp: Slot [9] registered [ 0.302210] acpiphp: Slot [10] registered [ 0.304202] acpiphp: Slot [3] registered [ 0.305188] acpiphp: Slot [4] registered [ 0.307145] acpiphp: Slot [11] registered [ 0.309149] acpiphp: Slot [12] registered [ 0.311190] acpiphp: Slot [13] registered [ 0.315197] acpiphp: Slot [14] registered [ 0.316126] acpiphp: Slot [15] registered [ 0.318134] acpiphp: Slot [16] registered [ 0.319145] acpiphp: Slot [17] registered [ 0.321258] acpiphp: Slot [18] registered [ 0.323142] acpiphp: Slot [19] registered [ 0.325156] acpiphp: Slot [20] registered [ 0.327140] acpiphp: Slot [21] registered [ 0.328141] acpiphp: Slot [22] registered [ 0.330132] acpiphp: Slot [23] registered [ 0.332194] acpiphp: Slot [24] registered [ 0.333105] acpiphp: Slot [25] registered [ 0.335126] acpiphp: Slot [26] registered [ 0.336176] acpiphp: Slot [27] registered [ 0.338117] acpiphp: Slot [28] registered [ 0.339129] acpiphp: Slot [29] registered [ 0.341193] acpiphp: Slot [30] registered [ 0.343140] acpiphp: Slot [31] registered [ 0.345058] PCI host bridge to bus 0000:00 [ 0.346020] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.348026] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.351021] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.354046] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.357044] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.360052] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.362372] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.366502] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.370554] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.381046] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.386049] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.389064] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.392030] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.393023] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.396598] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.399887] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.402046] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.404871] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.410015] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.426019] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.432014] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.437389] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.447028] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.460023] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.477021] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.486992] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.493016] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.499020] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.512017] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.524751] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.533017] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.541020] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.570021] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.586232] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.590833] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.595995] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.608014] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.617143] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.622020] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.628018] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.641019] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 0.650942] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.659026] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.668018] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.685019] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 0.695414] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.698376] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.700579] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.703462] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.706342] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.711144] iommu: Default domain type: Passthrough [ 0.713755] SCSI subsystem initialized [ 0.715130] ACPI: bus type USB registered [ 0.717123] usbcore: registered new interface driver usbfs [ 0.719085] usbcore: registered new interface driver hub [ 0.722103] usbcore: registered new device driver usb [ 0.723200] pps_core: LinuxPPS API ver. 1 registered [ 0.725011] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.728170] PTP clock support registered [ 0.731107] EDAC MC: Ver: 3.0.0 [ 0.733184] PCI: Using ACPI for IRQ routing [ 0.735028] NetLabel: Initializing [ 0.736013] NetLabel: domain hash size = 128 [ 0.738014] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.740090] NetLabel: unlabeled traffic allowed by default [ 0.743171] vgaarb: loaded [ 0.745231] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.747011] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.754050] clocksource: Switched to clocksource kvm-clock [ 0.861849] VFS: Disk quotas dquot_6.6.0 [ 0.865839] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.868696] *** VALIDATE ramfs *** [ 0.869845] *** VALIDATE hugetlbfs *** [ 0.871692] pnp: PnP ACPI init [ 0.873987] pnp: PnP ACPI: found 6 devices [ 0.898283] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.902225] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.904612] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.907019] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.909826] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.913037] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.915913] NET: Registered protocol family 2 [ 0.918226] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.922800] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.927253] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.934179] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.938531] TCP: Hash tables configured (established 65536 bind 65536) [ 0.942366] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.946281] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.948442] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.951675] NET: Registered protocol family 1 [ 0.954725] RPC: Registered named UNIX socket transport module. [ 0.957238] RPC: Registered udp transport module. [ 0.959221] RPC: Registered tcp transport module. [ 0.961161] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.964150] NET: Registered protocol family 44 [ 0.966108] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.968670] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.971113] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.973839] PCI: CLS 0 bytes, default 64 [ 0.975846] Unpacking initramfs... [ 2.394492] debug: unmapping init [mem 0xffff8e203cc54000-0xffff8e203ffbffff] [ 2.398494] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.401108] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.404298] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 2.929736] Initialise system trusted keyrings [ 2.931660] Key type blacklist registered [ 2.933784] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.950268] zbud: loaded [ 2.954099] *** VALIDATE nfs *** [ 2.955519] *** VALIDATE nfs4 *** [ 2.957074] pstore: using deflate compression [ 2.960599] Platform Keyring initialized [ 3.071968] NET: Registered protocol family 38 [ 3.073754] Key type asymmetric registered [ 3.075565] Asymmetric key parser 'x509' registered [ 3.077716] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 3.081291] io scheduler mq-deadline registered [ 3.083168] io scheduler kyber registered [ 3.084983] io scheduler bfq registered [ 3.086995] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 3.090351] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 3.093626] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 3.100082] ACPI: Power Button [PWRF] [ 3.106200] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 3.114893] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 3.126899] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 3.136810] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 3.157075] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 3.185081] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.213409] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.218693] Non-volatile memory driver v1.3 [ 3.220705] Linux agpgart interface v0.103 [ 3.258271] virtio_blk virtio1: [vda] 68000 512-byte logical blocks (34.8 MB/33.2 MiB) [ 3.263556] vda: detected capacity change from 0 to 34816000 [ 3.281988] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.286040] vdb: detected capacity change from 0 to 1073741824 [ 3.303691] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.306186] vdc: detected capacity change from 0 to 2621440000 [ 3.326141] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.329418] vdd: detected capacity change from 0 to 2621440000 [ 3.346204] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.349234] vde: detected capacity change from 0 to 4294967296 [ 3.367303] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.370835] vdf: detected capacity change from 0 to 4294967296 [ 3.379783] libphy: Fixed MDIO Bus: probed [ 3.386135] usbcore: registered new interface driver usbserial_generic [ 3.392077] usbserial: USB Serial support registered for generic [ 3.394482] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.399318] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.401205] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.403599] mousedev: PS/2 mouse device common for all mice [ 3.406985] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.408964] rtc_cmos 00:05: RTC can wake from S4 [ 3.415414] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.416446] rtc_cmos 00:05: registered as rtc0 [ 3.420890] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.420952] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.427344] intel_pstate: CPU model not supported [ 3.430651] hid: raw HID events driver (C) Jiri Kosina [ 3.432686] usbcore: registered new interface driver usbhid [ 3.435114] usbhid: USB HID core driver [ 3.436947] drop_monitor: Initializing network drop monitor service [ 3.439972] Initializing XFRM netlink socket [ 3.441973] NET: Registered protocol family 10 [ 3.445343] Segment Routing with IPv6 [ 3.446735] NET: Registered protocol family 17 [ 3.448436] mpls_gso: MPLS GSO support [ 3.454803] RAS: Correctable Errors collector initialized. [ 3.457179] AVX version of gcm_enc/dec engaged. [ 3.458972] AES CTR mode by8 optimization enabled [ 3.549746] sched_clock: Marking stable (3549708083, 0)->(4485404782, -935696699) [ 3.554252] registered taskstats version 1 [ 3.556135] Loading compiled-in X.509 certificates [ 3.558545] zswap: loaded using pool lzo/zbud [ 3.584054] Key type big_key registered [ 3.599069] Key type encrypted registered [ 3.600986] ima: No TPM chip found, activating TPM-bypass! [ 3.603664] ima: Allocated hash algorithm: sha1 [ 3.605685] ima: No architecture policies found [ 3.607609] evm: Initialising EVM extended attributes: [ 3.609609] evm: security.selinux [ 3.611121] evm: security.ima [ 3.612339] evm: security.capability [ 3.614090] evm: HMAC attrs: 0x1 [ 3.616921] rtc_cmos 00:05: setting system clock to 2026-04-15 15:03:19 UTC (1776265399) [ 3.623423] debug: unmapping init [mem 0xffffffff94e03000-0xffffffff94ffffff] [ 3.626425] debug: unmapping init [mem 0xffffffff93b82000-0xffffffff93e58fff] [ 3.635086] Write protecting the kernel read-only data: 28672k [ 3.639898] debug: unmapping init [mem 0xffffffff92203000-0xffffffff923fffff] [ 3.643303] debug: unmapping init [mem 0xffffffff92b14000-0xffffffff92bfffff] [ 3.679952] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 3.695429] systemd[1]: Detected virtualization kvm. [ 3.697248] systemd[1]: Detected architecture x86-64. [ 3.699131] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.727110] systemd[1]: No hostname configured. [ 3.729023] systemd[1]: Set hostname to . [ 3.731285] random: systemd: uninitialized urandom read (16 bytes read) [ 3.733846] systemd[1]: Initializing machine ID from random generator. [ 3.783372] random: ln: uninitialized urandom read (6 bytes read) [ 3.880473] random: systemd: uninitialized urandom read (16 bytes read) [ 3.885492] systemd[1]: Listening on Journal Socket (/dev/log). [ OK ] Listening on Journal Socket (/dev/log). [ 3.891745] systemd[1]: Listening on Journal Socket. [ OK ] Listening on Journal Socket. [ 3.901858] systemd[1]: Started Memstrack Anylazing Service. [ OK ] Started Memstrack Anylazing Service. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Reached target Timers. [ OK ] Reached target Swap. Starting Setup Virtual Console... [ OK ] Listening on udev Control Socket. [ OK ] Reached target Slices. Starting Journal Service... [ OK ] Reached target Initrd Root Device. [ OK ] Listening on udev Kernel Socket. [ OK ] Reached target Sockets. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Paths. [ OK ] Reached target Local File Systems. Starting Create Volatile Files and Directories... [ OK ] Reached target Local Encrypted Volumes. Starting Apply Kernel Variables... [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Setup Virtual Console. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Apply Kernel Variables. Starting dracut cmdline hook... Starting Create Static Device Nodes in /dev... [ OK ] Started Journal Service. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 4.635224] device-mapper: uevent: version 1.0.3 [ 4.637963] device-mapper: ioctl: 4.46.0-ioctl (2022-02-22) initialised: dm-devel@redhat.com [ OK ] Started dracut pre-udev hook. Starting udev Kernel Device Manager... [ OK ] Started udev Kernel Device Manager. Starting dracut pre-trigger hook... [ OK ] Started dracut pre-trigger hook. Starting udev Coldplug all Devices... Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. Starting dracut initqueue hook... [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ 5.358664] random: fast init done [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ 5.385969] virtio_net virtio0 ens2: renamed from eth0 [ 5.456351] scsi host0: ata_piix [ 5.511091] scsi host1: ata_piix [ 5.512438] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 5.514180] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 9.176810] dracut-initqueue[578]: RTNETLINK answers: File exists [ 10.119212] random: crng init done [ 10.121463] random: 7 urandom warning(s) missed due to ratelimiting Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Mounting /sysroot... [ 10.651745] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped target Timers. [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Sockets. [ OK ] Stopped target Paths. [ OK ] Stopped target Slices. [ 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 ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Closed udev Control Socket. [ OK ] Closed udev Kernel Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 11.823047] printk: systemd: 25 output lines suppressed due to ratelimiting [ 12.085924] SELinux: Disabled at runtime. [ 12.147407] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 12.155811] systemd[1]: Detected virtualization kvm. [ 12.158146] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 12.691809] systemd[1]: initrd-switch-root.service: Succeeded. [ 12.695534] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 12.701302] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 12.706277] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 12.709920] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 12.718096] systemd[1]: Starting Journal Service... Starting Journal Service... [ 12.723362] systemd[1]: Created slice system-getty.slice. [ OK ] Created slice system-getty.slice. [ OK ] Listening on udev Kernel Socket. [ OK ] Created slice User and Session Slice. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Listening on Process Core Dump Socket. [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Reached target RPC Port Mapper. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Stopped target Switch Root. Mounting Kernel Debug File System... [ OK ] Reached target rpc_pipefs.target. [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Listening on udev Control Socket. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Slices. [ OK ] Stopped target Initrd File Systems. [ OK ] Reached target Paths. Mounting Huge Pages File System... Activating swap /dev/disk/by-label/SWAP... [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Listening on initctl Compatibility Named Pipe. Starting Apply Kernel Variables... Starting udev Coldplug all Devices... Starting Remount Root and Kernel File Systems... [ OK [[ 12.853724] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS 0m] Created slice system-serial\x2dgetty.slice. [ OK ] Stopped target Initrd Root File System. Mounting POSIX Message Queue File System... [ OK ] Started Journal Service. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Mounted Kernel Debug File System. [ OK ] Mounted Huge Pages File System. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Started Apply Kernel Variables. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Mounted POSIX Message Queue File System. 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. Starting udev Kernel Device Manager... [ OK ] Reached target Local File Systems (Pre). Mounting /mnt... Mounting /home/green/git/lustre-release... [ OK ] Mounted /mnt. [ 13.130146] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Coldplug all Devices. [ OK ] Started udev Kernel Device Manager. [ 13.379956] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 13.422295] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 13.558212] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 13.572596] EDAC sbridge: Ver: 1.1.2 [ 15.146346] Key type dns_resolver registered [ 15.461359] NFS: Registering the id_resolver key type [ 15.464149] Key type id_resolver registered [ 15.465718] Key type id_legacy registered [ OK ] Started Configure read-only root support. Starting Load/Save Random Seed... [ OK ] Reached target Local File Systems. Starting Rebuild Dynamic Linker Cache... Starting Mark the need to relabel after reboot... Starting Create Volatile Files and Directories... [ OK ] Started Load/Save Random Seed. [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Create Volatile Files and Directories. Starting RPC Bind... Starting Update UTMP about System Boot/Shutdown... [ OK ] Started 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 ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting Login Service... [ OK ] Started Daily Cleanup of Temporary Directories. Starting Restore /run/initramfs on shutdown... [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Started dnf makecache --timer. [ OK ] Reached target Timers. [ OK ] Started irqbalance daemon. [ OK ] Started D-Bus System Message Bus. Starting Network Manager... [ OK ] Reached target sshd-keygen.target. [ 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... [ OK ] Started OpenSSH server daemon. [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... Starting Hostname Service... [ OK ] Started Permit User Sessions. [ OK ] Started Serial Getty on ttyS1. [ OK ] Started Command Scheduler. [ OK ] Started Getty on tty1. [ OK ] Started Serial Getty on ttyS0. [ OK ] Reached target Login Prompts. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting Crash recovery kernel arming... Starting System Logging Service... Starting Notify NFS peers of a restart... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Starting Authorization Manager... [ OK ] Started Authorization Manager. [ OK ] Started Dynamic System Tuning Daemon. [ OK ] Reached target Multi-User System. [ OK ] Reached target Graphical Interface. Starting Update UTMP about System Runlevel Changes... [ OK ] Started Update UTMP about System Runlevel Changes. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg651-server login: [ 31.530877] spl: loading out-of-tree module taints kernel. [ 34.364554] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 39.810842] alg: No test for adler32 (adler32-zlib) [ 40.563501] Key type ._llcrypt registered [ 40.565604] Key type .llcrypt registered [ 40.618441] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_hostid [ 48.583250] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing load_modules_local [ 49.380710] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 49.701152] Lustre: Lustre: Build Version: 2.15.8_1_ga99367a [ 50.027452] LNet: Added LNI 192.168.206.151@tcp [8/256/0/180] [ 50.030296] LNet: Accept secure, port 988 [ 51.664182] Key type lgssc registered [ 52.363677] Lustre: Echo OBD driver; http://www.lustre.org/ [ 56.893000] vdc: vdc1 vdc9 [ 66.012280] vde: vde1 vde9 [ 77.816778] vdf: vdf1 vdf9 [ 97.631826] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing load_modules_local [ 101.365775] hrtimer: interrupt took 9416817 ns [ 107.779634] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall in log lustre-MDT0000 [ 108.043924] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space: rc = -61 [ 108.123338] Lustre: lustre-MDT0000: new disk, initializing [ 108.450063] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 108.527314] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 113.523855] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 122.503707] Lustre: lustre-OST0000: new disk, initializing [ 122.509221] Lustre: srv-lustre-OST0000: No data found on store. Initialize space: rc = -61 [ 122.516347] Lustre: Skipped 1 previous similar message [ 122.619954] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 126.913307] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 135.484358] Lustre: lustre-OST0001: new disk, initializing [ 135.487976] Lustre: srv-lustre-OST0001: No data found on store. Initialize space: rc = -61 [ 135.573899] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 139.715585] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 149.177631] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 154.922370] Lustre: Modifying parameter general.lod.*.mdt_hash in log params [ 165.637651] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing check_logdir /tmp/testlogs/ [ 172.870297] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing yml_node [ 177.434418] Lustre: DEBUG MARKER: Client: 2.15.8.1 [ 180.063884] Lustre: DEBUG MARKER: MDS: 2.15.8.1 [ 182.773229] Lustre: DEBUG MARKER: OSS: 2.15.8.1 [ 184.551158] Lustre: DEBUG MARKER: -----============= acceptance-small: replay-single ============----- Wed Apr 15 11:06:17 EDT 2026 [ 192.983963] Lustre: DEBUG MARKER: excepting tests: 59 [ 199.599509] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing check_config_client /mnt/lustre [ 215.603704] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 219.601542] Lustre: Modifying parameter general.lod.*.mdt_hash in log params [ 224.172598] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 226.196817] Lustre: DEBUG MARKER: == replay-single test 0a: empty replay =================== 11:06:59 (1776265619) [ 229.878495] LustreError: 10669:0:(osd_handler.c:698:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 230.742397] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 232.750484] Lustre: Failing over lustre-MDT0000 [ 233.074587] Lustre: server umount lustre-MDT0000 complete [ 240.480138] Lustre: 2991:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776265629/real 1776265629] req@000000005e04d689 x1862549315281664/t0(0) o400->MGC192.168.206.151@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1776265636 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:2.0' [ 240.503891] LustreError: 166-1: MGC192.168.206.151@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 241.568459] Lustre: 2992:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776265629/real 1776265629] req@0000000076bd58fb x1862549315281792/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1776265636 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:2.0' [ 241.604023] 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 [ 245.665069] Lustre: 2992:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776265634/real 1776265634] req@0000000078a17bda x1862549315281984/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1776265641 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:1.0' [ 245.701077] Lustre: 2992:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 247.778744] Lustre: 2990:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776265636/real 1776265636] req@000000007fa09382 x1862549315282176/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1776265643 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:0.0' [ 247.804216] Lustre: 2990:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 257.889107] Lustre: Evicted from MGS (at 192.168.206.151@tcp) after server handle changed from 0x8c5ddb9355492fbc to 0x8c5ddb9355493469 [ 257.898376] Lustre: MGC192.168.206.151@tcp: Connection restored to (at 0@lo) [ 258.226687] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 259.176385] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to (at 0@lo) [ 260.584940] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 260.662224] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 261.865387] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 271.076788] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 272.867085] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 281.435725] Lustre: DEBUG MARKER: == replay-single test 0b: ensure object created after recover exists. (3284) ========================================================== 11:07:54 (1776265674) [ 283.427299] Lustre: Failing over lustre-OST0000 [ 283.525981] Lustre: server umount lustre-OST0000 complete [ 283.631839] LustreError: 11-0: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 283.639182] 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 [ 283.652030] Lustre: Skipped 1 previous similar message [ 283.663838] LustreError: 137-5: lustre-OST0000_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. [ 285.153699] LustreError: 137-5: lustre-OST0000_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. [ 286.228136] LustreError: 137-5: lustre-OST0000_UUID: not available for connect from 192.168.206.51@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 290.277802] LustreError: 137-5: lustre-OST0000_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. [ 295.393657] LustreError: 137-5: lustre-OST0000_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. [ 295.409189] LustreError: Skipped 1 previous similar message [ 301.492953] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 301.566829] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 303.609341] Lustre: lustre-OST0000: Recovery over after 0:02, of 2 clients 2 recovered and 0 were evicted. [ 303.610235] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 192.168.206.151@tcp (at 0@lo) [ 303.635199] Lustre: Skipped 1 previous similar message [ 303.643375] Lustre: lustre-OST0000: deleting orphan objects from 0x0:34 to 0x0:65 [ 305.929347] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 314.470437] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 316.086573] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 324.257700] Lustre: DEBUG MARKER: == replay-single test 0c: check replay-barrier =========== 11:08:37 (1776265717) [ 326.755424] LustreError: 13736:0:(osd_handler.c:698:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 327.608548] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 329.810514] Lustre: Failing over lustre-MDT0000 [ 330.257361] Lustre: server umount lustre-MDT0000 complete [ 339.360887] Lustre: 2990:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776265728/real 1776265728] req@0000000034cb116d x1862549315297280/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1776265735 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:2.0' [ 339.397372] Lustre: 2990:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 339.408471] Lustre: lustre-MDT0000-lwp-OST0000: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 339.431202] LustreError: 166-1: MGC192.168.206.151@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 356.833996] Lustre: Evicted from MGS (at 192.168.206.151@tcp) after server handle changed from 0x8c5ddb9355493469 to 0x8c5ddb9355493dc3 [ 356.857524] Lustre: MGC192.168.206.151@tcp: Connection restored to 192.168.206.151@tcp (at 0@lo) [ 357.291693] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 361.809978] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 364.169268] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 364.176826] Lustre: lustre-MDT0000: Denying connection for new client b72b3697-378c-4784-9575-662d78099c5c (at 192.168.206.51@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:59 [ 369.642096] Lustre: lustre-MDT0000: Denying connection for new client b72b3697-378c-4784-9575-662d78099c5c (at 192.168.206.51@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:54 [ 372.514294] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to (at 0@lo) [ 374.766124] Lustre: lustre-MDT0000: Denying connection for new client b72b3697-378c-4784-9575-662d78099c5c (at 192.168.206.51@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:49 [ 379.887389] Lustre: lustre-MDT0000: Denying connection for new client b72b3697-378c-4784-9575-662d78099c5c (at 192.168.206.51@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:44 [ 385.013161] Lustre: lustre-MDT0000: Denying connection for new client b72b3697-378c-4784-9575-662d78099c5c (at 192.168.206.51@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:38 [ 395.245282] Lustre: lustre-MDT0000: Denying connection for new client b72b3697-378c-4784-9575-662d78099c5c (at 192.168.206.51@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:28 [ 395.263899] Lustre: Skipped 1 previous similar message [ 415.728716] Lustre: lustre-MDT0000: Denying connection for new client b72b3697-378c-4784-9575-662d78099c5c (at 192.168.206.51@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:08 [ 415.741601] Lustre: Skipped 3 previous similar messages [ 424.000477] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 424.008864] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 424.071863] Lustre: lustre-MDT0000: Recovery over after 1:00, of 1 clients 0 recovered and 1 was evicted. [ 424.098898] Lustre: lustre-OST0000: deleting orphan objects from 0x0:76 to 0x0:97 [ 424.102192] Lustre: lustre-OST0001: deleting orphan objects from 0x0:44 to 0x0:65 [ 434.778742] Lustre: DEBUG MARKER: == replay-single test 0d: expired recovery with no clients ========================================================== 11:10:27 (1776265827) [ 437.338868] LustreError: 15173:0:(osd_handler.c:698:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 438.029707] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 439.876747] Lustre: Failing over lustre-MDT0000 [ 440.283963] Lustre: server umount lustre-MDT0000 complete [ 451.488376] Lustre: 2992:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776265840/real 1776265840] req@000000006183c1bf x1862549315310080/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1776265847 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:0.0' [ 451.527290] Lustre: 2992:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 4 previous similar messages [ 451.539519] 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 [ 451.547507] Lustre: Skipped 1 previous similar message [ 458.744454] LustreError: 166-1: MGC192.168.206.151@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 458.776300] Lustre: Evicted from MGS (at 192.168.206.151@tcp) after server handle changed from 0x8c5ddb9355493dc3 to 0x8c5ddb9355494158 [ 458.807271] Lustre: MGC192.168.206.151@tcp: Connection restored to (at 0@lo) [ 458.811673] Lustre: Skipped 1 previous similar message [ 459.197305] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 463.962191] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 466.240546] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 466.257371] Lustre: lustre-MDT0000: Denying connection for new client b58b32dc-84da-45ed-bc78-3c30f08bfd78 (at 192.168.206.51@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:59 [ 466.287365] Lustre: Skipped 1 previous similar message [ 526.000244] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 526.010561] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 526.075181] Lustre: lustre-MDT0000: Recovery over after 1:00, of 1 clients 0 recovered and 1 was evicted. [ 526.123798] Lustre: lustre-OST0001: deleting orphan objects from 0x0:44 to 0x0:97 [ 526.128060] Lustre: lustre-OST0000: deleting orphan objects from 0x0:76 to 0x0:129 [ 537.001855] Lustre: DEBUG MARKER: == replay-single test 1: simple create =================== 11:12:09 (1776265929) [ 540.239132] LustreError: 16603:0:(osd_handler.c:698:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 541.166470] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 543.158399] Lustre: Failing over lustre-MDT0000 [ 543.738477] Lustre: server umount lustre-MDT0000 complete [ 552.416176] Lustre: 2993:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776265941/real 1776265941] req@00000000018afd08 x1862549315321920/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1776265948 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:1.0' [ 552.416261] LustreError: 166-1: MGC192.168.206.151@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 552.448826] Lustre: 2993:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 4 previous similar messages [ 552.448891] Lustre: lustre-MDT0000-lwp-OST0000: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 569.829778] Lustre: Evicted from MGS (at 192.168.206.151@tcp) after server handle changed from 0x8c5ddb9355494158 to 0x8c5ddb935549455d [ 569.842842] Lustre: MGC192.168.206.151@tcp: Connection restored to (at 0@lo) [ 569.848375] Lustre: Skipped 2 previous similar messages [ 570.404027] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 574.873751] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 574.966138] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 575.207565] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 575.275930] Lustre: lustre-OST0000: deleting orphan objects from 0x0:76 to 0x0:161 [ 575.285107] Lustre: lustre-OST0001: deleting orphan objects from 0x0:44 to 0x0:129 [ 586.236176] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 588.347294] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 599.502942] Lustre: DEBUG MARKER: == replay-single test 2a: touch ========================== 11:13:12 (1776265992) [ 602.674302] LustreError: 18251:0:(osd_handler.c:698:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 603.619381] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 605.788108] Lustre: Failing over lustre-MDT0000 [ 606.248555] Lustre: server umount lustre-MDT0000 complete [ 613.217522] Lustre: 2993:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776266002/real 1776266002] req@0000000073ef1723 x1862549315329792/t0(0) o400->MGC192.168.206.151@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1776266009 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:0.0' [ 613.246271] Lustre: 2993:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 4 previous similar messages [ 613.260769] LustreError: 166-1: MGC192.168.206.151@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 613.277847] Lustre: lustre-MDT0000-lwp-OST0000: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 613.295219] Lustre: Skipped 1 previous similar message [ 630.753594] Lustre: Evicted from MGS (at 192.168.206.151@tcp) after server handle changed from 0x8c5ddb935549455d to 0x8c5ddb93554949c4 [ 630.778545] Lustre: MGC192.168.206.151@tcp: Connection restored to (at 0@lo) [ 630.791806] Lustre: Skipped 2 previous similar messages [ 631.294908] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 635.370223] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 635.580912] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 635.642201] Lustre: lustre-OST0000: deleting orphan objects from 0x0:163 to 0x0:193 [ 635.643606] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 635.643845] Lustre: lustre-OST0001: deleting orphan objects from 0x0:44 to 0x0:161 [ 645.756683] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 647.579456] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 656.349684] Lustre: DEBUG MARKER: == replay-single test 2b: touch ========================== 11:14:09 (1776266049) [ 659.273077] LustreError: 19910:0:(osd_handler.c:698:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 660.125485] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 662.037542] Lustre: Failing over lustre-MDT0000 [ 662.447154] Lustre: server umount lustre-MDT0000 complete [ 673.184293] Lustre: lustre-MDT0000-lwp-OST0000: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 673.201679] Lustre: Skipped 1 previous similar message [ 673.248193] LustreError: 166-1: MGC192.168.206.151@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 679.395377] Lustre: 2993:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776266068/real 1776266068] req@000000004efd0580 x1862549315338176/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1776266075 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:1.0' [ 679.425288] Lustre: 2993:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 10 previous similar messages [ 690.659462] Lustre: Evicted from MGS (at 192.168.206.151@tcp) after server handle changed from 0x8c5ddb93554949c4 to 0x8c5ddb9355494e6a [ 691.029244] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 691.031926] Lustre: Skipped 1 previous similar message [ 691.083344] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 696.443938] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 706.025078] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 706.266477] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 706.338296] Lustre: lustre-OST0000: deleting orphan objects from 0x0:195 to 0x0:225 [ 706.341921] Lustre: lustre-OST0001: deleting orphan objects from 0x0:44 to 0x0:193 [ 706.532931] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to (at 0@lo) [ 706.537994] Lustre: Skipped 3 previous similar messages [ 712.402652] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 714.230721] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 722.671653] Lustre: DEBUG MARKER: == replay-single test 2c: setstripe replay =============== 11:15:15 (1776266115) [ 725.324421] LustreError: 21565:0:(osd_handler.c:698:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 726.362760] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 728.438768] Lustre: Failing over lustre-MDT0000 [ 728.721421] Lustre: server umount lustre-MDT0000 complete [ 739.232162] LustreError: 166-1: MGC192.168.206.151@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 739.252748] 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 [ 739.274212] Lustre: Skipped 2 previous similar messages [ 756.704891] Lustre: Evicted from MGS (at 192.168.206.151@tcp) after server handle changed from 0x8c5ddb9355494e6a to 0x8c5ddb93554952fb [ 757.248393] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 761.720661] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 771.571704] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 771.746554] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 771.797222] Lustre: lustre-OST0000: deleting orphan objects from 0x0:227 to 0x0:257 [ 771.799975] Lustre: lustre-OST0001: deleting orphan objects from 0x0:195 to 0x0:225 [ 777.057369] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 778.470754] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 786.557546] Lustre: DEBUG MARKER: == replay-single test 2d: setdirstripe replay ============ 11:16:19 (1776266179) [ 789.922622] LustreError: 23210:0:(osd_handler.c:698:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 790.841892] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 793.193060] Lustre: Failing over lustre-MDT0000 [ 793.794092] Lustre: server umount lustre-MDT0000 complete [ 805.216365] LustreError: 166-1: MGC192.168.206.151@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 805.328253] Lustre: lustre-MDT0000-lwp-OST0000: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 805.349305] Lustre: Skipped 1 previous similar message [ 810.405989] Lustre: 2991:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776266199/real 1776266199] req@00000000552263db x1862549315354240/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1776266206 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:0.0' [ 810.434648] Lustre: 2991:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 9 previous similar messages [ 822.766878] Lustre: Evicted from MGS (at 192.168.206.151@tcp) after server handle changed from 0x8c5ddb93554952fb to 0x8c5ddb935549579a [ 823.450156] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 823.453160] Lustre: Skipped 1 previous similar message [ 823.595899] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 828.402518] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 837.104257] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 837.231293] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 837.303990] Lustre: lustre-OST0001: deleting orphan objects from 0x0:195 to 0x0:257 [ 837.304031] Lustre: lustre-OST0000: deleting orphan objects from 0x0:227 to 0x0:289 [ 838.573572] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to (at 0@lo) [ 838.576066] Lustre: Skipped 5 previous similar messages [ 844.121414] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 846.342641] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 855.964669] Lustre: DEBUG MARKER: == replay-single test 2e: O_CREAT|O_EXCL create replay === 11:17:28 (1776266248) [ 857.006724] Lustre: *** cfs_fail_loc=13b, val=315*** [ 857.012026] Lustre: *** cfs_fail_loc=13b, val=2147483648*** [ 857.019880] LustreError: 23830:0:(ldlm_lib.c:3224:target_send_reply_msg()) @@@ dropping reply req@00000000b5adafbc x1862549305877248/t38654705666(0) o35->b58b32dc-84da-45ed-bc78-3c30f08bfd78@192.168.206.51@tcp:419/0 lens 392/456 e 0 to 0 dl 1776266269 ref 1 fl Interpret:/0/0 rc 0/0 job:'openfile.0' [ 861.260753] LustreError: 24915:0:(osd_handler.c:698:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 862.390661] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 876.448220] LustreError: 166-1: MGC192.168.206.151@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 893.929390] Lustre: Evicted from MGS (at 192.168.206.151@tcp) after server handle changed from 0x8c5ddb935549579a to 0x8c5ddb9355495bde [ 894.724213] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 899.230758] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 908.425274] Lustre: lustre-OST0001: deleting orphan objects from 0x0:195 to 0x0:289 [ 908.427812] Lustre: lustre-OST0000: deleting orphan objects from 0x0:227 to 0x0:321 [ 908.437386] Lustre: 25533:0:(mdt_recovery.c:200:mdt_req_from_lrd()) @@@ restoring transno req@00000000771e6576 x1862549305877248/t38654705666(0) o35->b58b32dc-84da-45ed-bc78-3c30f08bfd78@192.168.206.51@tcp:471/0 lens 392/456 e 0 to 0 dl 1776266321 ref 1 fl Interpret:/2/0 rc 0/0 job:'openfile.0' [ 914.669738] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 916.595575] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 926.002439] Lustre: DEBUG MARKER: == replay-single test 3a: replay failed open(O_DIRECTORY) ========================================================== 11:18:38 (1776266318) [ 930.083969] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 932.371230] Lustre: Failing over lustre-MDT0000 [ 932.373060] Lustre: Skipped 1 previous similar message [ 932.722521] Lustre: server umount lustre-MDT0000 complete [ 932.724532] Lustre: Skipped 1 previous similar message [ 942.496163] Lustre: lustre-MDT0000-lwp-OST0000: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 942.511104] Lustre: Skipped 2 previous similar messages [ 951.918714] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 956.843812] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 958.615643] Lustre: lustre-OST0000: deleting orphan objects from 0x0:227 to 0x0:353 [ 958.616960] Lustre: lustre-OST0001: deleting orphan objects from 0x0:195 to 0x0:321 [ 965.797309] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 967.320265] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 974.553497] Lustre: DEBUG MARKER: == replay-single test 3b: replay failed open -ENOMEM ===== 11:19:27 (1776266367) [ 978.043270] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 978.978606] Lustre: *** cfs_fail_loc=114, val=0*** [ 1009.705338] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1013.658576] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 1023.978531] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1023.982019] Lustre: Skipped 2 previous similar messages [ 1024.087110] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1024.103210] Lustre: Skipped 2 previous similar messages [ 1024.145301] Lustre: lustre-OST0001: deleting orphan objects from 0x0:195 to 0x0:353 [ 1024.145385] Lustre: lustre-OST0000: deleting orphan objects from 0x0:227 to 0x0:385 [ 1030.454705] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1032.489591] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1041.817647] Lustre: DEBUG MARKER: == replay-single test 3c: replay failed open -ENOMEM ===== 11:20:34 (1776266434) [ 1045.392659] LustreError: 29980:0:(osd_handler.c:698:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 1045.411506] LustreError: 29980:0:(osd_handler.c:698:osd_ro()) Skipped 2 previous similar messages [ 1046.534768] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1047.771096] Lustre: *** cfs_fail_loc=128, val=0*** [ 1063.908301] LustreError: 166-1: MGC192.168.206.151@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1063.924301] LustreError: Skipped 2 previous similar messages [ 1080.297311] Lustre: Evicted from MGS (at 192.168.206.151@tcp) after server handle changed from 0x8c5ddb935549643c to 0x8c5ddb9355496864 [ 1080.308683] Lustre: Skipped 2 previous similar messages [ 1080.863476] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1080.868318] Lustre: Skipped 3 previous similar messages [ 1080.951964] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1084.991234] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 1094.795640] Lustre: lustre-OST0000: deleting orphan objects from 0x0:227 to 0x0:417 [ 1094.796336] Lustre: lustre-OST0001: deleting orphan objects from 0x0:195 to 0x0:385 [ 1101.522739] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1103.294768] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1112.760505] Lustre: DEBUG MARKER: == replay-single test 4a: |x| 10 open(O_CREAT)s ========== 11:21:45 (1776266505) [ 1117.113789] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1129.888146] Lustre: 2992:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776266518/real 1776266518] req@0000000079a87b79 x1862549315396032/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1776266525 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:0.0' [ 1129.930529] Lustre: 2992:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 24 previous similar messages [ 1141.259168] Lustre: MGC192.168.206.151@tcp: Connection restored to (at 0@lo) [ 1141.261890] Lustre: Skipped 13 previous similar messages [ 1144.377231] Lustre: lustre-OST0000: deleting orphan objects from 0x0:423 to 0x0:449 [ 1144.377783] Lustre: lustre-OST0001: deleting orphan objects from 0x0:391 to 0x0:417 [ 1147.556575] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 1157.272771] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1159.242979] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1169.837342] Lustre: DEBUG MARKER: == replay-single test 4b: |x| rm 10 files ================ 11:22:42 (1776266562) [ 1174.706368] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1206.709126] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1206.723804] Lustre: Skipped 1 previous similar message [ 1211.593895] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 1219.780331] Lustre: lustre-OST0000: deleting orphan objects from 0x0:455 to 0x0:481 [ 1219.780550] Lustre: lustre-OST0001: deleting orphan objects from 0x0:423 to 0x0:449 [ 1227.506393] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1230.112752] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1241.424461] Lustre: DEBUG MARKER: == replay-single test 5: |x| 220 open(O_CREAT) =========== 11:23:54 (1776266634) [ 1246.548822] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1257.259814] Lustre: Failing over lustre-MDT0000 [ 1257.264328] Lustre: Skipped 4 previous similar messages [ 1257.770252] Lustre: server umount lustre-MDT0000 complete [ 1257.774890] Lustre: Skipped 4 previous similar messages [ 1265.120178] Lustre: lustre-MDT0000-lwp-OST0000: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 1265.148563] Lustre: Skipped 10 previous similar messages [ 1284.100780] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1284.119305] Lustre: Skipped 3 previous similar messages [ 1288.041935] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 1289.129599] Lustre: lustre-MDT0000: Recovery over after 0:05, of 1 clients 1 recovered and 0 were evicted. [ 1289.144767] Lustre: Skipped 3 previous similar messages [ 1289.225952] Lustre: lustre-OST0000: deleting orphan objects from 0x0:592 to 0x0:609 [ 1289.231145] Lustre: lustre-OST0001: deleting orphan objects from 0x0:560 to 0x0:577 [ 1299.576316] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1301.281528] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1327.383027] Lustre: DEBUG MARKER: == replay-single test 6a: mkdir + contained create ======= 11:25:20 (1776266720) [ 1330.493472] LustreError: 36715:0:(osd_handler.c:698:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 1330.500274] LustreError: 36715:0:(osd_handler.c:698:osd_ro()) Skipped 3 previous similar messages [ 1331.394840] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1341.409423] LustreError: 166-1: MGC192.168.206.151@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1341.428139] LustreError: Skipped 3 previous similar messages [ 1358.837322] Lustre: Evicted from MGS (at 192.168.206.151@tcp) after server handle changed from 0x8c5ddb935549a0e2 to 0x8c5ddb93554a04c5 [ 1358.851397] Lustre: Skipped 3 previous similar messages [ 1359.406918] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1359.419915] Lustre: Skipped 1 previous similar message [ 1360.746025] Lustre: lustre-OST0001: deleting orphan objects from 0x0:560 to 0x0:609 [ 1360.749212] Lustre: lustre-OST0000: deleting orphan objects from 0x0:592 to 0x0:641 [ 1363.945789] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 1373.195893] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1375.030855] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1385.417038] Lustre: DEBUG MARKER: == replay-single test 6b: |X| rmdir ====================== 11:26:18 (1776266778) [ 1389.578960] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1421.251949] Lustre: lustre-OST0000: deleting orphan objects from 0x0:592 to 0x0:673 [ 1421.254815] Lustre: lustre-OST0001: deleting orphan objects from 0x0:560 to 0x0:641 [ 1424.967403] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 1435.283661] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1437.512394] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1446.564944] Lustre: DEBUG MARKER: == replay-single test 7: mkdir |X| contained create ====== 11:27:19 (1776266839) [ 1450.788818] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1483.958870] Lustre: lustre-OST0000: deleting orphan objects from 0x0:592 to 0x0:705 [ 1483.962206] Lustre: lustre-OST0001: deleting orphan objects from 0x0:560 to 0x0:673 [ 1485.214307] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 1494.516978] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1496.120596] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1504.889875] Lustre: DEBUG MARKER: == replay-single test 8: creat open |X| close ============ 11:28:17 (1776266897) [ 1509.183527] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1541.742189] Lustre: lustre-OST0001: deleting orphan objects from 0x0:560 to 0x0:705 [ 1541.743931] Lustre: lustre-OST0000: deleting orphan objects from 0x0:592 to 0x0:737 [ 1544.998835] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 1554.187790] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1555.972371] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1563.697680] Lustre: DEBUG MARKER: == replay-single test 9: |X| create (same inum/gen) ====== 11:29:16 (1776266956) [ 1567.078775] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1594.975413] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1594.980850] Lustre: Skipped 7 previous similar messages [ 1597.245988] Lustre: lustre-OST0001: deleting orphan objects from 0x0:560 to 0x0:737 [ 1597.247812] Lustre: lustre-OST0000: deleting orphan objects from 0x0:592 to 0x0:769 [ 1599.652506] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 1608.127960] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1609.731744] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1619.666234] Lustre: DEBUG MARKER: == replay-single test 10: create |X| rename unlink ======= 11:30:12 (1776267012) [ 1624.478097] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1654.242210] Lustre: MGC192.168.206.151@tcp: Connection restored to (at 0@lo) [ 1654.251788] Lustre: Skipped 23 previous similar messages [ 1654.755623] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1654.765542] Lustre: Skipped 4 previous similar messages [ 1656.465126] Lustre: lustre-OST0001: deleting orphan objects from 0x0:560 to 0x0:769 [ 1656.465426] Lustre: lustre-OST0000: deleting orphan objects from 0x0:592 to 0x0:801 [ 1659.337314] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 1669.041030] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1670.829862] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1671.136969] Lustre: 2991:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776267026/real 1776267026] req@00000000ac1d37aa x1862549315493824/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1776267067 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:2.0' [ 1671.156224] Lustre: 2991:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 97 previous similar messages [ 1679.360177] Lustre: DEBUG MARKER: == replay-single test 11: create open write rename |X| create-old-name read ========================================================== 11:31:12 (1776267072) [ 1683.532175] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1716.460094] Lustre: lustre-OST0001: deleting orphan objects from 0x0:771 to 0x0:801 [ 1716.460481] Lustre: lustre-OST0000: deleting orphan objects from 0x0:803 to 0x0:833 [ 1720.350692] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 1730.605084] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1732.499456] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1740.373158] Lustre: DEBUG MARKER: == replay-single test 12: open, unlink |X| close ========= 11:32:13 (1776267133) [ 1745.160927] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1775.893598] Lustre: lustre-OST0000: deleting orphan objects from 0x0:803 to 0x0:865 [ 1778.214782] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 1778.658612] Lustre: lustre-MDT0000-lwp-OST0000: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 1778.682532] Lustre: Skipped 15 previous similar messages [ 1787.486527] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1789.248524] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1797.179933] Lustre: DEBUG MARKER: == replay-single test 13: open chmod 0 |x| write close === 11:33:10 (1776267190) [ 1801.301195] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1803.316962] Lustre: Failing over lustre-MDT0000 [ 1803.322407] Lustre: Skipped 8 previous similar messages [ 1803.661124] Lustre: server umount lustre-MDT0000 complete [ 1803.664455] Lustre: Skipped 8 previous similar messages [ 1831.614575] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1831.625176] Lustre: Skipped 8 previous similar messages [ 1831.751431] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1831.765149] Lustre: Skipped 8 previous similar messages [ 1831.815842] Lustre: lustre-OST0000: deleting orphan objects from 0x0:867 to 0x0:897 [ 1831.829664] Lustre: lustre-OST0001: deleting orphan objects from 0x0:771 to 0x0:833 [ 1835.733789] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 1845.060151] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1847.043512] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1858.574194] Lustre: DEBUG MARKER: == replay-single test 14: open(O_CREAT), unlink |X| close ========================================================== 11:34:11 (1776267251) [ 1862.755954] LustreError: 51510:0:(osd_handler.c:698:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 1862.759342] LustreError: 51510:0:(osd_handler.c:698:osd_ro()) Skipped 8 previous similar messages [ 1863.630984] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1877.984293] LustreError: 166-1: MGC192.168.206.151@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1877.994707] LustreError: Skipped 8 previous similar messages [ 1895.402362] Lustre: Evicted from MGS (at 192.168.206.151@tcp) after server handle changed from 0x8c5ddb93554a2a49 to 0x8c5ddb93554a2f20 [ 1895.424243] Lustre: Skipped 8 previous similar messages [ 1896.870791] Lustre: lustre-OST0000: deleting orphan objects from 0x0:899 to 0x0:929 [ 1896.871329] Lustre: lustre-OST0001: deleting orphan objects from 0x0:771 to 0x0:865 [ 1900.537349] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 1909.304834] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1910.911979] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1919.466263] Lustre: DEBUG MARKER: == replay-single test 15: open(O_CREAT), unlink |X| touch new, close ========================================================== 11:35:12 (1776267312) [ 1923.169743] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1951.991576] Lustre: lustre-OST0000: deleting orphan objects from 0x0:931 to 0x0:961 [ 1951.995866] Lustre: lustre-OST0001: deleting orphan objects from 0x0:867 to 0x0:897 [ 1955.240469] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 1964.538146] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1966.204405] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1974.971987] Lustre: DEBUG MARKER: == replay-single test 16: |X| open(O_CREAT), unlink, touch new, unlink new ========================================================== 11:36:07 (1776267367) [ 1979.026171] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2014.683578] Lustre: lustre-OST0000: deleting orphan objects from 0x0:963 to 0x0:993 [ 2014.684591] Lustre: lustre-OST0001: deleting orphan objects from 0x0:867 to 0x0:929 [ 2020.043428] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 2032.312179] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2034.517616] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2044.006708] Lustre: DEBUG MARKER: == replay-single test 17: |X| open(O_CREAT), |replay| close ========================================================== 11:37:16 (1776267436) [ 2048.646837] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2079.116470] Lustre: lustre-OST0001: deleting orphan objects from 0x0:931 to 0x0:961 [ 2079.125653] Lustre: lustre-OST0000: deleting orphan objects from 0x0:963 to 0x0:1025 [ 2082.829372] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 2094.209731] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2096.109635] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2104.424629] Lustre: DEBUG MARKER: == replay-single test 18: open(O_CREAT), unlink, touch new, close, touch, unlink ========================================================== 11:38:17 (1776267497) [ 2108.389826] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2138.437812] Lustre: lustre-OST0001: deleting orphan objects from 0x0:963 to 0x0:993 [ 2138.437990] Lustre: lustre-OST0000: deleting orphan objects from 0x0:1027 to 0x0:1057 [ 2141.542396] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 2153.861621] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2155.990497] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2167.055364] Lustre: DEBUG MARKER: == replay-single test 19: mcreate, open, write, rename === 11:39:19 (1776267559) [ 2171.259757] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2202.035586] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 2202.042941] Lustre: Skipped 9 previous similar messages [ 2202.129029] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 2202.138751] Lustre: Skipped 8 previous similar messages [ 2203.877951] Lustre: lustre-OST0001: deleting orphan objects from 0x0:995 to 0x0:1025 [ 2203.879325] Lustre: lustre-OST0000: deleting orphan objects from 0x0:1059 to 0x0:1089 [ 2207.166627] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 2217.211800] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2218.860739] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2226.732561] Lustre: DEBUG MARKER: == replay-single test 20a: |X| open(O_CREAT), unlink, replay, close (test mds_cleanup_orphans) ========================================================== 11:40:19 (1776267619) [ 2230.393498] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2232.805972] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2232.814041] Lustre: Skipped 1 previous similar message [ 2261.422241] Lustre: MGC192.168.206.151@tcp: Connection restored to (at 0@lo) [ 2261.432797] Lustre: Skipped 29 previous similar messages [ 2263.216290] Lustre: lustre-OST0001: deleting orphan objects from 0x0:1027 to 0x0:1057 [ 2263.220246] Lustre: lustre-OST0000: deleting orphan objects from 0x0:1059 to 0x0:1121 [ 2266.321410] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 2275.971842] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2277.948602] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2286.796664] Lustre: DEBUG MARKER: == replay-single test 20b: write, unlink, eviction, replay (test mds_cleanup_orphans) ========================================================== 11:41:19 (1776267679) [ 2291.325781] Lustre: 63019:0:(genops.c:1710:obd_export_evict_by_uuid()) lustre-MDT0000: evicting b58b32dc-84da-45ed-bc78-3c30f08bfd78 at adminstrative request [ 2308.064228] Lustre: 2991:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776267696/real 1776267696] req@00000000b5235400 x1862549315585024/t0(0) o400->MGC192.168.206.151@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1776267703 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:1.0' [ 2308.109980] Lustre: 2991:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 146 previous similar messages [ 2327.700459] Lustre: lustre-OST0001: deleting orphan objects from 0x0:1027 to 0x0:1089 [ 2327.704101] Lustre: lustre-OST0000: deleting orphan objects from 0x0:1123 to 0x0:1153 [ 2330.412824] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 2339.372828] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2340.889995] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2345.990185] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 2359.012386] Lustre: DEBUG MARKER: before 6144, after 6144 [ 2365.781695] Lustre: DEBUG MARKER: == replay-single test 20c: check that client eviction does not affect file content ========================================================== 11:42:38 (1776267758) [ 2367.082174] Lustre: 65045:0:(genops.c:1710:obd_export_evict_by_uuid()) lustre-MDT0000: evicting b58b32dc-84da-45ed-bc78-3c30f08bfd78 at adminstrative request [ 2380.055496] Lustre: DEBUG MARKER: == replay-single test 21: |X| open(O_CREAT), unlink touch new, replay, close (test mds_cleanup_orphans) ========================================================== 11:42:52 (1776267772) [ 2384.712173] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2387.427664] 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 [ 2387.441598] Lustre: Skipped 18 previous similar messages [ 2387.450421] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2387.463348] Lustre: Skipped 1 previous similar message [ 2419.800189] Lustre: lustre-OST0000: deleting orphan objects from 0x0:1156 to 0x0:1185 [ 2419.800440] Lustre: lustre-OST0001: deleting orphan objects from 0x0:1091 to 0x0:1121 [ 2422.478112] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 2433.874798] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2435.798235] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2444.761137] Lustre: DEBUG MARKER: == replay-single test 22: open(O_CREAT), |X| unlink, replay, close (test mds_cleanup_orphans) ========================================================== 11:43:57 (1776267837) [ 2449.165096] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2451.177113] Lustre: Failing over lustre-MDT0000 [ 2451.179830] Lustre: Skipped 9 previous similar messages [ 2451.691828] Lustre: server umount lustre-MDT0000 complete [ 2451.701607] Lustre: Skipped 9 previous similar messages [ 2480.911236] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 2480.926214] Lustre: Skipped 9 previous similar messages [ 2481.122814] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 2481.130255] Lustre: Skipped 9 previous similar messages [ 2481.173444] Lustre: lustre-OST0000: deleting orphan objects from 0x0:1187 to 0x0:1217 [ 2481.174834] Lustre: lustre-OST0001: deleting orphan objects from 0x0:1123 to 0x0:1153 [ 2485.953961] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 2496.853607] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2499.186675] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2508.407939] Lustre: DEBUG MARKER: == replay-single test 23: open(O_CREAT), |X| unlink touch new, replay, close (test mds_cleanup_orphans) ========================================================== 11:45:01 (1776267901) [ 2511.895484] LustreError: 68679:0:(osd_handler.c:698:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 2511.908363] LustreError: 68679:0:(osd_handler.c:698:osd_ro()) Skipped 8 previous similar messages [ 2512.849955] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2523.616195] LustreError: 166-1: MGC192.168.206.151@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2523.633514] LustreError: Skipped 9 previous similar messages [ 2541.030607] Lustre: Evicted from MGS (at 192.168.206.151@tcp) after server handle changed from 0x8c5ddb93554a5b81 to 0x8c5ddb93554a603c [ 2541.045725] Lustre: Skipped 9 previous similar messages [ 2543.924588] Lustre: lustre-OST0000: deleting orphan objects from 0x0:1219 to 0x0:1249 [ 2543.927781] Lustre: lustre-OST0001: deleting orphan objects from 0x0:1155 to 0x0:1185 [ 2546.898321] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 2558.410617] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2560.289762] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2569.526954] Lustre: DEBUG MARKER: == replay-single test 24: open(O_CREAT), replay, unlink, close (test mds_cleanup_orphans) ========================================================== 11:46:02 (1776267962) [ 2574.404183] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2577.391447] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2577.402497] Lustre: Skipped 1 previous similar message [ 2608.446942] Lustre: lustre-OST0001: deleting orphan objects from 0x0:1187 to 0x0:1217 [ 2608.455597] Lustre: lustre-OST0000: deleting orphan objects from 0x0:1251 to 0x0:1281 [ 2613.647736] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 2626.435400] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2629.331159] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2639.672418] Lustre: DEBUG MARKER: == replay-single test 25: open(O_CREAT), unlink, replay, close (test mds_cleanup_orphans) ========================================================== 11:47:12 (1776268032) [ 2644.194779] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2669.812353] Lustre: lustre-OST0000: deleting orphan objects from 0x0:1283 to 0x0:1313 [ 2669.822307] Lustre: lustre-OST0001: deleting orphan objects from 0x0:1187 to 0x0:1249 [ 2671.549108] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 2683.784284] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2685.957154] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2697.556295] Lustre: DEBUG MARKER: == replay-single test 26: |X| open(O_CREAT), unlink two, close one, replay, close one (test mds_cleanup_orphans) ========================================================== 11:48:10 (1776268090) [ 2702.028171] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2731.334896] Lustre: lustre-OST0000: deleting orphan objects from 0x0:1315 to 0x0:1345 [ 2731.335342] Lustre: lustre-OST0001: deleting orphan objects from 0x0:1251 to 0x0:1281 [ 2732.364931] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 2744.346052] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2746.181575] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2756.908661] Lustre: DEBUG MARKER: == replay-single test 27: |X| open(O_CREAT), unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 11:49:09 (1776268149) [ 2761.886260] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2787.686701] Lustre: lustre-OST0001: deleting orphan objects from 0x0:1283 to 0x0:1313 [ 2787.691440] Lustre: lustre-OST0000: deleting orphan objects from 0x0:1347 to 0x0:1377 [ 2792.785682] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 2804.175758] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2806.700797] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2816.826709] Lustre: DEBUG MARKER: == replay-single test 28: open(O_CREAT), |X| unlink two, close one, replay, close one (test mds_cleanup_orphans) ========================================================== 11:50:09 (1776268209) [ 2821.307884] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2852.028883] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 2852.038603] Lustre: Skipped 9 previous similar messages [ 2852.160804] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 2852.180341] Lustre: Skipped 9 previous similar messages [ 2853.044177] Lustre: lustre-OST0001: deleting orphan objects from 0x0:1315 to 0x0:1345 [ 2853.060139] Lustre: lustre-OST0000: deleting orphan objects from 0x0:1379 to 0x0:1409 [ 2857.382690] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 2868.448427] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2870.835191] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2879.741345] Lustre: DEBUG MARKER: == replay-single test 29: open(O_CREAT), |X| unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 11:51:12 (1776268272) [ 2884.091627] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2911.213717] Lustre: MGC192.168.206.151@tcp: Connection restored to (at 0@lo) [ 2911.216247] Lustre: Skipped 29 previous similar messages [ 2912.477761] Lustre: lustre-OST0001: deleting orphan objects from 0x0:1347 to 0x0:1377 [ 2912.485718] Lustre: lustre-OST0000: deleting orphan objects from 0x0:1411 to 0x0:1441 [ 2916.272096] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 2927.651407] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2929.123373] Lustre: 2993:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776268283/real 1776268283] req@000000007465a464 x1862549315664064/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1776268324 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:3.0' [ 2929.175557] Lustre: 2993:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 97 previous similar messages [ 2930.025368] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2939.670782] Lustre: DEBUG MARKER: == replay-single test 30: open(O_CREAT) two, unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 11:52:12 (1776268332) [ 2945.110726] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2968.302961] Lustre: lustre-OST0000: deleting orphan objects from 0x0:1443 to 0x0:1473 [ 2968.303160] Lustre: lustre-OST0001: deleting orphan objects from 0x0:1379 to 0x0:1409 [ 2970.899130] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 2981.112759] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2983.161748] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2992.541782] Lustre: DEBUG MARKER: == replay-single test 31: open(O_CREAT) two, unlink one, |X| unlink one, close two (test mds_cleanup_orphans) ========================================================== 11:53:05 (1776268385) [ 2996.427479] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3027.204589] Lustre: lustre-MDT0000-lwp-OST0000: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 3027.214387] Lustre: Skipped 19 previous similar messages [ 3029.222446] Lustre: lustre-OST0001: deleting orphan objects from 0x0:1411 to 0x0:1441 [ 3029.222486] Lustre: lustre-OST0000: deleting orphan objects from 0x0:1475 to 0x0:1505 [ 3032.558902] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 3044.696858] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3047.002971] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3058.420454] Lustre: DEBUG MARKER: == replay-single test 32: close() notices client eviction; close() after client eviction ========================================================== 11:54:11 (1776268451) [ 3059.579114] Lustre: 83368:0:(genops.c:1710:obd_export_evict_by_uuid()) lustre-MDT0000: evicting b58b32dc-84da-45ed-bc78-3c30f08bfd78 at adminstrative request [ 3069.227111] Lustre: DEBUG MARKER: == replay-single test 33a: fid seq shouldn't be reused after abort recovery ========================================================== 11:54:21 (1776268461) [ 3072.226877] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3074.276935] Lustre: Failing over lustre-MDT0000 [ 3074.280912] Lustre: Skipped 9 previous similar messages [ 3074.503489] Lustre: server umount lustre-MDT0000 complete [ 3074.510437] Lustre: Skipped 9 previous similar messages [ 3082.238113] LustreError: 84231:0:(mdt_handler.c:7428:mdt_iocontrol()) lustre-MDT0000: Aborting recovery for device [ 3082.246453] LustreError: 84231:0:(ldlm_lib.c:2882:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 3082.252593] Lustre: 84277:0:(ldlm_lib.c:2288:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 3082.261205] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 3082.351987] Lustre: lustre-OST0001: deleting orphan objects from 0x0:1447 to 0x0:1473 [ 3082.356608] Lustre: lustre-OST0000: deleting orphan objects from 0x0:1512 to 0x0:1537 [ 3087.139818] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 3100.415990] Lustre: DEBUG MARKER: == replay-single test 33b: test fid seq allocation ======= 11:54:53 (1776268493) [ 3104.500534] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3114.829668] 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. [ 3114.843942] LustreError: Skipped 2 previous similar messages [ 3114.997473] Lustre: lustre-MDT0000: Not available for connect from 192.168.206.51@tcp (not set up) [ 3115.309958] Lustre: *** cfs_fail_loc=1311, val=0*** [ 3115.334264] LustreError: 85604:0:(mdt_handler.c:7428:mdt_iocontrol()) lustre-MDT0000: Aborting recovery for device [ 3115.339630] LustreError: 85604:0:(ldlm_lib.c:2882:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 3115.344250] Lustre: 85652:0:(ldlm_lib.c:2288:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 3115.349106] Lustre: 85652:0:(ldlm_lib.c:2288:target_recovery_overseer()) Skipped 2 previous similar messages [ 3115.356422] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 3115.427568] Lustre: lustre-OST0001: deleting orphan objects from 0x0:1484 to 0x0:1505 [ 3115.438187] Lustre: lustre-OST0000: deleting orphan objects from 0x0:1548 to 0x0:1569 [ 3119.273983] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 3124.767273] Lustre: *** cfs_fail_loc=1311, val=0*** [ 3132.278433] Lustre: DEBUG MARKER: == replay-single test 34: abort recovery before client does replay (test mds_cleanup_orphans) ========================================================== 11:55:25 (1776268525) [ 3135.413411] LustreError: 86409:0:(osd_handler.c:698:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 3135.420624] LustreError: 86409:0:(osd_handler.c:698:osd_ro()) Skipped 10 previous similar messages [ 3136.408762] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3145.283795] LustreError: 166-1: MGC192.168.206.151@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3145.304794] LustreError: Skipped 10 previous similar messages [ 3145.320522] Lustre: Evicted from MGS (at 192.168.206.151@tcp) after server handle changed from 0x8c5ddb93554a99a1 to 0x8c5ddb93554aa3b8 [ 3145.335693] Lustre: Skipped 10 previous similar messages [ 3145.814648] LustreError: 86980:0:(mdt_handler.c:7428:mdt_iocontrol()) lustre-MDT0000: Aborting recovery for device [ 3145.824195] LustreError: 86980:0:(ldlm_lib.c:2882:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 3145.836599] Lustre: 87027:0:(ldlm_lib.c:2288:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 3145.842261] Lustre: 87027:0:(ldlm_lib.c:2288:target_recovery_overseer()) Skipped 2 previous similar messages [ 3145.851140] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 3145.925909] Lustre: lustre-OST0001: deleting orphan objects from 0x0:1512 to 0x0:1537 [ 3145.931640] Lustre: lustre-OST0000: deleting orphan objects from 0x0:1575 to 0x0:1601 [ 3150.093126] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 3163.472588] Lustre: DEBUG MARKER: == replay-single test 35: test recovery from llog for unlink op ========================================================== 11:55:56 (1776268556) [ 3164.916107] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 3164.920299] LustreError: 87113:0:(ldlm_lib.c:3224:target_send_reply_msg()) @@@ dropping reply req@00000000cea4316d x1862549306380608/t201863462916(0) o36->b58b32dc-84da-45ed-bc78-3c30f08bfd78@192.168.206.51@tcp:451/0 lens 504/456 e 0 to 0 dl 1776268566 ref 1 fl Interpret:/0/0 rc 0/0 job:'rm.0' [ 3178.549710] LustreError: 88199:0:(mdt_handler.c:7428:mdt_iocontrol()) lustre-MDT0000: Aborting recovery for device [ 3178.559510] LustreError: 88199:0:(ldlm_lib.c:2882:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 3178.566886] Lustre: 88246:0:(ldlm_lib.c:2288:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 3178.576231] Lustre: 88246:0:(ldlm_lib.c:2288:target_recovery_overseer()) Skipped 2 previous similar messages [ 3178.586554] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 3178.687578] Lustre: lustre-OST0001: deleting orphan objects from 0x0:1539 to 0x0:1569 [ 3178.691018] Lustre: lustre-OST0000: deleting orphan objects from 0x0:1575 to 0x0:1633 [ 3183.860103] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 3197.886508] Lustre: DEBUG MARKER: == replay-single test 36: don't resend cancel ============ 11:56:30 (1776268590) [ 3202.145891] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3239.983913] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 3249.135205] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 3249.144679] Lustre: Skipped 9 previous similar messages [ 3249.276219] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 3249.285238] Lustre: Skipped 9 previous similar messages [ 3249.325050] Lustre: lustre-OST0001: deleting orphan objects from 0x0:1571 to 0x0:1601 [ 3249.329263] Lustre: lustre-OST0000: deleting orphan objects from 0x0:1575 to 0x0:1665 [ 3257.295981] Lustre: DEBUG MARKER: == replay-single test 37: abort recovery before client does replay (test mds_cleanup_orphans for directories) ========================================================== 11:57:30 (1776268650) [ 3261.926093] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3278.783284] LustreError: 91026:0:(mdt_handler.c:7428:mdt_iocontrol()) lustre-MDT0000: Aborting recovery for device [ 3278.790851] LustreError: 91026:0:(ldlm_lib.c:2882:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 3278.801092] Lustre: 91073:0:(ldlm_lib.c:2288:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 3278.820692] Lustre: 91073:0:(ldlm_lib.c:2288:target_recovery_overseer()) Skipped 2 previous similar messages [ 3278.840018] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 3278.926598] Lustre: lustre-OST0001: deleting orphan objects from 0x0:1571 to 0x0:1633 [ 3278.931570] Lustre: lustre-OST0000: deleting orphan objects from 0x0:1575 to 0x0:1697 [ 3284.027922] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 3296.571422] Lustre: DEBUG MARKER: == replay-single test 38: test recovery from unlink llog (test llog_gen_rec) ========================================================== 11:58:09 (1776268689) [ 3321.951499] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3323.887240] Lustre: lustre-MDT0000: Not available for connect from 192.168.206.51@tcp (stopping) [ 3325.924772] 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. [ 3325.952828] LustreError: Skipped 1 previous similar message [ 3354.773733] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 3355.840369] Lustre: lustre-OST0001: deleting orphan objects from 0x0:2034 to 0x0:2049 [ 3355.840648] Lustre: lustre-OST0000: deleting orphan objects from 0x0:2098 to 0x0:2113 [ 3367.913590] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3370.353430] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3394.197429] Lustre: DEBUG MARKER: == replay-single test 39: test recovery from unlink llog (test llog_gen_rec) ========================================================== 11:59:47 (1776268787) [ 3416.103765] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3425.646217] LustreError: 2992:0:(client.c:1256:ptlrpc_import_delay_req()) @@@ IMP_CLOSED req@00000000521ae29e x1862549315826304/t0(0) o6->lustre-OST0001-osc-MDT0000@0@lo:28/4 lens 544/432 e 0 to 0 dl 0 ref 1 fl Rpc:QU/0/ffffffff rc 0/-1 job:'osp-syn-1-0.0' [ 3452.923600] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3452.931981] Lustre: Skipped 10 previous similar messages [ 3453.002547] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 3453.014517] Lustre: Skipped 20 previous similar messages [ 3457.912534] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 3458.060790] Lustre: lustre-OST0001: deleting orphan objects from 0x0:2450 to 0x0:2465 [ 3458.061254] Lustre: lustre-OST0000: deleting orphan objects from 0x0:2514 to 0x0:2529 [ 3468.194721] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3469.880596] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3488.082941] Lustre: DEBUG MARKER: == replay-single test 40: cause recovery in ptlrpc, ensure IO continues ========================================================== 12:01:21 (1776268881) [ 3489.203306] Lustre: DEBUG MARKER: SKIP: replay-single test_40 layout_lock needs MDS connection for IO [ 3490.758802] Lustre: DEBUG MARKER: == replay-single test 41: read from a valid osc while other oscs are invalid ========================================================== 12:01:23 (1776268883) [ 3492.460422] Lustre: setting import lustre-OST0001_UUID INACTIVE by administrator request [ 3493.204776] Lustre: lustre-OST0001: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnecting [ 3493.220267] LustreError: lustre-OST0001-osc-MDT0000: This client was evicted by lustre-OST0001; in progress operations using this service will fail. [ 3493.232788] Lustre: lustre-OST0001: deleting orphan objects from 0x0:2450 to 0x0:2497 [ 3498.939570] Lustre: DEBUG MARKER: == replay-single test 42: recovery after ost failure ===== 12:01:32 (1776268892) [ 3517.291763] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 3529.696856] LustreError: 11-0: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 3529.705727] Lustre: lustre-OST0000: Not available for connect from 0@lo (stopping) [ 3532.787852] LustreError: 137-5: lustre-OST0000_UUID: not available for connect from 192.168.206.51@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3537.906742] LustreError: 137-5: lustre-OST0000_UUID: not available for connect from 192.168.206.51@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3537.919203] LustreError: Skipped 1 previous similar message [ 3548.767781] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 192.168.206.151@tcp (at 0@lo) [ 3548.772818] Lustre: lustre-OST0000: deleting orphan objects from 0x0:2931 to 0x0:2977 [ 3548.778710] Lustre: Skipped 33 previous similar messages [ 3551.028354] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 3606.361286] Lustre: DEBUG MARKER: == replay-single test 43: mds osc import failure during recovery; don't LBUG ========================================================== 12:03:19 (1776268999) [ 3610.120715] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3620.321043] Lustre: 2990:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776269009/real 1776269009] req@000000006fbe7304 x1862549315952512/t0(0) o400->MGC192.168.206.151@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1776269016 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:3.0' [ 3620.349056] Lustre: 2990:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 89 previous similar messages [ 3638.019952] Lustre: lustre-MDT0000-lwp-OST0000: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 3638.038592] Lustre: Skipped 19 previous similar messages [ 3638.361740] Lustre: *** cfs_fail_loc=204, val=2147483648*** [ 3638.363525] Lustre: lustre-OST0000: deleting orphan objects from 0x0:2931 to 0x0:3009 [ 3641.996590] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 3645.410032] LustreError: 99242:0:(osp_precreate.c:967:osp_precreate_cleanup_orphans()) lustre-OST0001-osc-MDT0000: cannot cleanup orphans: rc = -11 [ 3645.424680] Lustre: lustre-OST0001: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnecting [ 3646.496385] Lustre: lustre-OST0001: deleting orphan objects from 0x0:2898 to 0x0:2913 [ 3649.938482] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3651.487177] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3669.320190] Lustre: DEBUG MARKER: == replay-single test 44a: race in target handle connect ========================================================== 12:04:22 (1776269062) [ 3673.502345] LustreError: 99216:0:(libcfs_fail.h:169:cfs_race()) cfs_race id 701 sleeping [ 3678.688177] LustreError: 99216:0:(libcfs_fail.h:178:cfs_race()) cfs_fail_race id 701 awake: rc=0 [ 3678.702262] Lustre: lustre-MDT0000: Client b58b32dc-84da-45ed-bc78-3c30f08bfd78 (at 192.168.206.51@tcp) reconnecting [ 3678.761496] LustreError: 36350:0:(libcfs_fail.h:180:cfs_race()) cfs_fail_race id 701 waking [ 3680.288184] LustreError: 100381:0:(libcfs_fail.h:169:cfs_race()) cfs_race id 701 sleeping [ 3685.344126] LustreError: 100381:0:(libcfs_fail.h:178:cfs_race()) cfs_fail_race id 701 awake: rc=0 [ 3685.349602] Lustre: lustre-MDT0000: Client b58b32dc-84da-45ed-bc78-3c30f08bfd78 (at 192.168.206.51@tcp) reconnecting [ 3687.076268] LustreError: 99217:0:(libcfs_fail.h:169:cfs_race()) cfs_race id 701 sleeping [ 3692.512641] LustreError: 99217:0:(libcfs_fail.h:178:cfs_race()) cfs_fail_race id 701 awake: rc=0 [ 3692.523159] Lustre: lustre-MDT0000: Client b58b32dc-84da-45ed-bc78-3c30f08bfd78 (at 192.168.206.51@tcp) reconnecting [ 3693.960907] LustreError: 99215:0:(libcfs_fail.h:169:cfs_race()) cfs_race id 701 sleeping [ 3699.168193] LustreError: 99215:0:(libcfs_fail.h:178:cfs_race()) cfs_fail_race id 701 awake: rc=0 [ 3700.989236] LustreError: 100687:0:(libcfs_fail.h:169:cfs_race()) cfs_race id 701 sleeping [ 3706.336185] LustreError: 100687:0:(libcfs_fail.h:178:cfs_race()) cfs_fail_race id 701 awake: rc=0 [ 3706.340159] Lustre: lustre-MDT0000: Client b58b32dc-84da-45ed-bc78-3c30f08bfd78 (at 192.168.206.51@tcp) reconnecting [ 3706.352286] Lustre: Skipped 1 previous similar message [ 3714.379991] LustreError: 99216:0:(libcfs_fail.h:169:cfs_race()) cfs_race id 701 sleeping [ 3714.393477] LustreError: 99216:0:(libcfs_fail.h:169:cfs_race()) Skipped 1 previous similar message [ 3719.648457] LustreError: 99216:0:(libcfs_fail.h:178:cfs_race()) cfs_fail_race id 701 awake: rc=0 [ 3719.660370] LustreError: 99216:0:(libcfs_fail.h:178:cfs_race()) Skipped 1 previous similar message [ 3719.668457] LustreError: 100381:0:(libcfs_fail.h:180:cfs_race()) cfs_fail_race id 701 waking [ 3719.689025] LustreError: 100381:0:(libcfs_fail.h:180:cfs_race()) Skipped 1 previous similar message [ 3726.816248] Lustre: lustre-MDT0000: Client b58b32dc-84da-45ed-bc78-3c30f08bfd78 (at 192.168.206.51@tcp) reconnecting [ 3726.821398] Lustre: Skipped 3 previous similar messages [ 3726.826716] LustreError: 100381:0:(libcfs_fail.h:180:cfs_race()) cfs_fail_race id 701 waking [ 3734.958111] LustreError: 100687:0:(libcfs_fail.h:169:cfs_race()) cfs_race id 701 sleeping [ 3734.966248] LustreError: 100687:0:(libcfs_fail.h:169:cfs_race()) Skipped 2 previous similar messages [ 3740.128737] LustreError: 100687:0:(libcfs_fail.h:178:cfs_race()) cfs_fail_race id 701 awake: rc=0 [ 3740.134526] LustreError: 100687:0:(libcfs_fail.h:178:cfs_race()) Skipped 2 previous similar messages [ 3747.506633] Lustre: DEBUG MARKER: == replay-single test 44b: race in target handle connect ========================================================== 12:05:40 (1776269140) [ 3749.217232] LustreError: 100687:0:(fail.c:138:__cfs_fail_timeout_set()) cfs_fail_timeout id 704 sleeping for 40000ms [ 3755.496645] Lustre: lustre-MDT0000: Export 00000000422ea1f4 already connecting from 192.168.206.51@tcp [ 3757.373793] Lustre: lustre-MDT0000: Export 00000000422ea1f4 already connecting from 192.168.206.51@tcp [ 3759.231583] Lustre: lustre-MDT0000: Export 00000000422ea1f4 already connecting from 192.168.206.51@tcp [ 3762.860096] Lustre: lustre-MDT0000: Export 00000000422ea1f4 already connecting from 192.168.206.51@tcp [ 3762.869436] Lustre: Skipped 2 previous similar messages [ 3768.283088] Lustre: lustre-MDT0000: Export 00000000422ea1f4 already connecting from 192.168.206.51@tcp [ 3768.287254] Lustre: Skipped 3 previous similar messages [ 3773.338364] LustreError: 100687:0:(fail.c:144:__cfs_fail_timeout_set()) cfs_fail_timeout interrupted [ 3773.344997] Lustre: 100687:0:(service.c:2348:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/4s); client may timeout req@000000009495a516 x1862549307400320/t0(0) o38->b58b32dc-84da-45ed-bc78-3c30f08bfd78@192.168.206.51@tcp:0/0 lens 520/416 e 0 to 0 dl 1776269165 ref 1 fl Complete:H/0/0 rc 0/0 job:'lctl.0' [ 3776.002229] Lustre: lustre-MDT0000: Client b58b32dc-84da-45ed-bc78-3c30f08bfd78 (at 192.168.206.51@tcp) reconnecting [ 3776.016701] Lustre: Skipped 4 previous similar messages [ 3777.634919] Lustre: DEBUG MARKER: == replay-single test 44c: race in target handle connect ========================================================== 12:06:10 (1776269170) [ 3780.638200] LustreError: 102892:0:(osd_handler.c:698:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 3780.641125] LustreError: 102892:0:(osd_handler.c:698:osd_ro()) Skipped 6 previous similar messages [ 3781.358783] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3784.544900] Lustre: Failing over lustre-MDT0000 [ 3784.548352] Lustre: Skipped 9 previous similar messages [ 3784.826817] Lustre: server umount lustre-MDT0000 complete [ 3784.832191] Lustre: Skipped 9 previous similar messages [ 3790.989663] LustreError: 166-1: MGC192.168.206.151@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3791.000769] LustreError: Skipped 6 previous similar messages [ 3791.005126] Lustre: Evicted from MGS (at 192.168.206.151@tcp) after server handle changed from 0x8c5ddb93554dcccb to 0x8c5ddb93554dd5df [ 3791.012189] Lustre: Skipped 6 previous similar messages [ 3791.213898] Lustre: *** cfs_fail_loc=712, val=0*** [ 3791.219063] LustreError: 7909:0:(service.c:1226:ptlrpc_check_req()) @@@ Invalid replay without recovery req@00000000773982c6 x1862549315975168/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' [ 3791.249840] LustreError: lustre-OST0000-osc-MDT0000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 3791.412258] LustreError: 103522:0:(mdt_handler.c:7428:mdt_iocontrol()) lustre-MDT0000: Aborting recovery for device [ 3791.423280] LustreError: 103522:0:(ldlm_lib.c:2882:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 3791.434211] Lustre: 103571:0:(ldlm_lib.c:2288:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 3791.441816] Lustre: 103571:0:(ldlm_lib.c:2288:target_recovery_overseer()) Skipped 2 previous similar messages [ 3791.452261] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 3791.545137] Lustre: lustre-OST0001: deleting orphan objects from 0x0:2898 to 0x0:2945 [ 3791.546261] Lustre: lustre-OST0000: deleting orphan objects from 0x0:2931 to 0x0:3041 [ 3795.636112] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 3831.391037] Lustre: lustre-OST0000: deleting orphan objects from 0x0:2931 to 0x0:3073 [ 3831.395487] Lustre: lustre-OST0001: deleting orphan objects from 0x0:2898 to 0x0:2977 [ 3835.384973] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 3845.539575] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3847.585627] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3855.402975] Lustre: DEBUG MARKER: == replay-single test 45: Handle failed close ============ 12:07:28 (1776269248) [ 3855.622278] Lustre: lustre-MDT0000: Client b58b32dc-84da-45ed-bc78-3c30f08bfd78 (at 192.168.206.51@tcp) reconnecting [ 3862.780615] Lustre: DEBUG MARKER: == replay-single test 46: Don't leak file handle after open resend (3325) ========================================================== 12:07:35 (1776269255) [ 3863.659317] Lustre: *** cfs_fail_loc=122, val=2147483648*** [ 3863.661670] LustreError: 104552:0:(ldlm_lib.c:3224:target_send_reply_msg()) @@@ dropping reply req@00000000bf4e5cf5 x1862549307423616/t0(0) o700->b58b32dc-84da-45ed-bc78-3c30f08bfd78@192.168.206.51@tcp:395/0 lens 264/248 e 0 to 0 dl 1776269265 ref 1 fl Interpret:/0/0 rc 0/0 job:'touch.0' [ 3892.212168] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 3892.223327] Lustre: Skipped 5 previous similar messages [ 3892.321919] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 3892.333741] Lustre: Skipped 5 previous similar messages [ 3892.377432] Lustre: lustre-OST0001: deleting orphan objects from 0x0:2979 to 0x0:3009 [ 3892.385987] Lustre: lustre-OST0000: deleting orphan objects from 0x0:3075 to 0x0:3105 [ 3895.722326] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 3904.306699] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3905.626668] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3914.275781] Lustre: DEBUG MARKER: == replay-single test 47: MDS->OSC failure during precreate cleanup (2824) ========================================================== 12:08:27 (1776269307) [ 3917.282016] LustreError: 11-0: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 3917.304471] LustreError: 137-5: lustre-OST0000_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. [ 3917.325569] LustreError: Skipped 3 previous similar messages [ 3937.230396] Lustre: lustre-OST0000: deleting orphan objects from 0x0:3116 to 0x0:3137 [ 3940.525739] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 3950.379117] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 3952.413280] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4025.252357] Lustre: DEBUG MARKER: == replay-single test 48: MDS->OSC failure during precreate cleanup (2824) ========================================================== 12:10:18 (1776269418) [ 4029.589976] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4032.503182] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4061.608898] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4061.613865] Lustre: Skipped 6 previous similar messages [ 4061.662740] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4061.672996] Lustre: Skipped 8 previous similar messages [ 4062.777275] Lustre: lustre-OST0001: deleting orphan objects from 0x0:3030 to 0x0:3073 [ 4062.778127] Lustre: lustre-OST0000: deleting orphan objects from 0x0:3148 to 0x0:3169 [ 4066.512983] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 4134.459193] Lustre: *** cfs_fail_loc=216, val=0*** [ 4139.402842] Lustre: DEBUG MARKER: == replay-single test 50: Double OSC recovery, don't LASSERT (3812) ========================================================== 12:12:12 (1776269532) [ 4141.276789] Lustre: lustre-OST0000: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnecting [ 4141.282595] Lustre: Skipped 2 previous similar messages [ 4141.285995] Lustre: lustre-OST0000: deleting orphan objects from 0x0:3180 to 0x0:3201 [ 4142.083277] Lustre: lustre-OST0000: deleting orphan objects from 0x0:3180 to 0x0:3233 [ 4154.702932] Lustre: DEBUG MARKER: == replay-single test 52: time out lock replay (3764) ==== 12:12:27 (1776269547) [ 4186.608978] Lustre: MGC192.168.206.151@tcp: Connection restored to (at 0@lo) [ 4186.636197] Lustre: Skipped 20 previous similar messages [ 4187.497093] Lustre: *** cfs_fail_loc=157, val=2147483648*** [ 4187.502591] LustreError: 111114:0:(ldlm_lib.c:3224:target_send_reply_msg()) @@@ dropping reply req@000000008aaeac45 x1862549307475968/t0(0) o101->b58b32dc-84da-45ed-bc78-3c30f08bfd78@192.168.206.51@tcp:753/0 lens 328/344 e 0 to 0 dl 1776269623 ref 1 fl Complete:/40/0 rc 0/0 job:'ldlm_lock_repla.0' [ 4192.371788] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 4222.816272] Lustre: 2992:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776269576/real 1776269576] req@0000000010f4fce4 x1862549316028864/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1776269618 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:0.0' [ 4222.851249] Lustre: 2992:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 44 previous similar messages [ 4230.633537] Lustre: lustre-MDT0000: Client b58b32dc-84da-45ed-bc78-3c30f08bfd78 (at 192.168.206.51@tcp) reconnected, waiting for 1 clients in recovery for 0:56 [ 4230.846316] Lustre: lustre-OST0001: deleting orphan objects from 0x0:3084 to 0x0:3105 [ 4230.847240] Lustre: lustre-OST0000: deleting orphan objects from 0x0:3235 to 0x0:3265 [ 4237.335738] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4239.271056] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4249.308093] Lustre: DEBUG MARKER: == replay-single test 53a: |X| close request while two MDC requests in flight ========================================================== 12:14:02 (1776269642) [ 4251.809346] Lustre: *** cfs_fail_loc=115, val=2147483648*** [ 4256.392839] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4292.174477] Lustre: lustre-OST0000: deleting orphan objects from 0x0:3235 to 0x0:3297 [ 4292.179156] Lustre: lustre-OST0001: deleting orphan objects from 0x0:3107 to 0x0:3137 [ 4292.560519] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 4293.099169] Lustre: lustre-MDT0000-lwp-OST0000: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 4293.122037] Lustre: Skipped 16 previous similar messages [ 4303.602504] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4305.714881] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4316.060972] Lustre: DEBUG MARKER: == replay-single test 53b: |X| open request while two MDC requests in flight ========================================================== 12:15:08 (1776269708) [ 4317.832825] Lustre: *** cfs_fail_loc=107, val=2147483648*** [ 4323.581307] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4354.068073] Lustre: lustre-OST0000: deleting orphan objects from 0x0:3235 to 0x0:3329 [ 4354.075161] Lustre: lustre-OST0001: deleting orphan objects from 0x0:3139 to 0x0:3169 [ 4357.532608] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 4369.146198] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4371.754853] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4381.809435] Lustre: DEBUG MARKER: == replay-single test 53c: |X| open request and close request while two MDC requests in flight ========================================================== 12:16:14 (1776269774) [ 4383.590769] Lustre: *** cfs_fail_loc=107, val=2147483648*** [ 4385.824428] Lustre: *** cfs_fail_loc=115, val=2147483648*** [ 4389.154702] LustreError: 115784:0:(osd_handler.c:698:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 4389.159535] LustreError: 115784:0:(osd_handler.c:698:osd_ro()) Skipped 3 previous similar messages [ 4389.931497] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4392.662886] Lustre: Failing over lustre-MDT0000 [ 4392.668736] Lustre: Skipped 7 previous similar messages [ 4392.962292] Lustre: lustre-MDT0000: Not available for connect from 192.168.206.51@tcp (stopping) [ 4392.983323] Lustre: Skipped 1 previous similar message [ 4393.295989] Lustre: server umount lustre-MDT0000 complete [ 4393.303228] Lustre: Skipped 7 previous similar messages [ 4401.056161] LustreError: 166-1: MGC192.168.206.151@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4401.074430] LustreError: Skipped 6 previous similar messages [ 4417.513408] Lustre: Evicted from MGS (at 192.168.206.151@tcp) after server handle changed from 0x8c5ddb93554e094e to 0x8c5ddb93554e0f52 [ 4417.521492] Lustre: Skipped 6 previous similar messages [ 4422.453778] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 4424.770541] Lustre: lustre-OST0000: deleting orphan objects from 0x0:3235 to 0x0:3361 [ 4424.772145] Lustre: lustre-OST0001: deleting orphan objects from 0x0:3171 to 0x0:3201 [ 4435.315963] Lustre: DEBUG MARKER: == replay-single test 53d: close reply while two MDC requests in flight ========================================================== 12:17:07 (1776269827) [ 4437.668854] Lustre: *** cfs_fail_loc=13b, val=315*** [ 4437.670780] Lustre: *** cfs_fail_loc=13b, val=2147483648*** [ 4437.680645] LustreError: 116381:0:(ldlm_lib.c:3224:target_send_reply_msg()) @@@ dropping reply req@000000007e0ed994 x1862549307504320/t261993005073(0) o35->b58b32dc-84da-45ed-bc78-3c30f08bfd78@192.168.206.51@tcp:214/0 lens 392/456 e 0 to 0 dl 1776269839 ref 1 fl Interpret:/0/0 rc 0/0 job:'multiop.0' [ 4472.967512] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 4477.989400] Lustre: 117734:0:(mdt_recovery.c:200:mdt_req_from_lrd()) @@@ restoring transno req@0000000008eacb3a x1862549307504320/t261993005073(0) o35->b58b32dc-84da-45ed-bc78-3c30f08bfd78@192.168.206.51@tcp:254/0 lens 392/456 e 0 to 0 dl 1776269879 ref 1 fl Interpret:/2/0 rc 0/0 job:'multiop.0' [ 4478.006940] Lustre: lustre-OST0000: deleting orphan objects from 0x0:3363 to 0x0:3393 [ 4478.008357] Lustre: lustre-OST0001: deleting orphan objects from 0x0:3171 to 0x0:3233 [ 4484.322818] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4486.049628] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4494.396120] Lustre: DEBUG MARKER: == replay-single test 53e: |X| open reply while two MDC requests in flight ========================================================== 12:18:07 (1776269887) [ 4495.420660] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 4495.429194] LustreError: 118089:0:(ldlm_lib.c:3224:target_send_reply_msg()) @@@ dropping reply req@00000000d782a451 x1862549307511808/t266287972368(0) o36->b58b32dc-84da-45ed-bc78-3c30f08bfd78@192.168.206.51@tcp:306/0 lens 504/448 e 0 to 0 dl 1776269931 ref 1 fl Interpret:/0/0 rc 0/0 job:'mcreate.0' [ 4500.244078] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4530.468543] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4530.483231] Lustre: Skipped 7 previous similar messages [ 4530.556747] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4530.561342] Lustre: Skipped 7 previous similar messages [ 4530.589337] Lustre: 119469:0:(mdt_recovery.c:200:mdt_req_from_lrd()) @@@ restoring transno req@00000000f206e92e x1862549307511808/t266287972368(0) o36->b58b32dc-84da-45ed-bc78-3c30f08bfd78@192.168.206.51@tcp:341/0 lens 504/448 e 0 to 0 dl 1776269966 ref 1 fl Interpret:/2/0 rc 0/0 job:'mcreate.0' [ 4530.609260] Lustre: lustre-OST0000: deleting orphan objects from 0x0:3395 to 0x0:3425 [ 4530.610925] Lustre: lustre-OST0001: deleting orphan objects from 0x0:3171 to 0x0:3265 [ 4533.952199] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 4543.647784] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4545.515587] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4555.043465] Lustre: DEBUG MARKER: == replay-single test 53f: |X| open reply and close reply while two MDC requests in flight ========================================================== 12:19:07 (1776269947) [ 4556.244949] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 4556.249978] LustreError: 119470:0:(ldlm_lib.c:3224:target_send_reply_msg()) @@@ dropping reply req@0000000057bab6b2 x1862549307519936/t270582939664(0) o36->b58b32dc-84da-45ed-bc78-3c30f08bfd78@192.168.206.51@tcp:367/0 lens 504/448 e 0 to 0 dl 1776269992 ref 1 fl Interpret:/0/0 rc 0/0 job:'mcreate.0' [ 4558.301735] Lustre: *** cfs_fail_loc=13b, val=315*** [ 4562.288528] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4598.331541] Lustre: lustre-OST0000: deleting orphan objects from 0x0:3395 to 0x0:3457 [ 4598.333418] Lustre: lustre-OST0001: deleting orphan objects from 0x0:3267 to 0x0:3297 [ 4598.352813] Lustre: 121214:0:(mdt_recovery.c:200:mdt_req_from_lrd()) @@@ restoring transno req@00000000c228b970 x1862549307519936/t270582939664(0) o36->b58b32dc-84da-45ed-bc78-3c30f08bfd78@192.168.206.51@tcp:409/0 lens 504/448 e 0 to 0 dl 1776270034 ref 1 fl Interpret:/2/0 rc 0/0 job:'mcreate.0' [ 4598.402824] Lustre: 121214:0:(mdt_recovery.c:200:mdt_req_from_lrd()) Skipped 1 previous similar message [ 4599.761227] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 4613.085635] Lustre: DEBUG MARKER: == replay-single test 53g: |X| drop open reply and close request while close and open are both in flight ========================================================== 12:20:06 (1776270006) [ 4614.160732] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 4614.172450] Lustre: Skipped 1 previous similar message [ 4614.179480] LustreError: 121214:0:(ldlm_lib.c:3224:target_send_reply_msg()) @@@ dropping reply req@0000000041a460a6 x1862549307527488/t274877906960(0) o36->b58b32dc-84da-45ed-bc78-3c30f08bfd78@192.168.206.51@tcp:425/0 lens 504/448 e 0 to 0 dl 1776270050 ref 1 fl Interpret:/0/0 rc 0/0 job:'mcreate.0' [ 4614.207734] LustreError: 121214:0:(ldlm_lib.c:3224:target_send_reply_msg()) Skipped 1 previous similar message [ 4616.185273] Lustre: *** cfs_fail_loc=115, val=2147483648*** [ 4621.684489] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4623.345433] Lustre: lustre-MDT0000: Client b58b32dc-84da-45ed-bc78-3c30f08bfd78 (at 192.168.206.51@tcp) reconnecting [ 4623.364158] Lustre: Skipped 1 previous similar message [ 4623.390977] Lustre: 121214:0:(mdt_recovery.c:200:mdt_req_from_lrd()) @@@ restoring transno req@00000000e26d1381 x1862549307527488/t274877906960(0) o36->b58b32dc-84da-45ed-bc78-3c30f08bfd78@192.168.206.51@tcp:434/0 lens 504/448 e 0 to 0 dl 1776270059 ref 1 fl Interpret:/2/0 rc 0/0 job:'mcreate.0' [ 4649.099271] Lustre: lustre-OST0001: deleting orphan objects from 0x0:3267 to 0x0:3329 [ 4649.100263] Lustre: lustre-OST0000: deleting orphan objects from 0x0:3459 to 0x0:3489 [ 4650.336382] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 4662.084201] Lustre: DEBUG MARKER: == replay-single test 53h: open request and close reply while two MDC requests in flight ========================================================== 12:20:55 (1776270055) [ 4663.578286] Lustre: *** cfs_fail_loc=107, val=2147483648*** [ 4665.647206] Lustre: *** cfs_fail_loc=13b, val=315*** [ 4665.649340] Lustre: *** cfs_fail_loc=13b, val=2147483648*** [ 4665.659924] LustreError: 122801:0:(ldlm_lib.c:3224:target_send_reply_msg()) @@@ dropping reply req@00000000d4632578 x1862549307534400/t279172874256(0) o35->b58b32dc-84da-45ed-bc78-3c30f08bfd78@192.168.206.51@tcp:442/0 lens 392/456 e 0 to 0 dl 1776270067 ref 1 fl Interpret:/0/0 rc 0/0 job:'multiop.0' [ 4671.076560] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4673.022852] Lustre: 122801:0:(mdt_recovery.c:200:mdt_req_from_lrd()) @@@ restoring transno req@00000000358b2329 x1862549307534400/t279172874256(0) o35->b58b32dc-84da-45ed-bc78-3c30f08bfd78@192.168.206.51@tcp:449/0 lens 392/456 e 0 to 0 dl 1776270074 ref 1 fl Interpret:/2/0 rc 0/0 job:'multiop.0' [ 4700.211080] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4700.219789] Lustre: Skipped 8 previous similar messages [ 4700.340687] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4700.355547] Lustre: Skipped 8 previous similar messages [ 4701.986199] Lustre: lustre-OST0000: deleting orphan objects from 0x0:3459 to 0x0:3521 [ 4701.987805] Lustre: lustre-OST0001: deleting orphan objects from 0x0:3331 to 0x0:3361 [ 4706.308689] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 4717.900026] Lustre: DEBUG MARKER: == replay-single test 55: let MDS_CHECK_RESENT return the original return code instead of 0 ========================================================== 12:21:50 (1776270110) [ 4719.029263] Lustre: *** cfs_fail_loc=12b, val=2147483991*** [ 4719.035551] LustreError: 124313:0:(ldlm_lib.c:3224:target_send_reply_msg()) @@@ dropping reply req@000000007128bb35 x1862549307540480/t283467841549(0) o101->b58b32dc-84da-45ed-bc78-3c30f08bfd78@192.168.206.51@tcp:529/0 lens 664/600 e 0 to 0 dl 1776270154 ref 1 fl Interpret:/0/0 rc 301/0 job:'touch.0' [ 4760.051868] Lustre: 124312:0:(mdt_recovery.c:200:mdt_req_from_lrd()) @@@ restoring transno req@0000000067b8b0d8 x1862549307540480/t283467841549(0) o101->b58b32dc-84da-45ed-bc78-3c30f08bfd78@192.168.206.51@tcp:570/0 lens 664/3424 e 0 to 0 dl 1776270195 ref 1 fl Interpret:/2/0 rc 0/0 job:'touch.0' [ 4766.103851] Lustre: DEBUG MARKER: == replay-single test 56: don't replay a symlink open request (3440) ========================================================== 12:22:39 (1776270159) [ 4769.745612] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4800.486358] Lustre: MGC192.168.206.151@tcp: Connection restored to (at 0@lo) [ 4800.507635] Lustre: Skipped 26 previous similar messages [ 4804.210839] Lustre: lustre-OST0000: deleting orphan objects from 0x0:3459 to 0x0:3553 [ 4804.211191] Lustre: lustre-OST0001: deleting orphan objects from 0x0:3363 to 0x0:3393 [ 4806.100152] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 4816.197676] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4817.757091] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4824.480583] Lustre: 2993:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776270179/real 1776270179] req@0000000025dac11b x1862549316108736/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1776270220 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:0.0' [ 4824.519028] Lustre: 2993:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 135 previous similar messages [ 4835.769890] Lustre: DEBUG MARKER: == replay-single test 57: test recovery from llog for setattr op ========================================================== 12:23:48 (1776270228) [ 4840.532684] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4872.032391] Lustre: lustre-OST0000: deleting orphan objects from 0x0:3555 to 0x0:3585 [ 4872.032437] Lustre: lustre-OST0001: deleting orphan objects from 0x0:3363 to 0x0:3425 [ 4875.056946] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 4882.827215] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4884.050560] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4889.029613] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 4899.053612] Lustre: DEBUG MARKER: == replay-single test 58a: test recovery from llog for setattr op (test llog_gen_rec) ========================================================== 12:24:52 (1776270292) [ 4941.226249] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4973.976338] Lustre: lustre-OST0001: deleting orphan objects from 0x0:4676 to 0x0:4705 [ 4973.976942] Lustre: lustre-OST0000: deleting orphan objects from 0x0:4836 to 0x0:4865 [ 4975.491802] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 4977.124819] 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 [ 4977.136043] Lustre: Skipped 18 previous similar messages [ 4983.107699] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4984.367424] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5057.246892] Lustre: DEBUG MARKER: == replay-single test 58b: test replay of setxattr op ==== 12:27:30 (1776270450) [ 5060.952274] LustreError: 131418:0:(osd_handler.c:698:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 5060.959081] LustreError: 131418:0:(osd_handler.c:698:osd_ro()) Skipped 7 previous similar messages [ 5061.770688] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5063.544438] Lustre: Failing over lustre-MDT0000 [ 5063.549284] Lustre: Skipped 8 previous similar messages [ 5063.927960] Lustre: server umount lustre-MDT0000 complete [ 5063.931805] Lustre: Skipped 8 previous similar messages [ 5071.264302] LustreError: 166-1: MGC192.168.206.151@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5071.274056] LustreError: Skipped 8 previous similar messages [ 5088.739900] Lustre: Evicted from MGS (at 192.168.206.151@tcp) after server handle changed from 0x8c5ddb93554f91fd to 0x8c5ddb93555242ff [ 5088.757103] Lustre: Skipped 8 previous similar messages [ 5089.966925] Lustre: lustre-OST0000: deleting orphan objects from 0x0:4836 to 0x0:4897 [ 5093.761882] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 5103.187276] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 5104.950685] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5113.745659] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount FULL mgc.*.mgs_server_uuid [ 5115.041266] Lustre: DEBUG MARKER: mgc.*.mgs_server_uuid in FULL state after 0 sec [ 5120.071944] Lustre: DEBUG MARKER: == replay-single test 58c: resend/reconstruct setxattr op ========================================================== 12:28:33 (1776270513) [ 5126.541094] Lustre: *** cfs_fail_loc=123, val=2147483648*** [ 5168.637647] Lustre: lustre-MDT0000: Client b58b32dc-84da-45ed-bc78-3c30f08bfd78 (at 192.168.206.51@tcp) reconnecting [ 5168.650971] Lustre: Skipped 2 previous similar messages [ 5170.649950] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 5170.653617] Lustre: Skipped 1 previous similar message [ 5170.660950] LustreError: 132027:0:(ldlm_lib.c:3224:target_send_reply_msg()) @@@ dropping reply req@00000000d8b00b27 x1862549309021760/t300647710728(0) o36->b58b32dc-84da-45ed-bc78-3c30f08bfd78@192.168.206.51@tcp:226/0 lens 66040/440 e 0 to 0 dl 1776270606 ref 1 fl Interpret:/0/0 rc 0/0 job:'setfattr.0' [ 5213.690517] Lustre: 133378:0:(mdt_recovery.c:200:mdt_req_from_lrd()) @@@ restoring transno req@0000000033dc54b4 x1862549309021760/t300647710728(0) o36->b58b32dc-84da-45ed-bc78-3c30f08bfd78@192.168.206.51@tcp:269/0 lens 66040/440 e 0 to 0 dl 1776270649 ref 1 fl Interpret:/2/0 rc 0/0 job:'setfattr.0' [ 5222.019433] Lustre: DEBUG MARKER: SKIP: replay-single test_59 skipping ALWAYS excluded test 59 [ 5223.411907] Lustre: DEBUG MARKER: == replay-single test 60: test llog post recovery init vs llog unlink ========================================================== 12:30:16 (1776270616) [ 5232.288210] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5261.818336] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 5261.826383] Lustre: Skipped 7 previous similar messages [ 5262.920076] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 5262.925826] Lustre: Skipped 7 previous similar messages [ 5262.963125] Lustre: lustre-OST0000: deleting orphan objects from 0x0:5099 to 0x0:5121 [ 5262.963125] Lustre: lustre-OST0001: deleting orphan objects from 0x0:4707 to 0x0:4737 [ 5265.628606] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 5273.823889] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 5275.211908] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5283.782462] Lustre: DEBUG MARKER: == replay-single test 61a: test race llog recovery vs llog cleanup ========================================================== 12:31:17 (1776270677) [ 5300.798548] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 5313.002612] LustreError: 11-0: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 5313.006737] LustreError: 137-5: lustre-OST0000_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. [ 5313.025152] LustreError: Skipped 7 previous similar messages [ 5315.054128] LustreError: 137-5: lustre-OST0000_UUID: not available for connect from 192.168.206.51@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 5320.170249] LustreError: 137-5: lustre-OST0000_UUID: not available for connect from 192.168.206.51@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 5320.179721] LustreError: Skipped 1 previous similar message [ 5328.353064] LustreError: 137-5: lustre-OST0000_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. [ 5328.364468] LustreError: Skipped 2 previous similar messages [ 5328.673396] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 5328.676085] Lustre: Skipped 5 previous similar messages [ 5328.682768] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 5328.690753] Lustre: Skipped 5 previous similar messages [ 5331.356906] Lustre: lustre-OST0000: deleting orphan objects from 0x0:5522 to 0x0:5537 [ 5332.252144] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 5345.795609] LustreError: 137-5: lustre-OST0000_UUID: not available for connect from 192.168.206.51@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 5346.784607] LustreError: 11-0: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 5363.729054] Lustre: lustre-OST0000: deleting orphan objects from 0x0:5522 to 0x0:5569 [ 5364.532091] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 5372.183031] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 5373.459935] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 5411.318413] Lustre: DEBUG MARKER: == replay-single test 61b: test race mds llog sync vs llog cleanup ========================================================== 12:33:24 (1776270804) [ 5425.121389] Lustre: 2991:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776270813/real 1776270813] req@0000000026165676 x1862549316574464/t0(0) o400->MGC192.168.206.151@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1776270820 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:2.0' [ 5425.145460] Lustre: 2991:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 73 previous similar messages [ 5431.268525] Lustre: MGC192.168.206.151@tcp: Connection restored to 192.168.206.151@tcp (at 0@lo) [ 5431.275863] Lustre: Skipped 16 previous similar messages [ 5433.237132] Lustre: lustre-OST0001: deleting orphan objects from 0x0:5138 to 0x0:5153 [ 5433.240394] Lustre: lustre-OST0000: deleting orphan objects from 0x0:5522 to 0x0:5601 [ 5434.682979] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 5468.757974] Lustre: lustre-OST0001: deleting orphan objects from 0x0:5138 to 0x0:5185 [ 5468.758430] Lustre: lustre-OST0000: deleting orphan objects from 0x0:5522 to 0x0:5633 [ 5469.560201] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 5477.174367] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 5478.379461] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5484.622566] Lustre: DEBUG MARKER: == replay-single test 61c: test race mds llog sync vs llog cleanup ========================================================== 12:34:37 (1776270877) [ 5499.377782] LustreError: 137-5: lustre-OST0000_UUID: not available for connect from 192.168.206.51@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 5499.398654] LustreError: Skipped 7 previous similar messages [ 5501.921266] LustreError: 11-0: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 5515.211463] Lustre: lustre-OST0000: deleting orphan objects from 0x0:5635 to 0x0:5665 [ 5515.945620] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 5523.027497] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 5524.359429] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 5531.300653] Lustre: DEBUG MARKER: == replay-single test 61d: error in llog_setup should cleanup the llog context correctly ========================================================== 12:35:24 (1776270924) [ 5539.619368] Lustre: *** cfs_fail_loc=605, val=0*** [ 5539.621281] LustreError: 143104:0:(llog_obd.c:207:llog_setup()) MGS: ctxt 0 lop_setup=0000000042bdcdc5 failed: rc = -95 [ 5539.626864] LustreError: 143104:0:(obd_config.c:774:class_setup()) setup MGS failed (-95) [ 5539.629450] LustreError: 143104:0:(obd_mount.c:200:lustre_start_simple()) MGS setup error -95 [ 5539.636299] LustreError: 143104:0:(obd_mount_server.c:131:server_deregister_mount()) MGS not registered [ 5539.640226] LustreError: 15e-a: Failed to start MGS 'MGS' (-95). Is the 'mgs' module loaded? [ 5539.643889] LustreError: 143104:0:(obd_mount_server.c:1644:server_put_super()) no obd lustre-MDT0000 [ 5539.711201] LustreError: 143104:0:(super25.c:183:lustre_fill_super()) llite: Unable to mount : rc = -95 [ 5547.588783] Lustre: lustre-OST0001: deleting orphan objects from 0x0:5187 to 0x0:5217 [ 5547.590860] Lustre: lustre-OST0000: deleting orphan objects from 0x0:5635 to 0x0:5697 [ 5550.138422] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 5555.768935] Lustre: DEBUG MARKER: == replay-single test 62: don't mis-drop resent replay === 12:35:49 (1776270949) [ 5558.358291] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5587.446231] Lustre: *** cfs_fail_loc=707, val=0*** [ 5589.456807] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 5592.036856] 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 [ 5592.054854] Lustre: Skipped 14 previous similar messages [ 5631.480385] Lustre: lustre-MDT0000: Client b58b32dc-84da-45ed-bc78-3c30f08bfd78 (at 192.168.206.51@tcp) reconnected, waiting for 1 clients in recovery for 0:55 [ 5631.943176] Lustre: lustre-OST0000: deleting orphan objects from 0x0:5711 to 0x0:5729 [ 5631.944287] Lustre: lustre-OST0001: deleting orphan objects from 0x0:5230 to 0x0:5249 [ 5635.983589] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 5637.168279] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5644.623711] Lustre: DEBUG MARKER: == replay-single test 65a: AT: verify early replies ====== 12:37:18 (1776271038) [ 5671.625534] LustreError: 144804:0:(fail.c:138:__cfs_fail_timeout_set()) cfs_fail_timeout id 50a sleeping for 6000ms [ 5677.668114] LustreError: 144804:0:(fail.c:149:__cfs_fail_timeout_set()) cfs_fail_timeout id 50a awake [ 5691.733483] Lustre: DEBUG MARKER: == replay-single test 65b: AT: verify early replies on packed reply / bulk ========================================================== 12:38:05 (1776271085) [ 5718.172155] LustreError: 35186:0:(fail.c:138:__cfs_fail_timeout_set()) cfs_fail_timeout id 224 sleeping for 6000ms [ 5724.208101] LustreError: 35186:0:(fail.c:149:__cfs_fail_timeout_set()) cfs_fail_timeout id 224 awake [ 5730.164316] Lustre: DEBUG MARKER: == replay-single test 66a: AT: verify MDT service time adjusts with no early replies ========================================================== 12:38:43 (1776271123) [ 5755.565215] LustreError: 145260:0:(fail.c:138:__cfs_fail_timeout_set()) cfs_fail_timeout id 50a sleeping for 5000ms [ 5760.664121] LustreError: 145260:0:(fail.c:149:__cfs_fail_timeout_set()) cfs_fail_timeout id 50a awake [ 5761.956369] LustreError: 145260:0:(fail.c:138:__cfs_fail_timeout_set()) cfs_fail_timeout id 50a sleeping for 10000ms [ 5772.048179] LustreError: 145260:0:(fail.c:149:__cfs_fail_timeout_set()) cfs_fail_timeout id 50a awake [ 5786.424191] Lustre: DEBUG MARKER: == replay-single test 66b: AT: verify net latency adjusts ========================================================== 12:39:39 (1776271179) [ 5838.462936] Lustre: DEBUG MARKER: == replay-single test 67a: AT: verify slow request processing doesn't induce reconnects ========================================================== 12:40:32 (1776271232) [ 5863.544609] LustreError: 146309:0:(fail.c:138:__cfs_fail_timeout_set()) cfs_fail_timeout id 50a sleeping for 400ms [ 5863.968116] LustreError: 146309:0:(fail.c:149:__cfs_fail_timeout_set()) cfs_fail_timeout id 50a awake [ 5871.626681] LustreError: 144807:0:(fail.c:138:__cfs_fail_timeout_set()) cfs_fail_timeout id 50a sleeping for 400ms [ 5871.636212] LustreError: 144807:0:(fail.c:138:__cfs_fail_timeout_set()) Skipped 20 previous similar messages [ 5872.056090] LustreError: 144807:0:(fail.c:149:__cfs_fail_timeout_set()) cfs_fail_timeout id 50a awake [ 5872.060902] LustreError: 144807:0:(fail.c:149:__cfs_fail_timeout_set()) Skipped 20 previous similar messages [ 5887.834153] LustreError: 144805:0:(fail.c:138:__cfs_fail_timeout_set()) cfs_fail_timeout id 50a sleeping for 400ms [ 5887.840083] LustreError: 144805:0:(fail.c:138:__cfs_fail_timeout_set()) Skipped 53 previous similar messages [ 5888.264972] LustreError: 144805:0:(fail.c:149:__cfs_fail_timeout_set()) cfs_fail_timeout id 50a awake [ 5888.272596] LustreError: 144805:0:(fail.c:149:__cfs_fail_timeout_set()) Skipped 52 previous similar messages [ 5893.599532] Lustre: DEBUG MARKER: == replay-single test 67b: AT: verify instant slowdown doesn't induce reconnects ========================================================== 12:41:27 (1776271287) [ 5921.250826] Lustre: DEBUG MARKER: phase 2 [ 5926.261387] Lustre: DEBUG MARKER: == replay-single test 68: AT: verify slowing locks ======= 12:41:59 (1776271319) [ 6002.865434] Lustre: DEBUG MARKER: == replay-single test 70a: check multi client t-f ======== 12:43:16 (1776271396) [ 6003.826463] Lustre: DEBUG MARKER: SKIP: replay-single test_70a Need two or more clients, have 1 [ 6004.760744] Lustre: DEBUG MARKER: == replay-single test 70b: dbench 1mdts recovery; 1 clients ========================================================== 12:43:18 (1776271398) [ 6008.593175] Lustre: DEBUG MARKER: Started rundbench load pid=131371 ... [ 6012.139532] LustreError: 151601:0:(osd_handler.c:698:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 6012.146818] LustreError: 151601:0:(osd_handler.c:698:osd_ro()) Skipped 3 previous similar messages [ 6012.882786] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 6015.003671] Lustre: DEBUG MARKER: test_70b fail mds1 1 times [ 6016.100212] Lustre: Failing over lustre-MDT0000 [ 6016.105502] Lustre: Skipped 8 previous similar messages [ 6016.311148] Lustre: server umount lustre-MDT0000 complete [ 6016.313456] Lustre: Skipped 9 previous similar messages [ 6028.192488] Lustre: 2992:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776271417/real 1776271417] req@00000000de995f79 x1862549316670656/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1776271424 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:1.0' [ 6028.194766] LustreError: 166-1: MGC192.168.206.151@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 6028.224117] Lustre: 2992:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 46 previous similar messages [ 6028.232581] LustreError: Skipped 5 previous similar messages [ 6034.351503] Lustre: Evicted from MGS (at 192.168.206.151@tcp) after server handle changed from 0x8c5ddb9355538e52 to 0x8c5ddb935553eaef [ 6034.363880] Lustre: Skipped 5 previous similar messages [ 6034.378660] Lustre: MGC192.168.206.151@tcp: Connection restored to (at 0@lo) [ 6034.387690] Lustre: Skipped 12 previous similar messages [ 6034.981610] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 6034.986532] Lustre: Skipped 6 previous similar messages [ 6035.037234] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 6035.040612] Lustre: Skipped 6 previous similar messages [ 6038.660332] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 6054.251398] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 6054.259549] Lustre: Skipped 7 previous similar messages [ 6054.843838] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 6054.857138] Lustre: Skipped 7 previous similar messages [ 6054.879056] Lustre: lustre-OST0000: deleting orphan objects from 0x0:5833 to 0x0:5857 [ 6054.880077] Lustre: lustre-OST0001: deleting orphan objects from 0x0:5331 to 0x0:5377 [ 6058.834812] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 6060.040971] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6065.363807] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 6067.369765] Lustre: DEBUG MARKER: test_70b fail mds1 2 times [ 6087.882559] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 6097.376951] Lustre: lustre-OST0000: deleting orphan objects from 0x0:5890 to 0x0:5921 [ 6097.377035] Lustre: lustre-OST0001: deleting orphan objects from 0x0:5410 to 0x0:5441 [ 6101.186735] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 6102.243215] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6107.334855] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 6109.228703] Lustre: DEBUG MARKER: test_70b fail mds1 3 times [ 6110.489505] LustreError: 153777:0:(ldlm_lockd.c:1427:ldlm_handle_enqueue0()) ### lock on destroyed export 00000000387f8d86 ns: mdt-lustre-MDT0000_UUID lock: 00000000629c5a70/0x8c5ddb935554b1d5 lrc: 3/0,0 mode: PR/PR res: [0x20001b1b3:0xf96:0x0].0x0 bits 0x1b/0x0 rrc: 2 type: IBT gid 0 flags: 0x50200000000000 nid: 192.168.206.51@tcp remote: 0xff92d39e4df11016 expref: 3 pid: 153777 timeout: 0 lvb_type: 0 [ 6138.666338] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 6139.462703] Lustre: lustre-OST0000: deleting orphan objects from 0x0:5961 to 0x0:5985 [ 6139.465049] Lustre: lustre-OST0001: deleting orphan objects from 0x0:5481 to 0x0:5505 [ 6145.279358] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 6146.250123] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6154.984102] Lustre: DEBUG MARKER: == replay-single test 70c: tar 1mdts recovery ============ 12:45:48 (1776271548) [ 6279.298724] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 6290.458973] Lustre: DEBUG MARKER: test_70c fail mds1 1 times [ 6301.152147] 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 [ 6301.158489] Lustre: Skipped 7 previous similar messages [ 6311.007310] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 6315.743416] Lustre: lustre-OST0001: deleting orphan objects from 0x0:6310 to 0x0:6337 [ 6315.744829] Lustre: lustre-OST0000: deleting orphan objects from 0x0:6791 to 0x0:6817 [ 6319.813464] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 6321.355887] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6447.187989] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 6458.888035] Lustre: DEBUG MARKER: test_70c fail mds1 2 times [ 6460.337267] LustreError: 2993:0:(client.c:1256:ptlrpc_import_delay_req()) @@@ IMP_CLOSED req@00000000f63b5a7f x1862549317356416/t0(0) o2->lustre-OST0000-osc-MDT0000@0@lo:28/4 lens 440/432 e 0 to 0 dl 0 ref 1 fl Rpc:QU/0/ffffffff rc 0/-1 job:'osp-syn-0-0.0' [ 6460.357577] LustreError: 2993:0:(client.c:1256:ptlrpc_import_delay_req()) Skipped 1 previous similar message [ 6478.390943] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 6497.053585] Lustre: lustre-OST0000: deleting orphan objects from 0x0:7639 to 0x0:7681 [ 6497.053595] Lustre: lustre-OST0001: deleting orphan objects from 0x0:7159 to 0x0:7201 [ 6502.794943] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 6504.342508] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6559.152268] Lustre: DEBUG MARKER: == replay-single test 70d: mkdir/rmdir striped dir 1mdts recovery ========================================================== 12:52:32 (1776271952) [ 6560.058841] Lustre: DEBUG MARKER: SKIP: replay-single test_70d needs >= 2 MDTs [ 6561.246378] Lustre: DEBUG MARKER: == replay-single test 70e: rename cross-MDT with random fails ========================================================== 12:52:34 (1776271954) [ 6562.235919] Lustre: DEBUG MARKER: SKIP: replay-single test_70e needs >= 2 MDTs [ 6563.216865] Lustre: DEBUG MARKER: == replay-single test 70f: OSS O_DIRECT recovery with 1 clients ========================================================== 12:52:36 (1776271956) [ 6568.566270] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 6570.336473] Lustre: DEBUG MARKER: test_70f failing OST 1 times [ 6573.541111] LustreError: 137-5: lustre-OST0000_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. [ 6573.556154] LustreError: Skipped 5 previous similar messages [ 6583.778303] LustreError: 137-5: lustre-OST0000_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. [ 6583.789507] LustreError: Skipped 3 previous similar messages [ 6587.731697] Lustre: lustre-OST0000: deleting orphan objects from 0x0:7929 to 0x0:7969 [ 6588.733985] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 6594.961191] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 6596.056257] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 6604.648089] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 6606.668761] Lustre: DEBUG MARKER: test_70f failing OST 2 times [ 6608.353241] LustreError: 11-0: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 6608.362569] LustreError: 137-5: lustre-OST0000_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. [ 6608.373541] LustreError: Skipped 1 previous similar message [ 6624.181717] Lustre: lustre-OST0000: deleting orphan objects from 0x0:7929 to 0x0:8001 [ 6624.464830] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 6629.672134] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 6630.473149] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 6637.627258] Lustre: DEBUG MARKER: == replay-single test 71a: mkdir/rmdir striped dir with 2 mdts recovery ========================================================== 12:53:51 (1776272031) [ 6638.342881] Lustre: DEBUG MARKER: SKIP: replay-single test_71a needs >= 2 MDTs [ 6639.091322] Lustre: DEBUG MARKER: == replay-single test 73a: open(O_CREAT), unlink, replay, reconnect before open replay, close ========================================================== 12:53:52 (1776272032) [ 6640.561243] LustreError: 163373:0:(osd_handler.c:698:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 6640.564584] LustreError: 163373:0:(osd_handler.c:698:osd_ro()) Skipped 6 previous similar messages [ 6640.979231] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 6642.724047] Lustre: Failing over lustre-MDT0000 [ 6642.725984] Lustre: Skipped 6 previous similar messages [ 6642.954672] Lustre: server umount lustre-MDT0000 complete [ 6642.956581] Lustre: Skipped 6 previous similar messages [ 6654.944135] Lustre: 2991:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776272043/real 1776272043] req@00000000dcfd5107 x1862549317570944/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1776272050 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:0.0' [ 6654.944782] LustreError: 166-1: MGC192.168.206.151@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 6654.963453] Lustre: 2991:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 26 previous similar messages [ 6654.976025] LustreError: Skipped 4 previous similar messages [ 6661.089482] Lustre: Evicted from MGS (at 192.168.206.151@tcp) after server handle changed from 0x8c5ddb9355604402 to 0x8c5ddb935563743f [ 6661.094913] Lustre: Skipped 4 previous similar messages [ 6661.101297] Lustre: MGC192.168.206.151@tcp: Connection restored to 192.168.206.151@tcp (at 0@lo) [ 6661.105343] Lustre: Skipped 16 previous similar messages [ 6661.391379] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 6661.395071] Lustre: Skipped 6 previous similar messages [ 6661.431547] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 6661.435407] Lustre: Skipped 6 previous similar messages [ 6663.513337] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 6670.311792] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 6670.318228] Lustre: Skipped 6 previous similar messages [ 6670.325764] Lustre: *** cfs_fail_loc=302, val=2147483648*** [ 6677.492277] Lustre: lustre-MDT0000: Client b58b32dc-84da-45ed-bc78-3c30f08bfd78 (at 192.168.206.51@tcp) reconnected, waiting for 1 clients in recovery for 0:58 [ 6677.558845] Lustre: lustre-MDT0000: Recovery over after 0:07, of 1 clients 1 recovered and 0 were evicted. [ 6677.562708] Lustre: Skipped 6 previous similar messages [ 6677.579155] Lustre: lustre-OST0001: deleting orphan objects from 0x0:7449 to 0x0:7489 [ 6677.579316] Lustre: lustre-OST0000: deleting orphan objects from 0x0:8003 to 0x0:8033 [ 6680.257860] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 6680.979578] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6685.520576] Lustre: DEBUG MARKER: == replay-single test 73b: open(O_CREAT), unlink, replay, reconnect at open_replay reply, close ========================================================== 12:54:39 (1776272079) [ 6687.309543] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 6707.481080] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 6715.377754] Lustre: *** cfs_fail_loc=157, val=2147483648*** [ 6715.380786] LustreError: 165745:0:(ldlm_lib.c:3224:target_send_reply_msg()) @@@ dropping reply req@00000000d6e7db10 x1862549317230528/t347892350979(347892350979) o101->b58b32dc-84da-45ed-bc78-3c30f08bfd78@192.168.206.51@tcp:227/0 lens 592/600 e 0 to 0 dl 1776272117 ref 1 fl Interpret:/4/0 rc 301/0 job:'multiop.0' [ 6722.543163] Lustre: lustre-MDT0000: Client b58b32dc-84da-45ed-bc78-3c30f08bfd78 (at 192.168.206.51@tcp) reconnected, waiting for 1 clients in recovery for 0:58 [ 6722.549962] Lustre: 165743:0:(mdt_recovery.c:200:mdt_req_from_lrd()) @@@ restoring transno req@000000007afc65cf x1862549317230528/t347892350979(347892350979) o101->b58b32dc-84da-45ed-bc78-3c30f08bfd78@192.168.206.51@tcp:234/0 lens 592/3424 e 0 to 0 dl 1776272124 ref 1 fl Interpret:/6/0 rc 0/0 job:'multiop.0' [ 6722.589631] Lustre: lustre-OST0001: deleting orphan objects from 0x0:7491 to 0x0:7521 [ 6722.589650] Lustre: lustre-OST0000: deleting orphan objects from 0x0:8003 to 0x0:8065 [ 6725.006497] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 6725.640756] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6729.596653] Lustre: DEBUG MARKER: == replay-single test 74: Ensure applications don't fail waiting for OST recovery ========================================================== 12:55:23 (1776272123) [ 6731.745340] LustreError: 137-5: lustre-OST0000_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. [ 6731.754697] LustreError: Skipped 6 previous similar messages [ 6749.340124] Lustre: lustre-OST0001: deleting orphan objects from 0x0:7491 to 0x0:7553 [ 6750.963549] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 6754.359501] Lustre: lustre-OST0000: Denying connection for new client 8e57efa2-8298-4177-8376-5d66dd3130b2 (at 192.168.206.51@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:59 [ 6754.367060] Lustre: Skipped 11 previous similar messages [ 6754.489934] Lustre: lustre-OST0000: deleting orphan objects from 0x0:8003 to 0x0:8097 [ 6755.060510] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 6760.570334] Lustre: DEBUG MARKER: == replay-single test 80a: DNE: create remote dir, drop update rep from MDT0, fail MDT0 ========================================================== 12:55:54 (1776272154) [ 6761.178626] Lustre: DEBUG MARKER: SKIP: replay-single test_80a needs >= 2 MDTs [ 6761.830546] Lustre: DEBUG MARKER: == replay-single test 80b: DNE: create remote dir, drop update rep from MDT0, fail MDT1 ========================================================== 12:55:55 (1776272155) [ 6762.434328] Lustre: DEBUG MARKER: SKIP: replay-single test_80b needs >= 2 MDTs [ 6763.109844] Lustre: DEBUG MARKER: == replay-single test 80c: DNE: create remote dir, drop update rep from MDT1, fail MDT[0,1] ========================================================== 12:55:56 (1776272156) [ 6763.732109] Lustre: DEBUG MARKER: SKIP: replay-single test_80c needs >= 2 MDTs [ 6764.431278] Lustre: DEBUG MARKER: == replay-single test 80d: DNE: create remote dir, drop update rep from MDT1, fail 2 MDTs ========================================================== 12:55:58 (1776272158) [ 6765.059508] Lustre: DEBUG MARKER: SKIP: replay-single test_80d needs >= 2 MDTs [ 6765.770748] Lustre: DEBUG MARKER: == replay-single test 80e: DNE: create remote dir, drop MDT1 rep, fail MDT0 ========================================================== 12:55:59 (1776272159) [ 6766.321680] Lustre: DEBUG MARKER: SKIP: replay-single test_80e needs >= 2 MDTs [ 6766.989240] Lustre: DEBUG MARKER: == replay-single test 80f: DNE: create remote dir, drop MDT1 rep, fail MDT1 ========================================================== 12:56:00 (1776272160) [ 6767.627237] Lustre: DEBUG MARKER: SKIP: replay-single test_80f needs >= 2 MDTs [ 6768.289922] Lustre: DEBUG MARKER: == replay-single test 80g: DNE: create remote dir, drop MDT1 rep, fail MDT0, then MDT1 ========================================================== 12:56:02 (1776272162) [ 6768.872862] Lustre: DEBUG MARKER: SKIP: replay-single test_80g needs >= 2 MDTs [ 6769.512569] Lustre: DEBUG MARKER: == replay-single test 80h: DNE: create remote dir, drop MDT1 rep, fail 2 MDTs ========================================================== 12:56:03 (1776272163) [ 6770.094627] Lustre: DEBUG MARKER: SKIP: replay-single test_80h needs >= 2 MDTs [ 6770.775530] Lustre: DEBUG MARKER: == replay-single test 81a: DNE: unlink remote dir, drop MDT0 update rep, fail MDT1 ========================================================== 12:56:04 (1776272164) [ 6771.365935] Lustre: DEBUG MARKER: SKIP: replay-single test_81a needs >= 2 MDTs [ 6772.010817] Lustre: DEBUG MARKER: == replay-single test 81b: DNE: unlink remote dir, drop MDT0 update reply, fail MDT0 ========================================================== 12:56:05 (1776272165) [ 6772.627996] Lustre: DEBUG MARKER: SKIP: replay-single test_81b needs >= 2 MDTs [ 6773.290111] Lustre: DEBUG MARKER: == replay-single test 81c: DNE: unlink remote dir, drop MDT0 update reply, fail MDT0,MDT1 ========================================================== 12:56:07 (1776272167) [ 6773.913159] Lustre: DEBUG MARKER: SKIP: replay-single test_81c needs >= 2 MDTs [ 6774.533716] Lustre: DEBUG MARKER: == replay-single test 81d: DNE: unlink remote dir, drop MDT0 update reply, fail 2 MDTs ========================================================== 12:56:08 (1776272168) [ 6775.121386] Lustre: DEBUG MARKER: SKIP: replay-single test_81d needs >= 2 MDTs [ 6775.751484] Lustre: DEBUG MARKER: == replay-single test 81e: DNE: unlink remote dir, drop MDT1 req reply, fail MDT0 ========================================================== 12:56:09 (1776272169) [ 6776.364470] Lustre: DEBUG MARKER: SKIP: replay-single test_81e needs >= 2 MDTs [ 6776.956127] Lustre: DEBUG MARKER: == replay-single test 81f: DNE: unlink remote dir, drop MDT1 req reply, fail MDT1 ========================================================== 12:56:10 (1776272170) [ 6777.503824] Lustre: DEBUG MARKER: SKIP: replay-single test_81f needs >= 2 MDTs [ 6778.167480] Lustre: DEBUG MARKER: == replay-single test 81g: DNE: unlink remote dir, drop req reply, fail M0, then M1 ========================================================== 12:56:12 (1776272172) [ 6778.759753] Lustre: DEBUG MARKER: SKIP: replay-single test_81g needs >= 2 MDTs [ 6779.481167] Lustre: DEBUG MARKER: == replay-single test 81h: DNE: unlink remote dir, drop request reply, fail 2 MDTs ========================================================== 12:56:13 (1776272173) [ 6780.033403] Lustre: DEBUG MARKER: SKIP: replay-single test_81h needs >= 2 MDTs [ 6780.658466] Lustre: DEBUG MARKER: == replay-single test 84a: stale open during export disconnect ========================================================== 12:56:14 (1776272174) [ 6781.349766] Lustre: 170350:0:(genops.c:1710:obd_export_evict_by_uuid()) lustre-MDT0000: evicting 8e57efa2-8298-4177-8376-5d66dd3130b2 at adminstrative request [ 6785.066431] Lustre: DEBUG MARKER: == replay-single test 85a: check the cancellation of unused locks during recovery(IBITS) ========================================================== 12:56:18 (1776272178) [ 6806.249951] Lustre: lustre-OST0001: deleting orphan objects from 0x0:7605 to 0x0:7649 [ 6806.249955] Lustre: lustre-OST0000: deleting orphan objects from 0x0:8149 to 0x0:8193 [ 6806.507795] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 6810.694961] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 6811.328102] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6814.990964] Lustre: DEBUG MARKER: == replay-single test 85b: check the cancellation of unused locks during recovery(EXTENT) ========================================================== 12:56:48 (1776272208) [ 6820.320917] LustreError: 11-0: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 6820.325277] LustreError: 137-5: lustre-OST0000_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. [ 6820.331807] LustreError: Skipped 2 previous similar messages [ 6833.906163] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 6834.157171] Lustre: lustre-OST0000: deleting orphan objects from 0x0:8294 to 0x0:8321 [ 6837.926591] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 6838.514916] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 6842.484895] Lustre: DEBUG MARKER: == replay-single test 86: umount server after clear nid_stats should not hit LBUG ========================================================== 12:57:16 (1776272236) [ 6846.740503] Lustre: lustre-OST0000: deleting orphan objects from 0x0:8294 to 0x0:8353 [ 6846.740503] Lustre: lustre-OST0001: deleting orphan objects from 0x0:7605 to 0x0:7681 [ 6848.395277] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 6852.078042] Lustre: DEBUG MARKER: == replay-single test 87a: write replay ================== 12:57:25 (1776272245) [ 6853.853673] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 6857.184692] LustreError: 11-0: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 6869.224274] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 6869.319691] Lustre: lustre-OST0000: deleting orphan objects from 0x0:8355 to 0x0:8385 [ 6873.167614] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 6873.806165] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 6877.690216] Lustre: DEBUG MARKER: == replay-single test 87b: write replay with changed data (checksum resend) ========================================================== 12:57:51 (1776272271) [ 6879.438326] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 6895.605295] LustreError: 168-f: lustre-OST0000: BAD WRITE CHECKSUM: from 12345-192.168.206.51@tcp inode [0x200029c11:0x5:0x0] object 0x0:8386 extent [0-1048575]: client csum 2f526991, server csum 201db71b [ 6895.692448] Lustre: lustre-OST0000: deleting orphan objects from 0x0:8387 to 0x0:8417 [ 6895.858703] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 6899.761699] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 6900.318521] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 6903.896044] Lustre: DEBUG MARKER: == replay-single test 88: MDS should not assign same objid to different files ========================================================== 12:58:17 (1776272297) [ 6905.333918] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 6906.664698] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 6910.094536] LustreError: 7840:0:(ldlm_lockd.c:2526:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1776272305 with bad export cookie 10114481763983283348 [ 6917.088161] 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 [ 6917.093896] Lustre: Skipped 18 previous similar messages [ 6944.210187] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 6949.856698] LustreError: 137-5: lustre-OST0000_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. [ 6949.861284] LustreError: Skipped 27 previous similar messages [ 6951.014717] Lustre: lustre-OST0001: deleting orphan objects from 0x0:7605 to 0x0:7713 [ 6957.962349] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 6963.343825] Lustre: DEBUG MARKER: == replay-single test 89: no disk space leak on late ost connection ========================================================== 12:59:17 (1776272357) [ 6973.920322] LustreError: 11-0: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 6992.455378] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 7000.096102] Lustre: lustre-OST0001: deleting orphan objects from 0x0:7605 to 0x0:7745 [ 7003.420862] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 7004.379076] Lustre: lustre-OST0000: Denying connection for new client f9cb9a71-7b73-4939-a7fa-7a0ce45b6a79 (at 192.168.206.51@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 1:08 [ 7025.126840] Lustre: lustre-OST0000: Denying connection for new client f9cb9a71-7b73-4939-a7fa-7a0ce45b6a79 (at 192.168.206.51@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 0:47 [ 7025.133851] Lustre: Skipped 3 previous similar messages [ 7060.966595] Lustre: lustre-OST0000: Denying connection for new client f9cb9a71-7b73-4939-a7fa-7a0ce45b6a79 (at 192.168.206.51@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 0:12 [ 7060.971468] Lustre: Skipped 6 previous similar messages [ 7073.000182] Lustre: lustre-OST0000: recovery is timed out, evict stale exports [ 7073.002820] Lustre: lustre-OST0000: disconnecting 1 stale clients [ 7073.018891] Lustre: lustre-OST0000: deleting orphan objects from 0x0:8468 to 0x0:8489 [ 7077.220066] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 69 sec [ 7087.186504] Lustre: DEBUG MARKER: free_before: 7519232 free_after: 7519232 [ 7089.425182] Lustre: DEBUG MARKER: == replay-single test 90: lfs find identifies the missing striped file segments ========================================================== 13:01:23 (1776272483) [ 7093.728471] LustreError: 11-0: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 7105.312532] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 7105.865259] Lustre: lustre-OST0000: deleting orphan objects from 0x0:8492 to 0x0:8521 [ 7109.294559] Lustre: DEBUG MARKER: == replay-single test 93a: replay + reconnect ============ 13:01:43 (1776272503) [ 7111.137402] LustreError: 11-0: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 7124.531201] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 7125.107648] LustreError: 185172:0:(fail.c:138:__cfs_fail_timeout_set()) cfs_fail_timeout id 715 sleeping for 40000ms [ 7125.110041] LustreError: 185172:0:(fail.c:138:__cfs_fail_timeout_set()) Skipped 2 previous similar messages [ 7125.792098] Lustre: *** cfs_fail_loc=715, val=0*** [ 7131.558472] Lustre: lustre-OST0000: Client f9cb9a71-7b73-4939-a7fa-7a0ce45b6a79 (at 192.168.206.51@tcp) reconnected, waiting for 2 clients in recovery for 0:58 [ 7132.576163] Lustre: *** cfs_fail_loc=715, val=0*** [ 7132.577832] Lustre: Skipped 1 previous similar message [ 7133.600157] Lustre: *** cfs_fail_loc=715, val=0*** [ 7138.791220] Lustre: lustre-OST0000: Client f9cb9a71-7b73-4939-a7fa-7a0ce45b6a79 (at 192.168.206.51@tcp) reconnected, waiting for 2 clients in recovery for 0:51 [ 7138.796273] Lustre: Skipped 1 previous similar message [ 7139.808141] Lustre: *** cfs_fail_loc=715, val=0*** [ 7145.958552] Lustre: lustre-OST0000: Client f9cb9a71-7b73-4939-a7fa-7a0ce45b6a79 (at 192.168.206.51@tcp) reconnected, waiting for 2 clients in recovery for 0:44 [ 7145.962817] Lustre: Skipped 1 previous similar message [ 7146.976133] Lustre: *** cfs_fail_loc=715, val=0*** [ 7146.977858] Lustre: Skipped 1 previous similar message [ 7160.294608] Lustre: lustre-OST0000: Client f9cb9a71-7b73-4939-a7fa-7a0ce45b6a79 (at 192.168.206.51@tcp) reconnected, waiting for 2 clients in recovery for 0:29 [ 7160.298068] Lustre: Skipped 3 previous similar messages [ 7161.312119] Lustre: *** cfs_fail_loc=715, val=0*** [ 7161.313559] Lustre: Skipped 3 previous similar messages [ 7165.152098] LustreError: 185172:0:(fail.c:149:__cfs_fail_timeout_set()) cfs_fail_timeout id 715 awake [ 7165.154485] LustreError: 185172:0:(fail.c:149:__cfs_fail_timeout_set()) Skipped 2 previous similar messages [ 7165.168128] Lustre: lustre-OST0000: deleting orphan objects from 0x0:8523 to 0x0:8553 [ 7167.159429] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 7167.676148] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 7170.924748] Lustre: DEBUG MARKER: == replay-single test 93b: replay + reconnect on mds ===== 13:02:44 (1776272564) [ 7190.009403] LustreError: 186732:0:(fail.c:138:__cfs_fail_timeout_set()) cfs_fail_timeout id 715 sleeping for 80000ms [ 7190.458533] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 7191.072081] Lustre: *** cfs_fail_loc=715, val=0*** [ 7191.073422] Lustre: Skipped 1 previous similar message [ 7197.158501] Lustre: lustre-MDT0000: Client f9cb9a71-7b73-4939-a7fa-7a0ce45b6a79 (at 192.168.206.51@tcp) reconnected, waiting for 1 clients in recovery for 0:58 [ 7197.162067] Lustre: Skipped 1 previous similar message [ 7225.824121] Lustre: *** cfs_fail_loc=715, val=0*** [ 7225.825888] Lustre: Skipped 4 previous similar messages [ 7231.974787] Lustre: lustre-MDT0000: Client f9cb9a71-7b73-4939-a7fa-7a0ce45b6a79 (at 192.168.206.51@tcp) reconnected, waiting for 1 clients in recovery for 0:24 [ 7231.979704] Lustre: Skipped 4 previous similar messages [ 7259.622468] Lustre: lustre-MDT0000: Recovery already passed deadline 0:03. If you do not want to wait more, you may force taget eviction via 'lctl --device lustre-MDT0000 abort_recovery. [ 7266.790543] Lustre: lustre-MDT0000: Recovery already passed deadline 0:10. If you do not want to wait more, you may force taget eviction via 'lctl --device lustre-MDT0000 abort_recovery. [ 7270.096104] LustreError: 186732:0:(fail.c:149:__cfs_fail_timeout_set()) cfs_fail_timeout id 715 awake [ 7270.106908] Lustre: 186732:0:(ldlm_lib.c:2829:target_recovery_thread()) too long recovery - read logs [ 7270.109671] LustreError: dumping log to /tmp/lustre-log.1776272665.186732 [ 7270.147257] Lustre: lustre-OST0000: deleting orphan objects from 0x0:8564 to 0x0:8585 [ 7270.147275] Lustre: lustre-OST0001: deleting orphan objects from 0x0:7758 to 0x0:7777 [ 7272.061543] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 7272.562881] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7275.896471] Lustre: DEBUG MARKER: == replay-single test complete, duration 7090 sec ======== 13:04:29 (1776272669) [ 7277.616030] Lustre: Failing over lustre-MDT0000 [ 7277.617736] Lustre: Skipped 15 previous similar messages [ 7277.871603] Lustre: server umount lustre-MDT0000 complete [ 7277.872888] Lustre: Skipped 15 previous similar messages [ 7288.288138] Lustre: 2991:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776272677/real 1776272677] req@00000000ce0e93b4 x1862549317674368/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1776272684 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:2.0' [ 7288.288218] LustreError: 166-1: MGC192.168.206.151@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 7288.295819] Lustre: 2991:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 39 previous similar messages [ 7288.300210] LustreError: Skipped 7 previous similar messages [ 7294.432724] Lustre: Evicted from MGS (at 192.168.206.151@tcp) after server handle changed from 0x8c5ddb93556406c8 to 0x8c5ddb93556443d7 [ 7294.436752] Lustre: Skipped 7 previous similar messages [ 7294.438936] Lustre: MGC192.168.206.151@tcp: Connection restored to (at 0@lo) [ 7294.440659] Lustre: Skipped 28 previous similar messages [ 7294.627656] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 7294.631520] Lustre: Skipped 15 previous similar messages [ 7294.669111] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 7294.672079] Lustre: Skipped 13 previous similar messages [ 7295.463622] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 7295.467121] Lustre: Skipped 13 previous similar messages [ 7295.479794] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 7295.482124] Lustre: Skipped 13 previous similar messages [ 7295.496970] Lustre: lustre-OST0000: deleting orphan objects from 0x0:8564 to 0x0:8617 [ 7295.497374] Lustre: lustre-OST0001: deleting orphan objects from 0x0:7758 to 0x0:7809 [ 7295.948423] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all 8 [ 7299.559533] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 7300.064798] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7305.184795] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 7305.184795] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 7309.655781] LustreError: 7840:0:(ldlm_lockd.c:2526:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1776272705 with bad export cookie 10114481763983311831 [ 7309.659720] LustreError: 7840:0:(ldlm_lockd.c:2526:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 7315.456072] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing unload_modules_local [ 7316.350384] Key type lgssc unregistered [ 7316.447248] LNet: 189970:0:(lib-ptl.c:992:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 7316.450093] LNet: Removed LNI 192.168.206.151@tcp [ 7316.676483] Key type .llcrypt unregistered [ 7316.678100] Key type ._llcrypt unregistered