[ 0.000000] Linux version 4.18.0rh8.10-debug (green@maintenance) (gcc version 8.5.0 20210514 (Red Hat 8.5.0-26) (GCC)) #2 SMP Mon Jul 14 01:24:22 EDT 2025 [ 0.000000] Command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers' [ 0.000000] x86/fpu: xstate_offset[2]: 576, xstate_sizes[2]: 256 [ 0.000000] x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'standard' format. [ 0.000000] signal: max sigframe size: 1776 [ 0.000000] BIOS-provided physical RAM map: [ 0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable [ 0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000000100000-0x00000000bffcdfff] usable [ 0.000000] BIOS-e820: [mem 0x00000000bffce000-0x00000000bfffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000100000000-0x0000000146dfffff] usable [ 0.000000] NX (Execute Disable) protection: active [ 0.000000] SMBIOS 2.8 present. [ 0.000000] DMI: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.17.0-10.fc44 06/10/2025 [ 0.000000] Hypervisor detected: KVM [ 0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00 [ 0.000000] kvm-clock: using sched offset of 496077769 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 0x00000000BFFE247C 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE2318 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 0022D8 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE238C 000090 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE241C 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE2454 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe2318-0xbffe238b] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe2317] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe238c-0xbffe241b] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe241c-0xbffe2453] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe2454-0xbffe247b] [ 0.000000] No NUMA configuration found [ 0.000000] Faking a node at [mem 0x0000000000000000-0x0000000146dfffff] [ 0.000000] NODE_DATA(0) allocated [mem 0x1465a3000-0x1465cdfff] [ 0.000000] Reserving 256MB of memory at 2752MB for crashkernel (System RAM: 4205MB) [ 0.000000] Zone ranges: [ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.000000] DMA32 [mem 0x0000000001000000-0x00000000ffffffff] [ 0.000000] Normal [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Device empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff] [ 0.000000] node 0: [mem 0x0000000000100000-0x00000000bffcdfff] [ 0.000000] node 0: [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Zeroed struct page in unavailable ranges: 4756 pages [ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x0000000146dfffff] [ 0.000000] ACPI: PM-Timer IO Port: 0x608 [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) [ 0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) [ 0.000000] Using ACPI (MADT) for SMP configuration information [ 0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000] TSC deadline timer available [ 0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs [ 0.000000] kvm-guest: KVM setup pv remote TLB flush [ 0.000000] kvm-guest: setup PV sched yield [ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff] [ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff] [ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff] [ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff] [ 0.000000] PM: Registered nosave memory: [mem 0xbffce000-0xbfffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xc0000000-0xfeffbfff] [ 0.000000] PM: Registered nosave memory: [mem 0xfeffc000-0xfeffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xff000000-0xfffbffff] [ 0.000000] PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff] [ 0.000000] [mem 0xc0000000-0xfeffbfff] available for PCI devices [ 0.000000] Booting paravirtualized kernel on KVM [ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns [ 0.000000] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1 [ 0.000000] percpu: Embedded 63 pages/cpu s221184 r8192 d28672 u524288 [ 0.000000] kvm-guest: PV spinlocks enabled [ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1059606 [ 0.000000] Policy zone: Normal [ 0.000000] Kernel command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] Specific versions of hardware are certified with Red Hat Enterprise Linux 8. Please see the list of hardware certified with Red Hat Enterprise Linux 8 at https://catalog.redhat.com. [ 0.000000] audit: disabled (until reboot) [ 0.000000] software IO TLB: area num 4. [ 0.000000] Memory: 2829652K/4306352K available (18435K kernel code, 11221K rwdata, 7248K rodata, 2908K init, 18040K bss, 524576K 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.001014] APIC: Switch to symmetric I/O mode setup [ 0.003131] x2apic enabled [ 0.004009] Switched APIC routing to physical x2apic. [ 0.005015] kvm-guest: setup PV IPIs [ 0.008000] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.008000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.008027] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.009022] pid_max: default: 32768 minimum: 301 [ 0.011081] LSM: Security Framework initializing [ 0.012061] Yama: becoming mindful. [ 0.013052] SELinux: Initializing. [ 0.014083] *** VALIDATE selinux *** [ 0.023143] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.028485] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.030152] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.031143] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.033136] *** VALIDATE tmpfs *** [ 0.034515] *** VALIDATE proc *** [ 0.035296] *** VALIDATE cgroup *** [ 0.036012] *** VALIDATE cgroup2 *** [ 0.037299] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.038112] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.039005] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.040028] Spectre V2 : User space: Vulnerable [ 0.041009] Speculative Store Bypass: Vulnerable [ 0.044198] debug: unmapping init [mem 0xffffffffa7e59000-0xffffffffa7e60fff] [ 0.046159] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.047673] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.048019] ... version: 2 [ 0.048913] ... bit width: 48 [ 0.049012] ... generic registers: 4 [ 0.049749] ... value mask: 0000ffffffffffff [ 0.050010] ... max period: 00007fffffffffff [ 0.050880] ... fixed-purpose events: 3 [ 0.051011] ... event mask: 000000070000000f [ 0.052238] rcu: Hierarchical SRCU implementation. [ 0.054207] smp: Bringing up secondary CPUs ... [ 0.055473] x86: Booting SMP configuration: [ 0.056024] .... node #0, CPUs: #1 #2 #3 [ 0.058892] smp: Brought up 1 node, 4 CPUs [ 0.059909] smpboot: Max logical packages: 1 [ 0.060012] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.149861] node 0 deferred pages initialised in 86ms [ 0.153008] devtmpfs: initialized [ 0.154217] x86/mm: Memory block size: 128MB [ 0.156865] gcov: version magic: 0x41383552 [ 0.158164] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.159081] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.160311] pinctrl core: initialized pinctrl subsystem [ 0.161282] [ 0.161885] ************************************************************* [ 0.162020] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.163016] ** ** [ 0.164014] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.165018] ** ** [ 0.166015] ** This means that this kernel is built to expose internal ** [ 0.167009] ** IOMMU data structures, which may compromise security on ** [ 0.168008] ** your system. ** [ 0.169009] ** ** [ 0.170007] ** If you see this message and you are not debugging the ** [ 0.171008] ** kernel, report this immediately to your vendor! ** [ 0.172016] ** ** [ 0.173016] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.174013] ************************************************************* [ 0.175672] NET: Registered protocol family 16 [ 0.176329] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.177057] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.178042] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.180011] cpuidle: using governor menu [ 0.181716] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.184479] PCI: Using configuration type 1 for base access [ 0.186134] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.195128] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.198064] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.202106] cryptd: max_cpu_qlen set to 1000 [ 0.205192] ACPI: Added _OSI(Module Device) [ 0.206013] ACPI: Added _OSI(Processor Device) [ 0.207013] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.208015] ACPI: Added _OSI(Processor Aggregator Device) [ 0.212103] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.215110] ACPI: Interpreter enabled [ 0.216079] ACPI: PM: (supports S0 S3 S4 S5) [ 0.217000] ACPI: Using IOAPIC for interrupt routing [ 0.217000] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.221420] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.232291] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.236047] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.238022] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.242086] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.247364] acpiphp: Slot [2] registered [ 0.249123] acpiphp: Slot [5] registered [ 0.250120] acpiphp: Slot [6] registered [ 0.252118] acpiphp: Slot [7] registered [ 0.253110] acpiphp: Slot [8] registered [ 0.255194] acpiphp: Slot [9] registered [ 0.256128] acpiphp: Slot [10] registered [ 0.258115] acpiphp: Slot [3] registered [ 0.260101] acpiphp: Slot [4] registered [ 0.261101] acpiphp: Slot [11] registered [ 0.263117] acpiphp: Slot [12] registered [ 0.264072] acpiphp: Slot [13] registered [ 0.265131] acpiphp: Slot [14] registered [ 0.267128] acpiphp: Slot [15] registered [ 0.268106] acpiphp: Slot [16] registered [ 0.270107] acpiphp: Slot [17] registered [ 0.271094] acpiphp: Slot [18] registered [ 0.273101] acpiphp: Slot [19] registered [ 0.274138] acpiphp: Slot [20] registered [ 0.276108] acpiphp: Slot [21] registered [ 0.277099] acpiphp: Slot [22] registered [ 0.279106] acpiphp: Slot [23] registered [ 0.280097] acpiphp: Slot [24] registered [ 0.281249] acpiphp: Slot [25] registered [ 0.283124] acpiphp: Slot [26] registered [ 0.285127] acpiphp: Slot [27] registered [ 0.287171] acpiphp: Slot [28] registered [ 0.289114] acpiphp: Slot [29] registered [ 0.290116] acpiphp: Slot [30] registered [ 0.292144] acpiphp: Slot [31] registered [ 0.293085] PCI host bridge to bus 0000:00 [ 0.294018] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.296025] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.298027] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.301026] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.303026] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.306026] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.308256] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.311142] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.313645] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.328024] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.333009] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.335019] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.336015] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.338028] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.339987] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.343846] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.346047] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.349646] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.356020] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.369022] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.375019] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.382092] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.390031] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.396022] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.424026] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.439680] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.448019] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.462017] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.478023] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.496212] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.506029] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.513025] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.536028] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.547871] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.555023] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.566021] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.583032] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.596021] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.606032] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.617029] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.637032] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 0.648316] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.660026] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.668028] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.683022] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 0.699287] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.702517] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.706487] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.710450] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.712335] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.720239] iommu: Default domain type: Passthrough [ 0.721523] SCSI subsystem initialized [ 0.722000] ACPI: bus type USB registered [ 0.724213] usbcore: registered new interface driver usbfs [ 0.727100] usbcore: registered new interface driver hub [ 0.729134] usbcore: registered new device driver usb [ 0.731198] pps_core: LinuxPPS API ver. 1 registered [ 0.733014] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.736084] PTP clock support registered [ 0.738142] EDAC MC: Ver: 3.0.0 [ 0.740223] PCI: Using ACPI for IRQ routing [ 0.743097] NetLabel: Initializing [ 0.745025] NetLabel: domain hash size = 128 [ 0.746015] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.748111] NetLabel: unlabeled traffic allowed by default [ 0.750179] vgaarb: loaded [ 0.752399] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.754016] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.761423] clocksource: Switched to clocksource kvm-clock [ 0.876468] VFS: Disk quotas dquot_6.6.0 [ 0.878244] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.881180] *** VALIDATE ramfs *** [ 0.882556] *** VALIDATE hugetlbfs *** [ 0.884320] pnp: PnP ACPI init [ 0.886725] pnp: PnP ACPI: found 6 devices [ 0.905152] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.908831] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.911196] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.913559] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.916323] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.919031] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.922104] NET: Registered protocol family 2 [ 0.924744] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.930516] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.933557] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.938565] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.942872] TCP: Hash tables configured (established 65536 bind 65536) [ 0.945596] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.948363] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.951054] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.953433] NET: Registered protocol family 1 [ 0.955569] RPC: Registered named UNIX socket transport module. [ 0.957276] RPC: Registered udp transport module. [ 0.958274] RPC: Registered tcp transport module. [ 0.959342] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.961438] NET: Registered protocol family 44 [ 0.963534] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.966211] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.968758] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.971366] PCI: CLS 0 bytes, default 64 [ 0.973477] Unpacking initramfs... [ 2.174583] debug: unmapping init [mem 0xffff9b387cc54000-0xffff9b387ffbffff] [ 2.181552] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.184138] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.188685] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 2.705326] Initialise system trusted keyrings [ 2.706742] Key type blacklist registered [ 2.708470] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.716130] zbud: loaded [ 2.719266] *** VALIDATE nfs *** [ 2.720547] *** VALIDATE nfs4 *** [ 2.722229] pstore: using deflate compression [ 2.726399] Platform Keyring initialized [ 2.832297] NET: Registered protocol family 38 [ 2.833601] Key type asymmetric registered [ 2.834616] Asymmetric key parser 'x509' registered [ 2.836037] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 2.839188] io scheduler mq-deadline registered [ 2.841313] io scheduler kyber registered [ 2.843230] io scheduler bfq registered [ 2.845377] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 2.848305] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 2.851427] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 2.854511] ACPI: Power Button [PWRF] [ 2.860001] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 2.868370] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 2.905321] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 2.913216] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 2.932923] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 2.963699] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 2.994836] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.000609] Non-volatile memory driver v1.3 [ 3.002405] Linux agpgart interface v0.103 [ 3.038306] virtio_blk virtio1: [vda] 145904 512-byte logical blocks (74.7 MB/71.2 MiB) [ 3.041170] vda: detected capacity change from 0 to 74702848 [ 3.065319] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.067658] vdb: detected capacity change from 0 to 1073741824 [ 3.080548] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.082704] vdc: detected capacity change from 0 to 2621440000 [ 3.095129] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.097285] vdd: detected capacity change from 0 to 2621440000 [ 3.109208] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.112215] vde: detected capacity change from 0 to 4294967296 [ 3.127285] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.128931] vdf: detected capacity change from 0 to 4294967296 [ 3.133212] libphy: Fixed MDIO Bus: probed [ 3.141206] usbcore: registered new interface driver usbserial_generic [ 3.143354] usbserial: USB Serial support registered for generic [ 3.145411] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.149437] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.151040] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.152656] mousedev: PS/2 mouse device common for all mice [ 3.155316] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.158893] rtc_cmos 00:05: RTC can wake from S4 [ 3.162450] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.164661] rtc_cmos 00:05: registered as rtc0 [ 3.168350] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.168825] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.173858] intel_pstate: CPU model not supported [ 3.177499] hid: raw HID events driver (C) Jiri Kosina [ 3.179878] usbcore: registered new interface driver usbhid [ 3.181963] usbhid: USB HID core driver [ 3.183720] drop_monitor: Initializing network drop monitor service [ 3.186274] Initializing XFRM netlink socket [ 3.188450] NET: Registered protocol family 10 [ 3.191825] Segment Routing with IPv6 [ 3.193464] NET: Registered protocol family 17 [ 3.195518] mpls_gso: MPLS GSO support [ 3.201656] RAS: Correctable Errors collector initialized. [ 3.204337] AVX version of gcm_enc/dec engaged. [ 3.206289] AES CTR mode by8 optimization enabled [ 3.282655] sched_clock: Marking stable (3282606295, 0)->(4182147464, -899541169) [ 3.286384] registered taskstats version 1 [ 3.288170] Loading compiled-in X.509 certificates [ 3.290379] zswap: loaded using pool lzo/zbud [ 3.313961] Key type big_key registered [ 3.326072] Key type encrypted registered [ 3.327386] ima: No TPM chip found, activating TPM-bypass! [ 3.328960] ima: Allocated hash algorithm: sha1 [ 3.330210] ima: No architecture policies found [ 3.331540] evm: Initialising EVM extended attributes: [ 3.333138] evm: security.selinux [ 3.334234] evm: security.ima [ 3.335048] evm: security.capability [ 3.336620] evm: HMAC attrs: 0x1 [ 3.338709] rtc_cmos 00:05: setting system clock to 2026-08-13 13:29:14 UTC (1786627754) [ 3.344804] debug: unmapping init [mem 0xffffffffa8e03000-0xffffffffa8ffffff] [ 3.347794] debug: unmapping init [mem 0xffffffffa7b82000-0xffffffffa7e58fff] [ 3.355116] Write protecting the kernel read-only data: 28672k [ 3.357451] debug: unmapping init [mem 0xffffffffa6203000-0xffffffffa63fffff] [ 3.359324] debug: unmapping init [mem 0xffffffffa6b14000-0xffffffffa6bfffff] [ 3.388148] 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.394140] systemd[1]: Detected virtualization kvm. [ 3.395822] systemd[1]: Detected architecture x86-64. [ 3.397370] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.425592] systemd[1]: No hostname configured. [ 3.426804] systemd[1]: Set hostname to . [ 3.428234] random: systemd: uninitialized urandom read (16 bytes read) [ 3.430895] systemd[1]: Initializing machine ID from random generator. [ 3.565247] random: systemd: uninitialized urandom read (16 bytes read) [ 3.568574] systemd[1]: Listening on Journal Socket. [ OK ] Listening on Journal Socket. [ 3.572784] random: systemd: uninitialized urandom read (16 bytes read) [ 3.575247] systemd[1]: Reached target Swap. [ OK ] Reached target Swap. [ 3.579653] systemd[1]: Listening on Journal Socket (/dev/log). [ OK ] Listening on Journal Socket (/dev/log). Starting Journal Service... [ OK ] Reached target Slices. [ OK ] Reached target Local File Systems. [ OK ] Listening on udev Kernel Socket. Starting Apply Kernel Variables... Starting Create list of required st…ce nodes for the current kernel... Starting Create Volatile Files and Directories... [ OK ] Listening on udev Control Socket. [ OK ] Reached target Timers. [ OK ] Started Memstrack Anylazing Service. Starting Setup Virtual Console... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Paths. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Initrd Root Device. [ OK ] Reached target Sockets. [ OK ] Started Apply Kernel Variables. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Setup Virtual Console. [ OK ] Started Journal Service. Starting dracut cmdline hook... Starting Create Static Device Nodes in /dev... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 4.201802] device-mapper: uevent: version 1.0.3 [ 4.205710] device-mapper: ioctl: 4.46.0-ioctl (2022-02-22) initialised: dm-devel@redhat.com [ OK ] Started dracut pre-udev hook. Starting udev Kernel Device Manager... [ OK ] Started udev Kernel Device Manager. Starting dracut pre-trigger hook... [ OK ] Started dracut pre-trigger hook. Starting udev Coldplug all Devices... Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. Starting dracut initqueue hook... [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ 5.031918] virtio_net virtio0 ens2: renamed from eth0 [ 5.050397] random: fast init done [ 5.094256] scsi host0: ata_piix [ 5.113795] scsi host1: ata_piix [ 5.119493] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 5.122669] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 8.883742] dracut-initqueue[582]: RTNETLINK answers: File exists [ 9.846445] random: crng init done [ 9.848041] 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.351229] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped target Timers. [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Slices. [ OK ] Stopped target Sockets. [ OK ] Stopped target Paths. [ OK ] Stopped target System Initialization. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped target Swap. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. Stopping udev Kernel Device Manager... [ 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.543591] printk: systemd: 23 output lines suppressed due to ratelimiting [ 11.816522] SELinux: Disabled at runtime. [ 11.912963] 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) [ 11.931149] systemd[1]: Detected virtualization kvm. [ 11.937478] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 14.222812] systemd[1]: initrd-switch-root.service: Succeeded. [ 14.229336] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 14.288460] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 14.306948] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 14.321112] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 14.343564] systemd[1]: Starting Journal Service... Starting Journal Service... [ 14.358070] systemd[1]: proc-sys-fs-binfmt_misc.automount: Refusing to start, unit to trigger not loaded. [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Reached target rpc_pipefs.target. [ OK ] Created slice User and Session Slice. [ OK ] Started Dispatch Password Requests to Console Directory Watch. Starting Remount Root and Kernel File Systems... [ OK ] Listening on udev Kernel Socket. [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Stopped target Switch Root. Mounting Huge Pages File System... Starting Apply Kernel Variables... Mounting Kernel Debug File System... Starting Create list of required st…ce nodes for the current kernel... [ OK ] Stopped target Initrd File Systems. [ OK ] Listening on udev Control Socket. [ OK ] Reached target Slices. [ OK ] Stopped target Initrd Root File System. [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Created slice system-getty.slice. [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Listening on Process Core Dump Socket. Mounting POSIX Message Queue File System... Starting udev Coldplug all Devices... [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Reached target RPC Port Mapper. Activating swap /dev/disk/by-label/SWAP... [ OK ] Started Journal Service. [ 15.368078] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Mounted Huge Pages File System. [ OK ] Started Apply Kernel Variables. [ OK ] Mounted Kernel Debug File System. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Reached target Swap. Starting Configure read-only root support... Starting Create Static Device Nodes in /dev... Starting Flush Journal to Persistent Storage... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started udev Coldplug all Devices. [ OK ] Started Create Static Device Nodes in /dev. Starting udev Kernel Device Manager... [ OK ] Reached target Local File Systems (Pre). Mounting /home/green/git/lustre-release... Mounting /mnt... [ OK ] Mounted /mnt. [ 16.406063] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 17.746859] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 17.801163] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 18.479026] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 18.573949] EDAC sbridge: Ver: 1.1.2 [* ] A start job is running for Configur…-only root support (8s / no limit) [** ] A start job is running for Configur…-only root support (8s / no limit) [*** ] A start job is running for Configur…-only root support (9s / no limit) [ *** ] A start job is running for Configur…-only root support (9s / no limit) [ *** ] A start job is running for Configur…only root support (10s / no limit) [ ***] A start job is running for Configur…only root support (10s / no limit)[ 25.367809] Key type dns_resolver registered [ **] A start job is running for Configur…only root support (11s / no limit) [ *] A start job is running for Configur…only root support (12s / no limit)[ 26.241437] NFS: Registering the id_resolver key type [ 26.244231] Key type id_resolver registered [ 26.246516] Key type id_legacy registered [ **] A start job is running for Configur…only root support (12s / no limit) [ OK ] Started Configure read-only root support. Starting Load/Save Random Seed... [ OK ] Reached target Local File Systems. Starting Rebuild Dynamic Linker Cache... Starting Mark the need to relabel after reboot... Starting Create Volatile Files and Directories... [ OK ] Started Load/Save Random Seed. [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Create Volatile Files and Directories. Starting RPC Bind... Starting Update UTMP about System Boot/Shutdown... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Started dnf makecache --timer. [ OK ] Reached target Timers. [ OK ] Reached target Basic System. [ OK ] Started irqbalance daemon. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting Restore /run/initramfs on shutdown... [ OK ] Started D-Bus System Message Bus. Starting Network Manager... Starting Login Service... [ OK ] Reached target sshd-keygen.target. [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Network Manager. Starting Network Manager Wait Online... [ OK ] Reached target Network. Starting OpenSSH server daemon... Starting GSSAPI Proxy Daemon... Starting Dynamic System Tuning Daemon... Starting Hostname Service... [ OK ] Started Login Service. [ OK ] Started OpenSSH server daemon. [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... [ OK ] Started Permit User Sessions. [ OK ] Started Serial Getty on ttyS1. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Command Scheduler. [ OK ] Started Getty on tty1. [ OK ] Reached target Login Prompts. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting Notify NFS peers of a restart... Starting Crash recovery kernel arming... Starting System Logging Service... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg237-server login: [ 73.083501] spl: loading out-of-tree module taints kernel. [ 78.568175] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 93.792355] Key type ._llcrypt registered [ 93.794314] Key type .llcrypt registered [ 93.857922] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_hostid [ 119.580716] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing load_modules_local [ 121.734736] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 121.746116] alg: No test for adler32 (adler32-zlib) [ 123.790864] Lustre: Lustre: Build Version: 2.17.57_1_gb6c95b3 [ 125.051417] LNet: Added LNI 192.168.202.137@tcp [8/256/0/180] [ 126.855163] Key type lgssc registered [ 129.165278] Lustre: Echo OBD driver; http://www.lustre.org/ [ 140.930588] vdc: vdc1 vdc9 [ 140.942813] vdc: vdc1 vdc9 [ 151.342382] vde: vde1 vde9 [ 151.380053] vde: vde1 vde9 [ 163.791669] vdf: vdf1 vdf9 [ 172.685706] hrtimer: interrupt took 7598647 ns [ 185.585701] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing load_modules_local [ 197.155698] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 198.698157] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 199.180356] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 199.433772] Lustre: lustre-MDT0000: new disk, initializing [ 200.260790] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 200.314263] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 206.414577] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 213.212929] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 221.224173] Lustre: lustre-OST0000: new disk, initializing [ 221.230526] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 221.235829] Lustre: Skipped 1 previous similar message [ 221.383583] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 229.111317] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 231.266042] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:0:ost [ 231.283334] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:0:ost] [ 231.400559] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x240000400 [ 242.756120] Lustre: lustre-OST0001: new disk, initializing [ 242.769233] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 242.960490] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 249.078924] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:1:ost [ 249.088216] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:1:ost] [ 249.235816] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x280000400 [ 249.670976] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 264.151552] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 273.052990] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 279.555972] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing check_logdir /tmp/testlogs/ [ 285.019643] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing yml_node [ 290.549908] Lustre: DEBUG MARKER: Client: 2.17.57.1 [ 294.750769] Lustre: DEBUG MARKER: MDS: 2.17.57.1 [ 298.491806] Lustre: DEBUG MARKER: OSS: 2.17.57.1 [ 301.213522] Lustre: DEBUG MARKER: -----============= acceptance-small: replay-single ============----- Thu Aug 13 09:34:10 EDT 2026 [ 321.833308] Lustre: DEBUG MARKER: excepting tests: 59 36 [ 325.025219] Lustre: DEBUG MARKER: === replay-single: start setup 09:34:33 (1786628073) === [ 334.705853] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing check_config_client /mnt/lustre [ 356.411752] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 361.033694] Lustre: 11320:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 365.744580] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 369.177437] Lustre: DEBUG MARKER: === replay-single: finish setup 09:35:19 (1786628119) === [ 370.676108] Lustre: DEBUG MARKER: == replay-single test 0a: empty replay =================== 09:35:20 (1786628120) [ 374.610894] LustreError: 11815:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 375.586716] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 377.857031] Lustre: Failing over lustre-MDT0000 [ 378.278073] Lustre: server umount lustre-MDT0000 complete [ 396.266933] Lustre: 3309:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786628131/real 1786628131] req@ffff9b39003c7480 x1873415111764608/t0(0) o400->MGC192.168.202.137@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1786628147 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 396.269231] 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 [ 396.305900] Lustre: 3309:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 396.305983] LustreError: MGC192.168.202.137@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 396.371601] Lustre: Skipped 1 previous similar message [ 401.439251] Lustre: 3309:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786628136/real 1786628136] req@ffff9b38d23b8000 x1873415111765120/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786628152 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 401.477977] Lustre: 3309:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 405.983239] Lustre: 3307:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786628141/real 1786628141] req@ffff9b39003c7b80 x1873415111765504/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786628157 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 405.989980] LustreError: 3305:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9b38ffa5b100 x1873415111766656/t0(0) o250->MGC192.168.202.137@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 0 ref 1 fl Rpc:NQU/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 406.015069] Lustre: 3307:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 406.524545] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 407.231454] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 407.327138] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 411.197447] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 411.428982] Lustre: 3306:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786628146/real 1786628146] req@ffff9b39003c5180 x1873415111766016/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786628162 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 411.484703] Lustre: 3306:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 420.711657] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 421.672220] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 423.392230] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 434.186844] Lustre: DEBUG MARKER: == replay-single test 0b: ensure object created after recover exists. (3284) ========================================================== 09:36:23 (1786628183) [ 436.338813] Lustre: Failing over lustre-OST0000 [ 436.419051] Lustre: server umount lustre-OST0000 complete [ 437.216688] 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 [ 437.228886] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 442.338540] LustreError: 6690:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 442.355315] LustreError: 6690:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 3 previous similar messages [ 443.073254] LustreError: 6691:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.202.37@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 447.455901] LustreError: 6689:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 452.588379] LustreError: 8780:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 452.610937] LustreError: 8780:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 1 previous similar message [ 455.414233] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 456.741286] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 457.015181] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 457.018611] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 457.035133] Lustre: Skipped 1 previous similar message [ 462.207968] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 472.933518] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 474.799564] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 485.909719] Lustre: DEBUG MARKER: == replay-single test 0c: check replay-barrier =========== 09:37:15 (1786628235) [ 489.163158] LustreError: 14849:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 489.980835] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 491.998570] Lustre: Failing over lustre-MDT0000 [ 492.443943] Lustre: server umount lustre-MDT0000 complete [ 511.464987] LustreError: MGC192.168.202.137@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 511.686742] 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 [ 511.702483] Lustre: Skipped 1 previous similar message [ 511.828990] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 512.735420] Lustre: 3306:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786628247/real 1786628247] req@ffff9b38dfd7ea00 x1873415111798144/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786628263 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 512.762949] Lustre: 3306:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 515.514762] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 517.090383] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 517.713056] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 517.719362] Lustre: lustre-MDT0000: Denying connection for new client 22a94e2e-08c4-46ce-a2fd-0acef9a03219 (at 192.168.202.37@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:59 [ 522.939234] Lustre: lustre-MDT0000: Denying connection for new client 22a94e2e-08c4-46ce-a2fd-0acef9a03219 (at 192.168.202.37@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:54 [ 523.231164] Lustre: 3308:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786628258/real 1786628258] req@ffff9b38e662ed80 x1873415111798912/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786628274 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 523.280193] Lustre: 3308:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 528.063461] Lustre: lustre-MDT0000: Denying connection for new client 22a94e2e-08c4-46ce-a2fd-0acef9a03219 (at 192.168.202.37@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:49 [ 533.181959] Lustre: lustre-MDT0000: Denying connection for new client 22a94e2e-08c4-46ce-a2fd-0acef9a03219 (at 192.168.202.37@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:44 [ 538.311126] Lustre: lustre-MDT0000: Denying connection for new client 22a94e2e-08c4-46ce-a2fd-0acef9a03219 (at 192.168.202.37@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:39 [ 548.541679] Lustre: lustre-MDT0000: Denying connection for new client 22a94e2e-08c4-46ce-a2fd-0acef9a03219 (at 192.168.202.37@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:28 [ 548.562740] Lustre: Skipped 1 previous similar message [ 569.024690] Lustre: lustre-MDT0000: Denying connection for new client 22a94e2e-08c4-46ce-a2fd-0acef9a03219 (at 192.168.202.37@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:08 [ 569.046790] Lustre: Skipped 3 previous similar messages [ 577.501344] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 577.505300] Lustre: 15481:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 01e53eb5-2544-4feb-8175-d98eb57d28da@ [ 577.512855] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 577.633323] Lustre: lustre-MDT0000: Recovery over after 1:00, of 1 clients 0 recovered and 1 was evicted. [ 577.729719] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:44 to 0x240000400:65) [ 577.731634] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:44 to 0x280000400:65) [ 590.476452] Lustre: DEBUG MARKER: == replay-single test 0d: expired recovery with no clients ========================================================== 09:38:59 (1786628339) [ 594.753709] LustreError: 16218:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 595.741770] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 598.869424] Lustre: Failing over lustre-MDT0000 [ 599.016095] 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 [ 599.020212] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 599.039448] Lustre: Skipped 1 previous similar message [ 599.054798] Lustre: Skipped 1 previous similar message [ 599.306608] Lustre: server umount lustre-MDT0000 complete [ 618.704264] LustreError: MGC192.168.202.137@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 619.346373] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 619.473215] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 620.262933] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 620.268441] Lustre: Skipped 1 previous similar message [ 624.308516] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 627.057575] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 627.069086] Lustre: lustre-MDT0000: Denying connection for new client 9ec6cbd8-2c30-4333-93cc-d1e175076eca (at 192.168.202.37@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 1:00 [ 627.077946] Lustre: Skipped 1 previous similar message [ 687.503280] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 687.508244] Lustre: 16855:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 22a94e2e-08c4-46ce-a2fd-0acef9a03219@ [ 687.519934] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 687.560719] Lustre: lustre-MDT0000: Recovery over after 1:00, of 1 clients 0 recovered and 1 was evicted. [ 687.600840] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:44 to 0x240000400:97) [ 687.601841] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:44 to 0x280000400:97) [ 698.571459] Lustre: DEBUG MARKER: == replay-single test 1: simple create =================== 09:40:48 (1786628448) [ 701.592398] LustreError: 17591:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 702.578976] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 704.538791] Lustre: Failing over lustre-MDT0000 [ 704.765142] Lustre: server umount lustre-MDT0000 complete [ 722.847241] Lustre: 3307:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786628458/real 1786628458] req@ffff9b38e662fb80 x1873415111845504/t0(0) o400->MGC192.168.202.137@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1786628474 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 722.881979] LustreError: MGC192.168.202.137@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 722.902440] 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 [ 734.053416] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 734.180307] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 735.458352] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 735.593385] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 735.634858] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:44 to 0x280000400:129) [ 735.637307] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:44 to 0x240000400:129) [ 738.069220] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 748.520111] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 748.532081] Lustre: Skipped 1 previous similar message [ 749.259705] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 751.169344] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 761.124124] Lustre: DEBUG MARKER: == replay-single test 2a: touch ========================== 09:41:50 (1786628510) [ 764.231173] LustreError: 19178:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 765.063578] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 766.960967] Lustre: Failing over lustre-MDT0000 [ 767.257738] Lustre: server umount lustre-MDT0000 complete [ 785.188961] Lustre: 3308:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786628520/real 1786628520] req@ffff9b38d8987b80 x1873415111861760/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786628536 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 785.218551] Lustre: 3308:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 8 previous similar messages [ 785.228095] 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 [ 785.239134] Lustre: Skipped 1 previous similar message [ 785.243799] LustreError: MGC192.168.202.137@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 796.387858] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 797.900151] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 798.133677] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 798.203469] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:131 to 0x240000400:161) [ 798.203511] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:44 to 0x280000400:161) [ 800.760638] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 809.335443] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 810.411246] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 810.424101] Lustre: Skipped 1 previous similar message [ 811.068782] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 820.512263] Lustre: DEBUG MARKER: == replay-single test 2b: touch ========================== 09:42:50 (1786628570) [ 824.062770] LustreError: 20778:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 824.866913] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 826.690452] Lustre: Failing over lustre-MDT0000 [ 827.170089] Lustre: server umount lustre-MDT0000 complete [ 845.552699] LustreError: MGC192.168.202.137@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 846.050133] 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 [ 846.067286] Lustre: Skipped 1 previous similar message [ 846.207669] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 846.212393] Lustre: Skipped 1 previous similar message [ 846.269693] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 850.561315] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 851.433795] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 851.440769] Lustre: Skipped 1 previous similar message [ 852.259269] Lustre: 3307:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786628587/real 1786628587] req@ffff9b38f705e300 x1873415111878912/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786628603 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 852.311339] Lustre: 3307:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 11 previous similar messages [ 854.204235] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 854.356383] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 854.402967] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:163 to 0x280000400:193) [ 854.405049] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:131 to 0x240000400:193) [ 860.976072] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 862.590766] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 870.360334] Lustre: DEBUG MARKER: == replay-single test 2c: setstripe replay =============== 09:43:40 (1786628620) [ 872.822308] LustreError: 22362:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 873.563365] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 875.123694] Lustre: Failing over lustre-MDT0000 [ 875.331315] Lustre: server umount lustre-MDT0000 complete [ 893.153935] 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 [ 893.167892] Lustre: Skipped 1 previous similar message [ 893.391146] LustreError: MGC192.168.202.137@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 903.329923] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x70e172d4b1115f92 [ 903.336888] Lustre: MGC192.168.202.137@tcp: Connection restored to 0@lo (at 0@lo) [ 903.340165] Lustre: Skipped 1 previous similar message [ 904.082479] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 906.433612] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 906.719633] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 906.786727] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:225) [ 906.790218] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:225) [ 910.045377] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 920.734417] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 922.400429] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 931.681664] Lustre: DEBUG MARKER: == replay-single test 2d: setdirstripe replay ============ 09:44:41 (1786628681) [ 934.446511] LustreError: 23958:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 935.276994] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 937.422737] Lustre: Failing over lustre-MDT0000 [ 937.787674] Lustre: server umount lustre-MDT0000 complete [ 955.344184] LustreError: MGC192.168.202.137@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 965.605925] LustreError: 3305:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9b38fa29ad80 x1873415111912960/t0(0) o250->MGC192.168.202.137@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 0 ref 1 fl Rpc:NQU/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 966.233616] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 969.223284] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:257) [ 969.231695] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:257) [ 971.000331] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 980.463981] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 980.480197] Lustre: Skipped 2 previous similar messages [ 982.164912] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 984.052926] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 993.869615] Lustre: DEBUG MARKER: == replay-single test 2e: O_CREAT|O_EXCL create replay === 09:45:43 (1786628743) [ 994.825851] Lustre: *** cfs_fail_loc=13b, val=315*** [ 994.827700] Lustre: *** cfs_fail_loc=13b, val=2147483648*** [ 994.831159] LustreError: 24572:0:(ldlm_lib.c:3346:target_send_reply_msg()) @@@ dropping reply req@ffff9b38fa285180 x1873415086665728/t38654705666(0) o35->9ec6cbd8-2c30-4333-93cc-d1e175076eca@192.168.202.37@tcp:537/0 lens 392/456 e 0 to 0 dl 1786628762 ref 1 fl Interpret:/600/0 rc 0/0 job:'openfile.0' uid:0 gid:0 projid:0 [ 998.894434] LustreError: 25600:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 999.824294] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1001.953783] Lustre: Failing over lustre-MDT0000 [ 1002.314585] Lustre: server umount lustre-MDT0000 complete [ 1022.303132] Lustre: 3308:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786628757/real 1786628757] req@ffff9b38e662f480 x1873415111928576/t0(0) o400->MGC192.168.202.137@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1786628773 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1022.315086] Lustre: 3308:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 22 previous similar messages [ 1022.319465] LustreError: MGC192.168.202.137@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1022.431460] 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 [ 1022.436759] Lustre: Skipped 3 previous similar messages [ 1032.491047] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x70e172d4b1116844 [ 1032.822030] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1032.823854] Lustre: Skipped 2 previous similar messages [ 1032.863888] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1038.395755] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1042.621194] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1042.631588] Lustre: Skipped 1 previous similar message [ 1042.722365] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1042.735763] Lustre: Skipped 1 previous similar message [ 1042.761986] Lustre: 26208:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9b38e662f480 x1873415086665728/t38654705666(0) o35->9ec6cbd8-2c30-4333-93cc-d1e175076eca@192.168.202.37@tcp:585/0 lens 392/456 e 0 to 0 dl 1786628810 ref 1 fl Interpret:/602/0 rc 0/0 job:'openfile.0' uid:0 gid:0 projid:0 [ 1042.768452] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:289) [ 1042.770165] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:289) [ 1048.434938] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1050.209250] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1059.068341] Lustre: DEBUG MARKER: == replay-single test 3a: replay failed open(O_DIRECTORY) ========================================================== 09:46:48 (1786628808) [ 1063.321600] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1065.751813] Lustre: Failing over lustre-MDT0000 [ 1066.231213] Lustre: server umount lustre-MDT0000 complete [ 1094.056547] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x70e172d4b1116c8f [ 1094.944467] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1101.562560] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1108.971928] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 1108.983940] Lustre: Skipped 6 previous similar messages [ 1109.383721] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:321) [ 1109.384090] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:321) [ 1115.631941] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1117.545769] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1128.124727] Lustre: DEBUG MARKER: == replay-single test 3b: replay failed open -ENOMEM ===== 09:47:57 (1786628877) [ 1131.066662] LustreError: 28785:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 1131.076817] LustreError: 28785:0:(osd_handler.c:715:osd_ro()) Skipped 1 previous similar message [ 1132.030194] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1133.029948] Lustre: *** cfs_fail_loc=114, val=0*** [ 1136.298892] Lustre: Failing over lustre-MDT0000 [ 1136.628158] Lustre: server umount lustre-MDT0000 complete [ 1154.847503] LustreError: MGC192.168.202.137@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1154.851249] 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 [ 1154.860394] LustreError: Skipped 1 previous similar message [ 1154.889525] Lustre: Skipped 3 previous similar messages [ 1166.091635] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1166.799403] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:353) [ 1166.802665] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:353) [ 1171.933308] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1183.095834] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1185.169145] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1194.205133] Lustre: DEBUG MARKER: == replay-single test 3c: replay failed open -ENOMEM ===== 09:49:03 (1786628943) [ 1198.829040] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1199.967994] Lustre: *** cfs_fail_loc=128, val=0*** [ 1202.806334] Lustre: Failing over lustre-MDT0000 [ 1203.125461] Lustre: server umount lustre-MDT0000 complete [ 1231.350710] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x70e172d4b1117572 [ 1233.092246] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1233.102487] Lustre: Skipped 2 previous similar messages [ 1233.308584] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1233.325371] Lustre: Skipped 2 previous similar messages [ 1233.400413] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:385) [ 1233.401952] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:385) [ 1236.706698] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1246.520111] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1248.136687] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1258.443932] Lustre: DEBUG MARKER: == replay-single test 4a: |x| 10 open(O_CREAT)s ========== 09:50:07 (1786629007) [ 1262.151225] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1264.129780] Lustre: Failing over lustre-MDT0000 [ 1264.414126] Lustre: server umount lustre-MDT0000 complete [ 1282.017615] Lustre: 3308:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786629017/real 1786629017] req@ffff9b38d8985500 x1873415111996288/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786629033 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1282.060188] Lustre: 3308:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 33 previous similar messages [ 1292.193954] LustreError: 3305:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9b39003c4380 x1873415111998080/t0(0) o250->MGC192.168.202.137@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 0 ref 1 fl Rpc:NQU/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1292.809497] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1292.812075] Lustre: Skipped 3 previous similar messages [ 1296.024287] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:391 to 0x280000400:417) [ 1296.026522] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:391 to 0x240000400:417) [ 1298.045600] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1308.389650] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1310.076233] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1319.932254] Lustre: DEBUG MARKER: == replay-single test 4b: |x| rm 10 files ================ 09:51:09 (1786629069) [ 1323.899852] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1326.151077] Lustre: Failing over lustre-MDT0000 [ 1326.282270] Lustre: lustre-MDT0000: Not available for connect from 192.168.202.37@tcp (stopping) [ 1326.449512] Lustre: server umount lustre-MDT0000 complete [ 1354.012262] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1354.021230] Lustre: Skipped 2 previous similar messages [ 1359.972296] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1366.654181] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:423 to 0x280000400:449) [ 1366.659333] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:423 to 0x240000400:449) [ 1368.038748] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 1368.044143] Lustre: Skipped 7 previous similar messages [ 1374.278361] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1376.063567] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1386.258426] Lustre: DEBUG MARKER: == replay-single test 5: |x| 220 open(O_CREAT) =========== 09:52:15 (1786629135) [ 1390.221130] LustreError: 35356:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 1390.229731] LustreError: 35356:0:(osd_handler.c:715:osd_ro()) Skipped 3 previous similar messages [ 1391.168328] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1399.358812] Lustre: Failing over lustre-MDT0000 [ 1399.935580] Lustre: server umount lustre-MDT0000 complete [ 1419.465803] LustreError: MGC192.168.202.137@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1419.476311] LustreError: Skipped 3 previous similar messages [ 1420.025266] 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 [ 1420.052578] Lustre: Skipped 7 previous similar messages [ 1425.915781] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1431.811122] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:577) [ 1431.811485] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:577) [ 1438.000821] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1439.654218] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1466.919890] Lustre: DEBUG MARKER: == replay-single test 6a: mkdir + contained create ======= 09:53:36 (1786629216) [ 1471.088301] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1473.071549] Lustre: Failing over lustre-MDT0000 [ 1473.437229] Lustre: server umount lustre-MDT0000 complete [ 1502.111812] LustreError: 3305:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9b390138a680 x1873415112114176/t0(0) o250->MGC192.168.202.137@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 0 ref 1 fl Rpc:NQU/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1507.629213] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1516.222694] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1516.235045] Lustre: Skipped 3 previous similar messages [ 1516.437878] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1516.452848] Lustre: Skipped 3 previous similar messages [ 1516.519966] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:609) [ 1516.520263] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:609) [ 1523.889916] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1525.905878] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1536.616770] Lustre: DEBUG MARKER: == replay-single test 6b: |X| rmdir ====================== 09:54:46 (1786629286) [ 1541.437628] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1543.777479] Lustre: Failing over lustre-MDT0000 [ 1544.116187] Lustre: server umount lustre-MDT0000 complete [ 1573.348265] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x70e172d4b11225d7 [ 1573.567895] Lustre: lustre-MDT0000: Not available for connect from 192.168.202.37@tcp (not set up) [ 1575.257386] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:641) [ 1575.266168] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:641) [ 1579.279112] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1590.872571] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1593.016956] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1602.791119] Lustre: DEBUG MARKER: == replay-single test 7: mkdir |X| contained create ====== 09:55:52 (1786629352) [ 1607.316553] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1609.570528] Lustre: Failing over lustre-MDT0000 [ 1609.853696] Lustre: server umount lustre-MDT0000 complete [ 1639.391843] LustreError: 3305:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9b39001a0700 x1873415112148352/t0(0) o250->MGC192.168.202.137@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 0 ref 1 fl Rpc:NQU/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1640.071839] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1640.083014] Lustre: Skipped 3 previous similar messages [ 1640.366631] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:673) [ 1640.366878] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:673) [ 1645.432579] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1655.875851] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1657.508417] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1666.498764] Lustre: DEBUG MARKER: == replay-single test 8: creat open |X| close ============ 09:56:56 (1786629416) [ 1670.738368] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1673.106176] Lustre: Failing over lustre-MDT0000 [ 1673.560886] Lustre: server umount lustre-MDT0000 complete [ 1702.929087] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:705) [ 1702.938559] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:705) [ 1707.939467] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1719.314581] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1721.055960] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1731.067731] Lustre: DEBUG MARKER: == replay-single test 9: |X| create (same inum/gen) ====== 09:58:00 (1786629480) [ 1735.565473] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1737.700507] Lustre: Failing over lustre-MDT0000 [ 1738.151898] Lustre: server umount lustre-MDT0000 complete [ 1767.391865] LustreError: 3305:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9b38ef362d80 x1873415112181504/t0(0) o250->MGC192.168.202.137@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 0 ref 1 fl Rpc:NQU/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1774.204677] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1779.652172] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:737) [ 1779.674527] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:737) [ 1786.565569] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1788.437271] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1799.059265] Lustre: DEBUG MARKER: == replay-single test 10: create |X| rename unlink ======= 09:59:08 (1786629548) [ 1803.354214] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1805.545842] Lustre: Failing over lustre-MDT0000 [ 1805.970248] Lustre: server umount lustre-MDT0000 complete [ 1824.159725] Lustre: 3306:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786629559/real 1786629559] req@ffff9b38c861b800 x1873415112196864/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786629575 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1824.212021] Lustre: 3306:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 65 previous similar messages [ 1834.469701] LustreError: 3305:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9b38ef29d180 x1873415112198784/t0(0) o250->MGC192.168.202.137@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 0 ref 1 fl Rpc:NQU/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1835.219486] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1835.222916] Lustre: Skipped 7 previous similar messages [ 1836.001032] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:769) [ 1836.004583] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:769) [ 1841.030381] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1851.064172] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1852.827343] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1863.677894] Lustre: DEBUG MARKER: == replay-single test 11: create open write rename |X| create-old-name read ========================================================== 10:00:12 (1786629612) [ 1869.207075] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1871.382746] Lustre: Failing over lustre-MDT0000 [ 1871.573171] Lustre: lustre-MDT0000: Not available for connect from 192.168.202.37@tcp (stopping) [ 1871.717921] Lustre: server umount lustre-MDT0000 complete [ 1892.420583] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:771 to 0x280000400:801) [ 1892.422693] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:771 to 0x240000400:801) [ 1894.834625] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1895.394056] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 1895.405513] Lustre: Skipped 16 previous similar messages [ 1904.840057] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1906.851656] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1915.937725] Lustre: DEBUG MARKER: == replay-single test 12: open, unlink |X| close ========= 10:01:05 (1786629665) [ 1919.178627] LustreError: 48112:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 1919.187432] LustreError: 48112:0:(osd_handler.c:715:osd_ro()) Skipped 7 previous similar messages [ 1920.261685] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1922.471268] Lustre: Failing over lustre-MDT0000 [ 1922.759847] Lustre: server umount lustre-MDT0000 complete [ 1941.725091] LustreError: MGC192.168.202.137@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1941.738294] LustreError: Skipped 7 previous similar messages [ 1942.030394] 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 [ 1942.053839] Lustre: Skipped 15 previous similar messages [ 1947.263425] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1949.525331] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:771 to 0x240000400:833) [ 1949.527288] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:771 to 0x280000400:833) [ 1957.813626] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1959.905833] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1969.049152] Lustre: DEBUG MARKER: == replay-single test 13: open chmod 0 |x| write close === 10:01:58 (1786629718) [ 1973.412317] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1975.155202] Lustre: Failing over lustre-MDT0000 [ 1975.651996] Lustre: server umount lustre-MDT0000 complete [ 1994.521207] Lustre: lustre-MDT0000: Not available for connect from 0@lo (not set up) [ 1995.717125] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:835 to 0x280000400:865) [ 1995.721811] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:771 to 0x240000400:865) [ 1999.777624] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2008.843859] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2010.095895] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2017.591983] Lustre: DEBUG MARKER: == replay-single test 14: open(O_CREAT), unlink |X| close ========================================================== 10:02:47 (1786629767) [ 2022.090835] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2024.517687] Lustre: Failing over lustre-MDT0000 [ 2024.967880] Lustre: server umount lustre-MDT0000 complete [ 2051.774035] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 2051.782447] Lustre: Skipped 8 previous similar messages [ 2051.926300] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 2051.934035] Lustre: Skipped 8 previous similar messages [ 2052.007296] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:867 to 0x240000400:897) [ 2052.012041] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:835 to 0x280000400:897) [ 2055.763660] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2066.543069] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2068.644415] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2077.187616] Lustre: DEBUG MARKER: == replay-single test 15: open(O_CREAT), unlink |X| touch new, close ========================================================== 10:03:46 (1786629826) [ 2081.532805] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2083.997239] Lustre: Failing over lustre-MDT0000 [ 2084.443916] Lustre: server umount lustre-MDT0000 complete [ 2113.565874] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:899 to 0x240000400:929) [ 2113.569333] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:899 to 0x280000400:929) [ 2117.399609] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2127.500987] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2129.751436] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2139.630263] Lustre: DEBUG MARKER: == replay-single test 16: |X| open(O_CREAT), unlink, touch new, unlink new ========================================================== 10:04:49 (1786629889) [ 2144.194671] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2146.383768] Lustre: Failing over lustre-MDT0000 [ 2146.753306] Lustre: server umount lustre-MDT0000 complete [ 2175.648722] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x70e172d4b11256e5 [ 2176.355547] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 2176.365729] Lustre: Skipped 8 previous similar messages [ 2180.934987] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2191.380271] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:931 to 0x280000400:961) [ 2191.381719] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:899 to 0x240000400:961) [ 2196.519485] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2198.281174] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2206.827539] Lustre: DEBUG MARKER: == replay-single test 17: |X| open(O_CREAT), |replay| close ========================================================== 10:05:56 (1786629956) [ 2210.099462] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2211.788981] Lustre: Failing over lustre-MDT0000 [ 2212.232159] Lustre: server umount lustre-MDT0000 complete [ 2240.235623] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2242.420061] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:931 to 0x280000400:993) [ 2242.421054] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:963 to 0x240000400:993) [ 2252.224685] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2254.051347] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2262.560983] Lustre: DEBUG MARKER: == replay-single test 18: open(O_CREAT), unlink, touch new, close, touch, unlink ========================================================== 10:06:52 (1786630012) [ 2266.608254] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2268.496500] Lustre: Failing over lustre-MDT0000 [ 2268.651210] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2268.658231] Lustre: Skipped 2 previous similar messages [ 2268.774873] Lustre: server umount lustre-MDT0000 complete [ 2288.335882] Lustre: lustre-MDT0000: Not available for connect from 192.168.202.37@tcp (not set up) [ 2290.239182] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:995 to 0x240000400:1025) [ 2290.239727] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:995 to 0x280000400:1025) [ 2294.689371] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2306.514791] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2308.339905] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2317.803708] Lustre: DEBUG MARKER: == replay-single test 19: mcreate, open, write, rename === 10:07:47 (1786630067) [ 2322.144982] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2324.407676] Lustre: Failing over lustre-MDT0000 [ 2324.681241] Lustre: server umount lustre-MDT0000 complete [ 2355.211111] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1027 to 0x240000400:1057) [ 2355.216755] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1027 to 0x280000400:1057) [ 2357.992687] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2368.301714] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2370.049609] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2379.741506] Lustre: DEBUG MARKER: == replay-single test 20a: |X| open(O_CREAT), unlink, replay, close (test mds_cleanup_orphans) ========================================================== 10:08:49 (1786630129) [ 2383.564136] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2385.714515] Lustre: Failing over lustre-MDT0000 [ 2386.121332] Lustre: server umount lustre-MDT0000 complete [ 2417.621308] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1027 to 0x240000400:1089) [ 2417.626189] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1059 to 0x280000400:1089) [ 2417.758879] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2427.385177] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2428.968339] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2436.469959] Lustre: DEBUG MARKER: == replay-single test 20b: write, unlink, eviction, replay (test mds_cleanup_orphans) ========================================================== 10:09:46 (1786630186) [ 2440.981409] Lustre: 62427:0:(genops.c:1795:obd_export_evict_by_uuid()) lustre-MDT0000: evicting 9ec6cbd8-2c30-4333-93cc-d1e175076eca at adminstrative request [ 2447.714169] Lustre: Failing over lustre-MDT0000 [ 2447.967770] Lustre: server umount lustre-MDT0000 complete [ 2464.735211] Lustre: 3308:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786630199/real 1786630199] req@ffff9b38d1e6ed80 x1873415112380032/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786630215 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2464.772240] Lustre: 3308:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 89 previous similar messages [ 2473.953370] LustreError: 3305:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9b38ef2f5c00 x1873415112381952/t0(0) o250->MGC192.168.202.137@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 0 ref 1 fl Rpc:NQU/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2474.616163] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 2474.620430] Lustre: Skipped 10 previous similar messages [ 2479.398246] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2489.176553] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1059 to 0x280000400:1121) [ 2489.177072] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1091 to 0x240000400:1121) [ 2495.268617] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2497.317739] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2503.545400] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 2519.183578] Lustre: DEBUG MARKER: before 4096, after 4096 [ 2524.764686] Lustre: DEBUG MARKER: == replay-single test 20c: check that client eviction does not affect file content ========================================================== 10:11:14 (1786630274) [ 2525.565623] Lustre: 64517:0:(genops.c:1795:obd_export_evict_by_uuid()) lustre-MDT0000: evicting 9ec6cbd8-2c30-4333-93cc-d1e175076eca at adminstrative request [ 2536.656823] Lustre: DEBUG MARKER: == replay-single test 21: |X| open(O_CREAT), unlink touch new, replay, close (test mds_cleanup_orphans) ========================================================== 10:11:26 (1786630286) [ 2539.648177] LustreError: 64864:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 2539.653567] LustreError: 64864:0:(osd_handler.c:715:osd_ro()) Skipped 8 previous similar messages [ 2540.748513] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2543.218386] Lustre: Failing over lustre-MDT0000 [ 2543.634514] Lustre: server umount lustre-MDT0000 complete [ 2562.399197] 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 [ 2562.423140] Lustre: Skipped 19 previous similar messages [ 2562.707564] LustreError: MGC192.168.202.137@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2562.722717] LustreError: Skipped 9 previous similar messages [ 2568.150936] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2571.335163] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1123 to 0x240000400:1153) [ 2571.346994] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1124 to 0x280000400:1153) [ 2572.264685] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 2572.273689] Lustre: Skipped 22 previous similar messages [ 2577.494304] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2579.146825] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2587.150723] Lustre: DEBUG MARKER: == replay-single test 22: open(O_CREAT), |X| unlink, replay, close (test mds_cleanup_orphans) ========================================================== 10:12:17 (1786630337) [ 2590.982823] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2592.568304] Lustre: Failing over lustre-MDT0000 [ 2592.737086] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2592.740906] Lustre: Skipped 1 previous similar message [ 2592.884913] Lustre: server umount lustre-MDT0000 complete [ 2612.066391] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1155 to 0x280000400:1185) [ 2612.070284] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1155 to 0x240000400:1185) [ 2615.694805] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2624.435554] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2625.885629] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2633.203454] Lustre: DEBUG MARKER: == replay-single test 23: open(O_CREAT), |X| unlink touch new, replay, close (test mds_cleanup_orphans) ========================================================== 10:13:03 (1786630383) [ 2636.767877] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2638.760020] Lustre: Failing over lustre-MDT0000 [ 2639.020323] Lustre: server umount lustre-MDT0000 complete [ 2668.228407] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 2668.235329] Lustre: Skipped 9 previous similar messages [ 2668.423310] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 2668.432092] Lustre: Skipped 9 previous similar messages [ 2668.490658] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1187 to 0x280000400:1217) [ 2668.493277] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1187 to 0x240000400:1217) [ 2669.877647] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2679.375804] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2680.875542] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2688.932164] Lustre: DEBUG MARKER: == replay-single test 24: open(O_CREAT), replay, unlink, close (test mds_cleanup_orphans) ========================================================== 10:13:59 (1786630439) [ 2692.702117] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2694.443554] Lustre: Failing over lustre-MDT0000 [ 2694.676125] Lustre: server umount lustre-MDT0000 complete [ 2711.521623] Lustre: lustre-MDT0000: Not available for connect from 0@lo (not set up) [ 2714.576388] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1219 to 0x280000400:1249) [ 2714.578132] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1219 to 0x240000400:1249) [ 2716.226614] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2726.304757] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2728.331162] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2736.400652] Lustre: DEBUG MARKER: == replay-single test 25: open(O_CREAT), unlink, replay, close (test mds_cleanup_orphans) ========================================================== 10:14:46 (1786630486) [ 2739.745776] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2741.392612] Lustre: Failing over lustre-MDT0000 [ 2741.598147] Lustre: server umount lustre-MDT0000 complete [ 2760.585365] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1219 to 0x280000400:1281) [ 2760.587128] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1251 to 0x240000400:1281) [ 2762.310788] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2770.656668] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2771.951187] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2778.993458] Lustre: DEBUG MARKER: == replay-single test 26: |X| open(O_CREAT), unlink two, close one, replay, close one (test mds_cleanup_orphans) ========================================================== 10:15:29 (1786630529) [ 2782.401829] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2784.367883] Lustre: Failing over lustre-MDT0000 [ 2784.630873] Lustre: server umount lustre-MDT0000 complete [ 2802.151122] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 2802.162204] Lustre: Skipped 10 previous similar messages [ 2802.696925] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1283 to 0x240000400:1313) [ 2802.697114] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1283 to 0x280000400:1313) [ 2806.490700] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2815.062646] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2816.486401] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2824.386790] Lustre: DEBUG MARKER: == replay-single test 27: |X| open(O_CREAT), unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 10:16:14 (1786630574) [ 2828.211057] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2830.122695] Lustre: Failing over lustre-MDT0000 [ 2830.413074] Lustre: server umount lustre-MDT0000 complete [ 2851.549323] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1315 to 0x280000400:1345) [ 2851.552550] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1315 to 0x240000400:1345) [ 2853.726284] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2862.666905] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2864.186298] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2872.942074] Lustre: DEBUG MARKER: == replay-single test 28: open(O_CREAT), |X| unlink two, close one, replay, close one (test mds_cleanup_orphans) ========================================================== 10:17:02 (1786630622) [ 2877.033304] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2878.982930] Lustre: Failing over lustre-MDT0000 [ 2879.271362] Lustre: server umount lustre-MDT0000 complete [ 2906.594162] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x70e172d4b1129950 [ 2912.376261] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2921.310612] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1347 to 0x280000400:1377) [ 2921.319937] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1347 to 0x240000400:1377) [ 2926.554689] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2928.193323] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2936.411107] Lustre: DEBUG MARKER: == replay-single test 29: open(O_CREAT), |X| unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 10:18:06 (1786630686) [ 2940.093107] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2942.272658] Lustre: Failing over lustre-MDT0000 [ 2942.665506] Lustre: server umount lustre-MDT0000 complete [ 2963.596701] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1379 to 0x240000400:1409) [ 2963.612448] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1379 to 0x280000400:1409) [ 2966.716660] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2977.071954] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2978.444445] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2987.327936] Lustre: DEBUG MARKER: == replay-single test 30: open(O_CREAT) two, unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 10:18:56 (1786630736) [ 2991.590541] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2993.879687] Lustre: Failing over lustre-MDT0000 [ 2994.140234] Lustre: server umount lustre-MDT0000 complete [ 3013.320827] Lustre: lustre-MDT0000: Not available for connect from 192.168.202.37@tcp (not set up) [ 3013.334293] Lustre: Skipped 1 previous similar message [ 3014.635318] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1411 to 0x280000400:1441) [ 3014.635816] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1411 to 0x240000400:1441) [ 3018.895665] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3029.399744] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3031.096727] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3039.300871] Lustre: DEBUG MARKER: == replay-single test 31: open(O_CREAT) two, unlink one, |X| unlink one, close two (test mds_cleanup_orphans) ========================================================== 10:19:49 (1786630789) [ 3043.464818] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3045.348494] Lustre: Failing over lustre-MDT0000 [ 3045.856507] Lustre: server umount lustre-MDT0000 complete [ 3065.536444] LustreError: 81324:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.202.37@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3065.570948] LustreError: 81324:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 1 previous similar message [ 3066.848082] Lustre: 3309:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786630800/real 1786630800] req@ffff9b38c7bf0000 x1873415112558592/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786630816 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3066.874257] Lustre: 3309:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 77 previous similar messages [ 3067.897530] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1443 to 0x240000400:1473) [ 3067.899105] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1443 to 0x280000400:1473) [ 3072.937538] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3086.287765] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3087.829992] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3096.600211] Lustre: DEBUG MARKER: == replay-single test 32: close() notices client eviction; close() after client eviction ========================================================== 10:20:46 (1786630846) [ 3097.796283] Lustre: 82204:0:(genops.c:1795:obd_export_evict_by_uuid()) lustre-MDT0000: evicting 9ec6cbd8-2c30-4333-93cc-d1e175076eca at adminstrative request [ 3108.342780] Lustre: DEBUG MARKER: == replay-single test 33a: fid seq shouldn't be reused after abort recovery ========================================================== 10:20:58 (1786630858) [ 3111.286874] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3113.392455] Lustre: Failing over lustre-MDT0000 [ 3113.648967] Lustre: server umount lustre-MDT0000 complete [ 3123.270511] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3123.279042] Lustre: Skipped 11 previous similar messages [ 3123.379786] Lustre: lustre-MDT0000: Aborting client recovery [ 3123.382547] LustreError: 83108:0:(ldlm_lib.c:3004:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 3123.389144] Lustre: 83155:0:(ldlm_lib.c:2404:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 3123.397957] Lustre: 83155:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 9ec6cbd8-2c30-4333-93cc-d1e175076eca@ [ 3123.408269] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 3123.460993] Lustre: lustre-MDT0000-osd: cancel update llog [0x200000400:0x1:0x0] [ 3123.635324] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1480 to 0x240000400:1505) [ 3123.642616] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1479 to 0x280000400:1505) [ 3129.493047] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3142.464871] Lustre: DEBUG MARKER: == replay-single test 33b: test fid seq allocation ======= 10:21:32 (1786630892) [ 3145.231668] LustreError: 83849:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 3145.236434] LustreError: 83849:0:(osd_handler.c:715:osd_ro()) Skipped 11 previous similar messages [ 3146.186612] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3148.328439] Lustre: Failing over lustre-MDT0000 [ 3148.709642] Lustre: server umount lustre-MDT0000 complete [ 3157.706043] LustreError: 84486:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.202.37@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3158.327034] Lustre: *** cfs_fail_loc=1311, val=0*** [ 3158.380779] Lustre: lustre-MDT0000: Aborting client recovery [ 3158.384599] LustreError: 84474:0:(ldlm_lib.c:3004:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 3158.392223] Lustre: 84521:0:(ldlm_lib.c:2404:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 3158.402177] Lustre: 84521:0:(ldlm_lib.c:2404:target_recovery_overseer()) Skipped 2 previous similar messages [ 3158.406957] Lustre: 84521:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 9ec6cbd8-2c30-4333-93cc-d1e175076eca@ [ 3158.420818] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 3158.563718] Lustre: lustre-MDT0000-osd: cancel update llog [0x200015bc0:0x1:0x0] [ 3158.767531] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1516 to 0x240000400:1537) [ 3158.771302] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1516 to 0x280000400:1537) [ 3163.486379] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3169.009292] Lustre: *** cfs_fail_loc=1311, val=0*** [ 3175.819385] Lustre: DEBUG MARKER: == replay-single test 34: abort recovery before client does replay (test mds_cleanup_orphans) ========================================================== 10:22:05 (1786630925) [ 3179.318350] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3181.128747] Lustre: Failing over lustre-MDT0000 [ 3181.305835] Lustre: server umount lustre-MDT0000 complete [ 3189.344259] LustreError: MGC192.168.202.137@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3189.348533] LustreError: Skipped 12 previous similar messages [ 3189.615120] 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 [ 3189.630706] Lustre: Skipped 26 previous similar messages [ 3189.832567] Lustre: lustre-MDT0000: Aborting client recovery [ 3189.834066] LustreError: 85845:0:(ldlm_lib.c:3004:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 3189.836646] Lustre: 85892:0:(ldlm_lib.c:2404:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 3189.840239] Lustre: 85892:0:(ldlm_lib.c:2404:target_recovery_overseer()) Skipped 2 previous similar messages [ 3189.843417] Lustre: 85892:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 9ec6cbd8-2c30-4333-93cc-d1e175076eca@ [ 3189.848396] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 3189.936428] Lustre: lustre-MDT0000-osd: cancel update llog [0x200016778:0x1:0x0] [ 3190.066563] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1543 to 0x280000400:1569) [ 3190.082487] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1544 to 0x240000400:1569) [ 3194.562349] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3194.856686] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 3194.862854] Lustre: Skipped 26 previous similar messages [ 3205.938604] Lustre: DEBUG MARKER: == replay-single test 35: test recovery from llog for unlink op ========================================================== 10:22:36 (1786630956) [ 3206.861932] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 3206.865505] LustreError: 85855:0:(ldlm_lib.c:3346:target_send_reply_msg()) @@@ dropping reply req@ffff9b39001a2d80 x1873415087672960/t201863462916(0) o36->9ec6cbd8-2c30-4333-93cc-d1e175076eca@192.168.202.37@tcp:479/0 lens 512/456 e 0 to 0 dl 1786630969 ref 1 fl Interpret:/200/0 rc 0/0 job:'rm.0' uid:0 gid:0 projid:4294967295 [ 3210.440865] Lustre: Failing over lustre-MDT0000 [ 3210.675445] Lustre: server umount lustre-MDT0000 complete [ 3218.687995] Lustre: lustre-MDT0000: Aborting client recovery [ 3218.691497] LustreError: 87074:0:(ldlm_lib.c:3004:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 3218.697457] Lustre: 87121:0:(ldlm_lib.c:2404:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 3218.702387] Lustre: 87121:0:(ldlm_lib.c:2404:target_recovery_overseer()) Skipped 2 previous similar messages [ 3218.707645] Lustre: 87121:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 9ec6cbd8-2c30-4333-93cc-d1e175076eca@ [ 3218.718804] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 3218.769799] Lustre: lustre-MDT0000-osd: cancel update llog [0x200017330:0x1:0x0] [ 3218.953060] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1544 to 0x240000400:1601) [ 3218.962843] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1571 to 0x280000400:1601) [ 3222.970779] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3236.053801] Lustre: DEBUG MARKER: SKIP: replay-single test_36 skipping ALWAYS excluded test 36 [ 3237.363283] Lustre: DEBUG MARKER: == replay-single test 37: abort recovery before client does replay (test mds_cleanup_orphans for directories) ========================================================== 10:23:07 (1786630987) [ 3241.725734] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3244.254935] Lustre: Failing over lustre-MDT0000 [ 3244.465113] Lustre: server umount lustre-MDT0000 complete [ 3252.776732] Lustre: lustre-MDT0000: Aborting client recovery [ 3252.780341] LustreError: 88532:0:(ldlm_lib.c:3004:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 3252.784068] Lustre: 88580:0:(ldlm_lib.c:2404:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 3252.788387] Lustre: 88580:0:(ldlm_lib.c:2404:target_recovery_overseer()) Skipped 2 previous similar messages [ 3252.790770] Lustre: 88580:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 9ec6cbd8-2c30-4333-93cc-d1e175076eca@ [ 3252.795114] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 3252.826527] Lustre: lustre-MDT0000-osd: cancel update llog [0x200017b00:0x1:0x0] [ 3252.974702] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1571 to 0x280000400:1633) [ 3252.975112] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1544 to 0x240000400:1633) [ 3257.658506] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3271.389153] Lustre: DEBUG MARKER: == replay-single test 38: test recovery from unlink llog (test llog_gen_rec) ========================================================== 10:23:40 (1786631020) [ 3303.092953] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3305.661763] Lustre: Failing over lustre-MDT0000 [ 3306.022773] Lustre: server umount lustre-MDT0000 complete [ 3331.098827] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3331.774595] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 3331.794186] Lustre: Skipped 8 previous similar messages [ 3331.943748] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 3331.947732] Lustre: Skipped 8 previous similar messages [ 3331.986439] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2034 to 0x280000400:2049) [ 3331.989842] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2034 to 0x240000400:2049) [ 3341.428335] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3342.912515] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3364.524076] Lustre: DEBUG MARKER: == replay-single test 39: test recovery from unlink llog (test llog_gen_rec) ========================================================== 10:25:13 (1786631113) [ 3386.412781] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3398.306861] Lustre: Failing over lustre-MDT0000 [ 3398.341913] Lustre: lustre-MDT0000: Not available for connect from 192.168.202.37@tcp (stopping) [ 3398.658238] Lustre: server umount lustre-MDT0000 complete [ 3428.783300] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 3428.795526] Lustre: Skipped 21 previous similar messages [ 3434.795210] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3443.368544] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2450 to 0x240000400:2465) [ 3443.371785] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2450 to 0x280000400:2465) [ 3451.088873] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3453.734940] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3474.424753] Lustre: DEBUG MARKER: == replay-single test 41: read from a valid osc while other oscs are invalid ========================================================== 10:27:04 (1786631224) [ 3476.264681] Lustre: setting import lustre-OST0001_UUID INACTIVE by administrator request [ 3477.044300] Lustre: lustre-OST0001: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnecting [ 3477.049371] LustreError: lustre-OST0001-osc-MDT0000: This client was evicted by lustre-OST0001; in progress operations using this service will fail. [ 3482.860318] Lustre: DEBUG MARKER: == replay-single test 42: recovery after ost failure ===== 10:27:12 (1786631232) [ 3508.062559] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 3519.556728] Lustre: Failing over lustre-OST0000 [ 3519.701700] Lustre: server umount lustre-OST0000 complete [ 3519.979433] LustreError: 36631:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3525.107462] LustreError: 36626:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3525.137882] LustreError: 36626:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 1 previous similar message [ 3530.209032] LustreError: 36634:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3530.223864] LustreError: 36634:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 1 previous similar message [ 3543.310653] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3604.638593] Lustre: DEBUG MARKER: == replay-single test 43: mds osc import failure during recovery; don't LBUG ========================================================== 10:29:13 (1786631353) [ 3610.024572] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3614.102357] Lustre: Failing over lustre-MDT0000 [ 3614.556396] Lustre: server umount lustre-MDT0000 complete [ 3638.901571] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3643.338688] Lustre: *** cfs_fail_loc=204, val=2147483648*** [ 3643.340164] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2866 to 0x280000400:2881) [ 3650.655604] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3652.664615] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3659.745388] LustreError: 96516:0:(osp_precreate.c:974:osp_precreate_cleanup_orphans()) lustre-OST0000-osc-MDT0000: cannot cleanup orphans: rc = -11 [ 3659.749188] Lustre: lustre-OST0000: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnecting [ 3660.832290] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2867 to 0x240000400:2913) [ 3671.747866] Lustre: DEBUG MARKER: == replay-single test 44a: race in target handle connect ========================================================== 10:30:21 (1786631421) [ 3677.569391] LustreError: 96491:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_race id 701 sleeping [ 3682.784604] LustreError: 96491:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 3682.799441] Lustre: lustre-MDT0000: Client 9ec6cbd8-2c30-4333-93cc-d1e175076eca (at 192.168.202.37@tcp) reconnecting [ 3682.869446] LustreError: 14720:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_fail_race id 701 waking [ 3684.919356] LustreError: 97605:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_race id 701 sleeping [ 3689.951128] LustreError: 97605:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 3689.956049] Lustre: lustre-MDT0000: Client 9ec6cbd8-2c30-4333-93cc-d1e175076eca (at 192.168.202.37@tcp) reconnecting [ 3691.972147] LustreError: 96491:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_race id 701 sleeping [ 3697.119176] LustreError: 96491:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 3697.124534] Lustre: lustre-MDT0000: Client 9ec6cbd8-2c30-4333-93cc-d1e175076eca (at 192.168.202.37@tcp) reconnecting [ 3699.361400] LustreError: 96493:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_race id 701 sleeping [ 3704.800274] LustreError: 96493:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 3706.720064] LustreError: 96492:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_race id 701 sleeping [ 3711.968230] LustreError: 96492:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 3711.982667] Lustre: lustre-MDT0000: Client 9ec6cbd8-2c30-4333-93cc-d1e175076eca (at 192.168.202.37@tcp) reconnecting [ 3711.990517] Lustre: Skipped 1 previous similar message [ 3721.373755] LustreError: 96492:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_race id 701 sleeping [ 3721.382462] LustreError: 96492:0:(ldlm_lib.c:1178:target_handle_connect()) Skipped 1 previous similar message [ 3726.815125] LustreError: 96492:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 3726.821459] LustreError: 96492:0:(ldlm_lib.c:1178:target_handle_connect()) Skipped 1 previous similar message [ 3734.497241] Lustre: lustre-MDT0000: Client 9ec6cbd8-2c30-4333-93cc-d1e175076eca (at 192.168.202.37@tcp) reconnecting [ 3734.515899] Lustre: Skipped 2 previous similar messages [ 3744.620404] LustreError: 96493:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_race id 701 sleeping [ 3744.634340] LustreError: 96493:0:(ldlm_lib.c:1178:target_handle_connect()) Skipped 2 previous similar messages [ 3749.857115] LustreError: 96493:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 3749.869620] LustreError: 96493:0:(ldlm_lib.c:1178:target_handle_connect()) Skipped 2 previous similar messages [ 3759.642082] Lustre: DEBUG MARKER: == replay-single test 44b: race in target handle connect ========================================================== 10:31:49 (1786631509) [ 3761.771494] LustreError: 96493:0:(ldlm_lib.c:1436:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 3772.111958] Lustre: lustre-MDT0000: Export ffff9b38f1ce0800 already connecting from 192.168.202.37@tcp [ 3775.102262] Lustre: lustre-MDT0000: Export ffff9b38f1ce0800 already connecting from 192.168.202.37@tcp [ 3780.286613] Lustre: lustre-MDT0000: Export ffff9b38f1ce0800 already connecting from 192.168.202.37@tcp [ 3785.282656] Lustre: lustre-MDT0000: Export ffff9b38f1ce0800 already connecting from 192.168.202.37@tcp [ 3790.524117] Lustre: lustre-MDT0000: Export ffff9b38f1ce0800 already connecting from 192.168.202.37@tcp [ 3800.764261] Lustre: lustre-MDT0000: Export ffff9b38f1ce0800 already connecting from 192.168.202.37@tcp [ 3800.774587] Lustre: Skipped 1 previous similar message [ 3801.775282] LustreError: 96493:0:(ldlm_lib.c:1436:target_handle_connect()) cfs_fail_timeout id 704 awake [ 3801.781913] Lustre: 96493:0:(service.c:2582:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/20s); client may timeout req@ffff9b39001a4e00 x1873415090313088/t0(0) o38->9ec6cbd8-2c30-4333-93cc-d1e175076eca@192.168.202.37@tcp:0/0 lens 520/416 e 0 to 0 dl 1786631532 ref 1 fl Complete:H/200/0 rc 0/0 job:'lctl.0' uid:0 gid:0 projid:4294967295 [ 3805.884651] Lustre: lustre-MDT0000: Client 9ec6cbd8-2c30-4333-93cc-d1e175076eca (at 192.168.202.37@tcp) reconnecting [ 3805.896540] Lustre: Skipped 3 previous similar messages [ 3805.909675] LustreError: 96492:0:(ldlm_lib.c:1436:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 3831.485149] Lustre: lustre-MDT0000: Export ffff9b38f1ce0800 already connecting from 192.168.202.37@tcp [ 3845.919822] LustreError: 96492:0:(ldlm_lib.c:1436:target_handle_connect()) cfs_fail_timeout id 704 awake [ 3845.933819] Lustre: 96492:0:(service.c:2582:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/20s); client may timeout req@ffff9b38e72dce00 x1873415090316160/t0(0) o38->9ec6cbd8-2c30-4333-93cc-d1e175076eca@192.168.202.37@tcp:0/0 lens 520/416 e 0 to 0 dl 1786631577 ref 1 fl Complete:H/200/0 rc 0/0 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3846.843992] LustreError: 96493:0:(ldlm_lib.c:1436:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 3872.446464] Lustre: lustre-MDT0000: Export ffff9b38f1ce0800 already connecting from 192.168.202.37@tcp [ 3872.453509] Lustre: Skipped 2 previous similar messages [ 3886.855249] LustreError: 96493:0:(ldlm_lib.c:1436:target_handle_connect()) cfs_fail_timeout id 704 awake [ 3886.864461] Lustre: 96493:0:(service.c:2582:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/20s); client may timeout req@ffff9b38f179c380 x1873415090317824/t0(0) o38->9ec6cbd8-2c30-4333-93cc-d1e175076eca@192.168.202.37@tcp:0/0 lens 520/416 e 0 to 0 dl 1786631618 ref 1 fl Complete:H/200/0 rc 0/0 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3887.812446] Lustre: lustre-MDT0000: Client 9ec6cbd8-2c30-4333-93cc-d1e175076eca (at 192.168.202.37@tcp) reconnecting [ 3887.831367] Lustre: Skipped 1 previous similar message [ 3887.835686] LustreError: 98502:0:(ldlm_lib.c:1436:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 3927.863117] LustreError: 98502:0:(ldlm_lib.c:1436:target_handle_connect()) cfs_fail_timeout id 704 awake [ 3927.873415] Lustre: 98502:0:(service.c:2582:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/21s); client may timeout req@ffff9b38c5bdc380 x1873415090319616/t0(0) o38->9ec6cbd8-2c30-4333-93cc-d1e175076eca@192.168.202.37@tcp:0/0 lens 520/416 e 0 to 0 dl 1786631658 ref 1 fl Complete:H/200/0 rc 0/0 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3928.763118] LustreError: 96492:0:(ldlm_lib.c:1436:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 3954.365134] Lustre: lustre-MDT0000: Export ffff9b38f1ce0800 already connecting from 192.168.202.37@tcp [ 3954.371823] Lustre: Skipped 6 previous similar messages [ 3968.855195] LustreError: 96492:0:(ldlm_lib.c:1436:target_handle_connect()) cfs_fail_timeout id 704 awake [ 3968.861447] Lustre: 96492:0:(service.c:2582:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/21s); client may timeout req@ffff9b38d084f480 x1873415090321536/t0(0) o38->9ec6cbd8-2c30-4333-93cc-d1e175076eca@192.168.202.37@tcp:0/0 lens 520/416 e 0 to 0 dl 1786631699 ref 1 fl Complete:H/200/0 rc 0/0 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3969.727287] LustreError: 96491:0:(ldlm_lib.c:1436:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 3990.824071] LustreError: 96491:0:(ldlm_lib.c:1436:target_handle_connect()) cfs_fail_timeout interrupted [ 3990.827846] Lustre: 96491:0:(service.c:2582:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/1s); client may timeout req@ffff9b38f8c53100 x1873415090323456/t0(0) o38->9ec6cbd8-2c30-4333-93cc-d1e175076eca@192.168.202.37@tcp:0/0 lens 520/416 e 0 to 0 dl 1786631740 ref 1 fl Complete:H/200/0 rc 0/0 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3996.508872] Lustre: DEBUG MARKER: == replay-single test 44c: race in target handle connect ========================================================== 10:35:46 (1786631746) [ 3999.833845] LustreError: 100346:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 3999.842661] LustreError: 100346:0:(osd_handler.c:715:osd_ro()) Skipped 6 previous similar messages [ 4000.828496] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4004.977352] Lustre: Failing over lustre-MDT0000 [ 4005.504040] Lustre: server umount lustre-MDT0000 complete [ 4013.000757] LustreError: MGC192.168.202.137@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4013.007230] LustreError: Skipped 5 previous similar messages [ 4013.038750] 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 [ 4013.048325] Lustre: Skipped 13 previous similar messages [ 4013.051455] LustreError: 101034:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4013.081769] LustreError: 101034:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 4 previous similar messages [ 4013.260146] Lustre: *** cfs_fail_loc=712, val=0*** [ 4013.263505] LustreError: 8780:0:(service.c:1394:ptlrpc_check_req()) @@@ Invalid replay without recovery req@ffff9b38d0b70000 x1873415113210240/t0(0) o400->lustre-MDT0000-mdtlov_UUID@0@lo:0/0 lens 224/0 e 0 to 0 dl 0 ref 1 fl New:/2c0/ffffffff rc 0/-1 job:'ptlrpcd_rcv.0' uid:0 gid:0 projid:4294967295 [ 4013.439735] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4013.443629] Lustre: Skipped 8 previous similar messages [ 4013.495843] Lustre: lustre-MDT0000: Aborting client recovery [ 4013.497744] LustreError: 101022:0:(ldlm_lib.c:3004:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 4013.502521] Lustre: 101070:0:(ldlm_lib.c:2404:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 4013.506388] Lustre: 101070:0:(ldlm_lib.c:2404:target_recovery_overseer()) Skipped 2 previous similar messages [ 4013.511466] Lustre: 101070:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 9ec6cbd8-2c30-4333-93cc-d1e175076eca@ [ 4013.516362] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 4013.552203] Lustre: lustre-MDT0000-osd: cancel update llog [0x2000182d0:0x1:0x0] [ 4013.643222] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2866 to 0x280000400:2913) [ 4013.649207] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2867 to 0x240000400:2945) [ 4018.420181] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4018.662475] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 4018.666899] Lustre: Skipped 14 previous similar messages [ 4025.331805] Lustre: Failing over lustre-MDT0000 [ 4025.555365] Lustre: server umount lustre-MDT0000 complete [ 4043.684227] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4043.686268] Lustre: Skipped 5 previous similar messages [ 4045.535098] Lustre: 3309:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786631780/real 1786631780] req@ffff9b38d1e6fb80 x1873415113219456/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786631796 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4045.561793] Lustre: 3309:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 46 previous similar messages [ 4048.247745] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4052.692274] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4052.713814] Lustre: Skipped 3 previous similar messages [ 4052.805295] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4052.812602] Lustre: Skipped 3 previous similar messages [ 4052.856447] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2866 to 0x280000400:2945) [ 4052.861693] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2867 to 0x240000400:2977) [ 4059.661683] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4061.803778] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4070.431057] Lustre: DEBUG MARKER: == replay-single test 45: Handle failed close ============ 10:37:00 (1786631820) [ 4070.575735] Lustre: lustre-MDT0000: Client 9ec6cbd8-2c30-4333-93cc-d1e175076eca (at 192.168.202.37@tcp) reconnecting [ 4070.580823] Lustre: Skipped 2 previous similar messages [ 4078.161078] Lustre: DEBUG MARKER: == replay-single test 46: Don't leak file handle after open resend (3325) ========================================================== 10:37:07 (1786631827) [ 4079.259492] Lustre: *** cfs_fail_loc=122, val=2147483648*** [ 4079.265438] LustreError: 101991:0:(ldlm_lib.c:3346:target_send_reply_msg()) @@@ dropping reply req@ffff9b38fa29b800 x1873415090379136/t0(0) o700->9ec6cbd8-2c30-4333-93cc-d1e175076eca@192.168.202.37@tcp:596/0 lens 264/248 e 0 to 0 dl 1786631841 ref 1 fl Interpret:/200/0 rc 0/0 job:'touch.0' uid:0 gid:0 projid:4294967295 [ 4099.767275] Lustre: Failing over lustre-MDT0000 [ 4100.166847] Lustre: server umount lustre-MDT0000 complete [ 4127.632938] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2979 to 0x240000400:3009) [ 4127.637136] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2947 to 0x280000400:2977) [ 4133.140743] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4145.142216] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4146.745942] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4159.680793] Lustre: DEBUG MARKER: == replay-single test 47: MDS->OSC failure during precreate cleanup (2824) ========================================================== 10:38:29 (1786631909) [ 4162.932462] Lustre: Failing over lustre-OST0000 [ 4163.068243] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 4163.085413] LustreError: 36630:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4163.115785] Lustre: server umount lustre-OST0000 complete [ 4188.605354] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4197.871662] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 4199.509755] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4271.920460] Lustre: DEBUG MARKER: == replay-single test 48: MDS->OSC failure during precreate cleanup (2824) ========================================================== 10:40:21 (1786632021) [ 4276.064742] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4278.313513] Lustre: Failing over lustre-MDT0000 [ 4278.648730] Lustre: server umount lustre-MDT0000 complete [ 4301.915456] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4306.226738] Lustre: *** cfs_fail_loc=216, val=0*** [ 4306.227358] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3030 to 0x240000400:3073) [ 4306.230652] LustreError: 106839:0:(osp_precreate.c:974:osp_precreate_cleanup_orphans()) lustre-OST0001-osc-MDT0000: cannot cleanup orphans: rc = -30 [ 4307.232842] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2998 to 0x280000400:3041) [ 4374.906649] Lustre: DEBUG MARKER: == replay-single test 50: Double OSC recovery, don't LASSERT (3812) ========================================================== 10:42:04 (1786632124) [ 4376.557656] Lustre: lustre-OST0000: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnecting [ 4376.562792] Lustre: Skipped 2 previous similar messages [ 4389.171446] Lustre: DEBUG MARKER: == replay-single test 52: time out lock replay (3764) ==== 10:42:19 (1786632139) [ 4392.412918] Lustre: Failing over lustre-MDT0000 [ 4392.647254] LustreError: 107266:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.202.37@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4392.659485] LustreError: 107266:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 7 previous similar messages [ 4392.736982] Lustre: server umount lustre-MDT0000 complete [ 4413.132658] Lustre: *** cfs_fail_loc=157, val=2147483648*** [ 4413.136033] LustreError: 108479:0:(ldlm_lib.c:3346:target_send_reply_msg()) @@@ dropping reply req@ffff9b38f8c52d80 x1873415090495744/t0(0) o101->9ec6cbd8-2c30-4333-93cc-d1e175076eca@192.168.202.37@tcp:175/0 lens 328/344 e 0 to 0 dl 1786632175 ref 1 fl Complete:/240/0 rc 0/0 job:'ldlm_lock_repla.0' uid:0 gid:0 projid:4294967295 [ 4419.041471] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4429.499634] Lustre: lustre-MDT0000: Client 9ec6cbd8-2c30-4333-93cc-d1e175076eca (at 192.168.202.37@tcp) reconnected, waiting for 1 clients in recovery for 1:24 [ 4429.692938] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3053 to 0x280000400:3073) [ 4429.694650] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3084 to 0x240000400:3105) [ 4435.772705] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4437.443479] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4446.830278] Lustre: DEBUG MARKER: == replay-single test 53a: |X| close request while two MDC requests in flight ========================================================== 10:43:16 (1786632196) [ 4448.841702] Lustre: *** cfs_fail_loc=115, val=2147483648*** [ 4453.704387] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4455.783859] Lustre: Failing over lustre-MDT0000 [ 4456.156548] Lustre: server umount lustre-MDT0000 complete [ 4475.281706] Lustre: lustre-MDT0000: Not available for connect from 0@lo (not set up) [ 4476.983411] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3107 to 0x240000400:3137) [ 4476.984522] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3053 to 0x280000400:3105) [ 4481.262824] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4493.459688] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4495.000866] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4505.383626] Lustre: DEBUG MARKER: == replay-single test 53b: |X| open request while two MDC requests in flight ========================================================== 10:44:14 (1786632254) [ 4506.504497] Lustre: *** cfs_fail_loc=107, val=2147483648*** [ 4512.839285] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4515.206356] Lustre: Failing over lustre-MDT0000 [ 4515.704107] Lustre: server umount lustre-MDT0000 complete [ 4542.303614] LustreError: 3305:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9b38c7bf1f80 x1873415113359616/t0(0) o250->MGC192.168.202.137@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 0 ref 1 fl Rpc:NQU/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4547.469978] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3107 to 0x280000400:3137) [ 4547.473273] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3107 to 0x240000400:3169) [ 4547.685275] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4557.598486] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4559.275279] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4568.800309] Lustre: DEBUG MARKER: == replay-single test 53c: |X| open request and close request while two MDC requests in flight ========================================================== 10:45:18 (1786632318) [ 4569.822959] Lustre: *** cfs_fail_loc=107, val=2147483648*** [ 4575.539130] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4577.325241] Lustre: Failing over lustre-MDT0000 [ 4577.517464] Lustre: server umount lustre-MDT0000 complete [ 4610.874196] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3171 to 0x240000400:3201) [ 4610.883476] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3107 to 0x280000400:3169) [ 4611.341895] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4620.262216] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 4620.282659] Lustre: Skipped 16 previous similar messages [ 4623.374366] Lustre: DEBUG MARKER: == replay-single test 53d: close reply while two MDC requests in flight ========================================================== 10:46:13 (1786632373) [ 4625.680935] Lustre: *** cfs_fail_loc=13b, val=315*** [ 4625.684580] Lustre: *** cfs_fail_loc=13b, val=2147483648*** [ 4625.694309] LustreError: 113572:0:(ldlm_lib.c:3346:target_send_reply_msg()) @@@ dropping reply req@ffff9b38c7b05c00 x1873415090544640/t257698037777(0) o35->9ec6cbd8-2c30-4333-93cc-d1e175076eca@192.168.202.37@tcp:387/0 lens 392/456 e 0 to 0 dl 1786632387 ref 1 fl Interpret:/600/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 4628.752058] Lustre: Failing over lustre-MDT0000 [ 4629.126716] Lustre: server umount lustre-MDT0000 complete [ 4645.860467] Lustre: 3306:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786632381/real 1786632381] req@ffff9b38c7b07800 x1873415113388800/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786632397 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4645.885069] Lustre: 3306:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 54 previous similar messages [ 4645.891943] 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 [ 4645.909548] Lustre: Skipped 17 previous similar messages [ 4646.879170] LustreError: MGC192.168.202.137@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4646.882535] LustreError: Skipped 7 previous similar messages [ 4657.060475] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x70e172d4b117435c [ 4657.573051] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4657.578852] Lustre: Skipped 8 previous similar messages [ 4657.710963] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4657.717739] Lustre: Skipped 7 previous similar messages [ 4663.320806] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4667.133889] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4667.142955] Lustre: Skipped 7 previous similar messages [ 4667.244426] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4667.264679] Lustre: Skipped 7 previous similar messages [ 4667.283230] Lustre: 114878:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9b38d1e6fb80 x1873415090544640/t257698037777(0) o35->9ec6cbd8-2c30-4333-93cc-d1e175076eca@192.168.202.37@tcp:429/0 lens 392/456 e 0 to 0 dl 1786632429 ref 1 fl Interpret:/602/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 4667.332207] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3107 to 0x280000400:3201) [ 4667.333306] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3203 to 0x240000400:3233) [ 4673.940959] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4675.545965] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4684.747793] Lustre: DEBUG MARKER: == replay-single test 53e: |X| open reply while two MDC requests in flight ========================================================== 10:47:14 (1786632434) [ 4685.946369] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 4685.949315] LustreError: 114875:0:(ldlm_lib.c:3346:target_send_reply_msg()) @@@ dropping reply req@ffff9b38e68eaa00 x1873415090558464/t261993005072(0) o36->9ec6cbd8-2c30-4333-93cc-d1e175076eca@192.168.202.37@tcp:448/0 lens 504/448 e 0 to 0 dl 1786632448 ref 1 fl Interpret:/200/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 4690.957541] LustreError: 115958:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 4690.971331] LustreError: 115958:0:(osd_handler.c:715:osd_ro()) Skipped 4 previous similar messages [ 4692.068712] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4694.130916] Lustre: Failing over lustre-MDT0000 [ 4694.456163] Lustre: server umount lustre-MDT0000 complete [ 4718.101500] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4727.671815] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3107 to 0x280000400:3233) [ 4727.674988] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3235 to 0x240000400:3265) [ 4727.702684] Lustre: 116555:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9b37c7a50380 x1873415090558464/t261993005072(0) o36->9ec6cbd8-2c30-4333-93cc-d1e175076eca@192.168.202.37@tcp:489/0 lens 504/2880 e 0 to 0 dl 1786632489 ref 1 fl Interpret:/202/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 4734.281188] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4736.059942] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4744.578101] Lustre: DEBUG MARKER: == replay-single test 53f: |X| open reply and close reply while two MDC requests in flight ========================================================== 10:48:14 (1786632494) [ 4745.568409] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 4745.570310] LustreError: 116552:0:(ldlm_lib.c:3346:target_send_reply_msg()) @@@ dropping reply req@ffff9b38e663dc00 x1873415090572928/t266287972368(0) o36->9ec6cbd8-2c30-4333-93cc-d1e175076eca@192.168.202.37@tcp:507/0 lens 504/448 e 0 to 0 dl 1786632507 ref 1 fl Interpret:/200/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 4747.507989] Lustre: *** cfs_fail_loc=13b, val=315*** [ 4751.440484] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4753.736878] Lustre: Failing over lustre-MDT0000 [ 4754.105936] Lustre: server umount lustre-MDT0000 complete [ 4779.999933] LustreError: 3305:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9b38c7bf3800 x1873415113425792/t0(0) o250->MGC192.168.202.137@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 0 ref 1 fl Rpc:NQU/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4786.501833] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3235 to 0x240000400:3297) [ 4786.507076] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3235 to 0x280000400:3265) [ 4786.517973] Lustre: 118242:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9b390138bb80 x1873415090572928/t266287972368(0) o36->9ec6cbd8-2c30-4333-93cc-d1e175076eca@192.168.202.37@tcp:548/0 lens 504/2880 e 0 to 0 dl 1786632548 ref 1 fl Interpret:/202/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 4786.938690] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4799.851915] Lustre: DEBUG MARKER: == replay-single test 53g: |X| drop open reply and close request while close and open are both in flight ========================================================== 10:49:09 (1786632549) [ 4801.141658] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 4801.155438] Lustre: Skipped 1 previous similar message [ 4801.170578] LustreError: 118240:0:(ldlm_lib.c:3346:target_send_reply_msg()) @@@ dropping reply req@ffff9b38c7bf2a00 x1873415090585600/t270582939664(0) o36->9ec6cbd8-2c30-4333-93cc-d1e175076eca@192.168.202.37@tcp:563/0 lens 504/448 e 0 to 0 dl 1786632563 ref 1 fl Interpret:/200/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 4801.215525] LustreError: 118240:0:(ldlm_lib.c:3346:target_send_reply_msg()) Skipped 1 previous similar message [ 4803.161712] Lustre: *** cfs_fail_loc=115, val=2147483648*** [ 4803.169637] Lustre: Skipped 1 previous similar message [ 4808.060638] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4809.954807] Lustre: Failing over lustre-MDT0000 [ 4810.230231] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4810.234710] Lustre: Skipped 2 previous similar messages [ 4810.311145] Lustre: server umount lustre-MDT0000 complete [ 4835.577758] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4842.175112] Lustre: 119776:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9b38f7392680 x1873415090585600/t270582939664(0) o36->9ec6cbd8-2c30-4333-93cc-d1e175076eca@192.168.202.37@tcp:604/0 lens 504/2880 e 0 to 0 dl 1786632604 ref 1 fl Interpret:/202/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 4842.204710] Lustre: 119776:0:(mdt_recovery.c:102:mdt_req_from_lrd()) Skipped 1 previous similar message [ 4842.207642] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3267 to 0x280000400:3297) [ 4842.207853] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3235 to 0x240000400:3329) [ 4850.883102] Lustre: DEBUG MARKER: == replay-single test 53h: open request and close reply while two MDC requests in flight ========================================================== 10:50:00 (1786632600) [ 4852.252602] Lustre: *** cfs_fail_loc=107, val=2147483648*** [ 4854.188423] Lustre: *** cfs_fail_loc=13b, val=315*** [ 4854.193609] Lustre: *** cfs_fail_loc=13b, val=2147483648*** [ 4854.195555] LustreError: 119779:0:(ldlm_lib.c:3346:target_send_reply_msg()) @@@ dropping reply req@ffff9b38ef34c000 x1873415090598144/t274877906960(0) o35->9ec6cbd8-2c30-4333-93cc-d1e175076eca@192.168.202.37@tcp:616/0 lens 392/456 e 0 to 0 dl 1786632616 ref 1 fl Interpret:/600/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 4859.176713] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4861.054611] Lustre: Failing over lustre-MDT0000 [ 4861.420948] Lustre: server umount lustre-MDT0000 complete [ 4887.087915] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4893.549284] Lustre: 121225:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9b38f8c51880 x1873415090598144/t274877906960(0) o35->9ec6cbd8-2c30-4333-93cc-d1e175076eca@192.168.202.37@tcp:655/0 lens 392/456 e 0 to 0 dl 1786632655 ref 1 fl Interpret:/602/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 4893.575069] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3299 to 0x280000400:3329) [ 4893.575195] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3235 to 0x240000400:3361) [ 4904.744795] Lustre: DEBUG MARKER: == replay-single test 55: let MDS_CHECK_RESENT return the original return code instead of 0 ========================================================== 10:50:54 (1786632654) [ 4906.117849] Lustre: *** cfs_fail_loc=12b, val=2147483991*** [ 4906.132740] LustreError: 121224:0:(ldlm_lib.c:3346:target_send_reply_msg()) @@@ dropping reply req@ffff9b38ef306300 x1873415090608256/t279172874255(0) o101->9ec6cbd8-2c30-4333-93cc-d1e175076eca@192.168.202.37@tcp:668/0 lens 664/608 e 0 to 0 dl 1786632668 ref 1 fl Interpret:/600/0 rc 301/0 job:'touch.0' uid:0 gid:0 projid:0 [ 4922.568369] Lustre: lustre-MDT0000: Client 9ec6cbd8-2c30-4333-93cc-d1e175076eca (at 192.168.202.37@tcp) reconnecting [ 4922.584839] Lustre: Skipped 1 previous similar message [ 4922.611548] Lustre: 121224:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9b38e68e8a80 x1873415090608256/t279172874255(0) o101->9ec6cbd8-2c30-4333-93cc-d1e175076eca@192.168.202.37@tcp:684/0 lens 664/3488 e 0 to 0 dl 1786632684 ref 1 fl Interpret:/602/0 rc 0/0 job:'touch.0' uid:0 gid:0 projid:0 [ 4929.899126] Lustre: DEBUG MARKER: == replay-single test 56: don't replay a symlink open request (3440) ========================================================== 10:51:19 (1786632679) [ 4935.027827] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4936.555332] Lustre: Failing over lustre-MDT0000 [ 4937.001975] Lustre: server umount lustre-MDT0000 complete [ 4965.858892] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x70e172d4b11760eb [ 4972.376985] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4980.056448] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3331 to 0x280000400:3361) [ 4980.059332] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3235 to 0x240000400:3393) [ 4986.449324] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4988.015992] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5007.807220] Lustre: DEBUG MARKER: == replay-single test 57: test recovery from llog for setattr op ========================================================== 10:52:37 (1786632757) [ 5012.759933] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5014.782167] Lustre: Failing over lustre-MDT0000 [ 5015.171453] Lustre: server umount lustre-MDT0000 complete [ 5043.172676] LustreError: 3305:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9b39001a0380 x1873415113496320/t0(0) o250->MGC192.168.202.137@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 0 ref 1 fl Rpc:NQU/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5049.231711] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5056.905502] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3363 to 0x280000400:3393) [ 5056.906076] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3235 to 0x240000400:3425) [ 5063.986098] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5066.422666] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5075.470428] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 5088.809329] Lustre: DEBUG MARKER: == replay-single test 58a: test recovery from llog for setattr op (test llog_gen_rec) ========================================================== 10:53:58 (1786632838) [ 5133.596797] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5135.976974] Lustre: Failing over lustre-MDT0000 [ 5136.641822] Lustre: server umount lustre-MDT0000 complete [ 5161.370676] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5164.832043] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:4676 to 0x240000400:4705) [ 5164.833354] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:4644 to 0x280000400:4673) [ 5171.756224] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5173.269966] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5230.576716] Lustre: DEBUG MARKER: == replay-single test 58b: test replay of setxattr op ==== 10:56:20 (1786632980) [ 5235.559851] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5237.931305] Lustre: Failing over lustre-MDT0000 [ 5238.304970] Lustre: server umount lustre-MDT0000 complete [ 5254.624853] Lustre: 3307:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786632989/real 1786632989] req@ffff9b38d23bb800 x1873415114196992/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786633005 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5254.633863] LustreError: MGC192.168.202.137@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5254.668657] Lustre: 3307:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 59 previous similar messages [ 5254.668725] 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 [ 5254.682393] LustreError: Skipped 7 previous similar messages [ 5254.712909] Lustre: Skipped 15 previous similar messages [ 5263.844200] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x70e172d4b11b7216 [ 5263.869203] Lustre: MGC192.168.202.137@tcp: Connection restored to 0@lo (at 0@lo) [ 5263.871926] Lustre: Skipped 19 previous similar messages [ 5264.577046] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 5264.581020] Lustre: Skipped 7 previous similar messages [ 5264.686283] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 5264.710858] Lustre: Skipped 7 previous similar messages [ 5270.067831] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5276.540729] Lustre: lustre-MDT0000: Recovery over after 0:09, of 2 clients 2 recovered and 0 were evicted. [ 5276.558336] Lustre: Skipped 7 previous similar messages [ 5276.602435] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:4707 to 0x240000400:4737) [ 5276.606802] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:4644 to 0x280000400:4705) [ 5282.733646] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5284.990125] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5295.412747] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount FULL mgc.*.mgs_server_uuid 1475 0 [ 5297.082799] Lustre: DEBUG MARKER: mgc.*.mgs_server_uuid in FULL state after 0 sec [ 5304.144133] Lustre: DEBUG MARKER: == replay-single test 58c: resend/reconstruct setxattr op ========================================================== 10:57:33 (1786633053) [ 5310.822455] Lustre: *** cfs_fail_loc=123, val=2147483648*** [ 5329.960675] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 5329.978936] Lustre: Skipped 1 previous similar message [ 5329.993055] LustreError: 129223:0:(ldlm_lib.c:3346:target_send_reply_msg()) @@@ dropping reply req@ffff9b37c4daec50 x1873415093391232/t296352743435(0) o36->9ec6cbd8-2c30-4333-93cc-d1e175076eca@192.168.202.37@tcp:337/0 lens 66040/440 e 0 to 0 dl 1786633092 ref 1 fl Interpret:/600/0 rc 0/0 job:'setfattr.0' uid:0 gid:0 projid:0 [ 5346.509339] Lustre: 128665:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9b38c7797100 x1873415093391232/t296352743435(0) o36->9ec6cbd8-2c30-4333-93cc-d1e175076eca@192.168.202.37@tcp:353/0 lens 66040/440 e 0 to 0 dl 1786633108 ref 1 fl Interpret:/602/0 rc 0/0 job:'setfattr.0' uid:0 gid:0 projid:0 [ 5358.101412] Lustre: DEBUG MARKER: SKIP: replay-single test_59 skipping ALWAYS excluded test 59 [ 5359.988285] Lustre: DEBUG MARKER: == replay-single test 60: test llog post recovery init vs llog unlink ========================================================== 10:58:29 (1786633109) [ 5370.292550] LustreError: 130552:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 5370.297681] LustreError: 130552:0:(osd_handler.c:715:osd_ro()) Skipped 7 previous similar messages [ 5371.210281] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5374.786856] Lustre: Failing over lustre-MDT0000 [ 5375.257886] Lustre: server umount lustre-MDT0000 complete [ 5403.619052] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x70e172d4b11ba068 [ 5409.029609] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5418.174108] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 5418.192467] Lustre: Skipped 8 previous similar messages [ 5419.016090] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:4806 to 0x280000400:4833) [ 5419.018239] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:4839 to 0x240000400:4865) [ 5424.671929] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5426.312224] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5437.141721] Lustre: DEBUG MARKER: == replay-single test 61a: test race llog recovery vs llog cleanup ========================================================== 10:59:46 (1786633186) [ 5456.904968] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 5472.609511] Lustre: Failing over lustre-OST0000 [ 5472.752523] Lustre: server umount lustre-OST0000 complete [ 5474.797310] LustreError: 36629:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 5474.837149] LustreError: 36629:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 2 previous similar messages [ 5485.024096] LustreError: 127648:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 5485.052333] LustreError: 127648:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 1 previous similar message [ 5499.619433] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5514.147677] Lustre: Failing over lustre-OST0000 [ 5514.190580] LustreError: 133713:0:(ldlm_lib.c:3004:target_stop_recovery_thread()) lustre-OST0000: Aborting recovery [ 5514.210607] Lustre: 133138:0:(ldlm_lib.c:2404:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 5514.218667] Lustre: 133138:0:(ldlm_lib.c:2404:target_recovery_overseer()) Skipped 2 previous similar messages [ 5514.225550] Lustre: 133138:0:(ldlm_lib.c:1914:abort_req_replay_queue()) @@@ aborted: req@ffff9b37c6a99880 x1873415114281728/t0(17179870643) o6->lustre-MDT0000-mdtlov_UUID@0@lo:526/0 lens 544/0 e 2 to 0 dl 1786633281 ref 1 fl Complete:/204/ffffffff rc 0/-1 job:'osp-syn-0-0.0' uid:0 gid:0 projid:4294967295 [ 5514.258538] LustreError: 133138:0:(ofd_obd.c:1324:ofd_iocontrol()) lustre-OST0000: iocontrol from 'tgt_recover_0' cmd=c00866c1 _IOWR('f', 193, 8) unrecognized: rc = -25 [ 5514.262607] LustreError: lustre-OST0000-osc-MDT0000: operation ost_destroy to node 0@lo failed: rc = -19 [ 5514.290840] Lustre: lustre-OST0000: Not available for connect from 0@lo (stopping) [ 5514.427909] Lustre: server umount lustre-OST0000 complete [ 5519.329790] LustreError: 36626:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 5519.364563] LustreError: 36626:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 1 previous similar message [ 5540.137395] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5544.638245] LustreError: 3305:0:(client.c:3435:ptlrpc_replay_interpret()) @@@ status 0, old was -19 req@ffff9b38c4b7f800 x1873415114281728/t17179870643(17179870643) o6->lustre-OST0000-osc-MDT0000@0@lo:28/4 lens 544/432 e 3 to 0 dl 1786633313 ref 2 fl Interpret:RQU/204/0 rc 0/0 job:'osp-syn-0-0.0' uid:0 gid:0 projid:4294967295 [ 5550.442954] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 5552.024299] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 5592.263239] Lustre: DEBUG MARKER: == replay-single test 61b: test race mds llog sync vs llog cleanup ========================================================== 11:02:22 (1786633342) [ 5594.789545] Lustre: Failing over lustre-MDT0000 [ 5595.088270] Lustre: server umount lustre-MDT0000 complete [ 5622.771707] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x70e172d4b11caf07 [ 5627.303726] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5636.412155] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5266 to 0x240000400:5281) [ 5636.412506] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5234 to 0x280000400:5249) [ 5641.471649] Lustre: Failing over lustre-MDT0000 [ 5641.695613] Lustre: server umount lustre-MDT0000 complete [ 5669.091511] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x70e172d4b11cb1bc [ 5672.253995] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5266 to 0x240000400:5313) [ 5672.254783] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5234 to 0x280000400:5281) [ 5673.677571] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5682.666287] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5684.327425] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5693.884830] Lustre: DEBUG MARKER: == replay-single test 61c: test race mds llog sync vs llog cleanup ========================================================== 11:04:03 (1786633443) [ 5708.440491] Lustre: Failing over lustre-OST0000 [ 5709.802923] Lustre: lustre-OST0000: Not available for connect from 0@lo (stopping) [ 5710.615785] Lustre: server umount lustre-OST0000 complete [ 5713.097262] LustreError: 36628:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.202.37@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 5713.118160] LustreError: 36628:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 2 previous similar messages [ 5734.058308] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5743.300320] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 5744.557906] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 5754.112745] Lustre: DEBUG MARKER: == replay-single test 61d: error in llog_setup should cleanup the llog context correctly ========================================================== 11:05:03 (1786633503) [ 5756.039804] Lustre: Failing over lustre-MDT0000 [ 5756.364460] Lustre: server umount lustre-MDT0000 complete [ 5765.823349] Lustre: *** cfs_fail_loc=605, val=0*** [ 5765.829538] LustreError: 139722:0:(llog_obd.c:192:llog_setup()) MGS: ctxt 0 lop_setup=ffffffffc11f44b0 failed: rc = -95 [ 5765.855665] LustreError: 139722:0:(obd_config.c:845:class_setup()) setup MGS failed (-95) [ 5765.865383] LustreError: 139722:0:(obd_mount.c:259:lustre_start_simple()) MGS setup error -95 [ 5765.881405] LustreError: 139722:0:(tgt_mount.c:116:server_deregister_mount()) MGS not registered [ 5765.884680] LustreError: Failed to start MGS 'MGS' (-95). Is the 'mgs' module loaded? [ 5765.903279] LustreError: 139722:0:(tgt_mount.c:2129:server_put_super()) no obd lustre-MDT0000 [ 5766.011516] Lustre: server umount lustre-MDT0000 complete [ 5766.018880] LustreError: 139722:0:(super25.c:179:lustre_fill_super()) llite: Unable to mount : rc = -95 [ 5774.725304] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5283 to 0x280000400:5313) [ 5774.729306] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5315 to 0x240000400:5345) [ 5778.585775] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5785.886185] Lustre: DEBUG MARKER: == replay-single test 62: don't mis-drop resent replay === 11:05:36 (1786633536) [ 5789.442855] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5792.175915] Lustre: Failing over lustre-MDT0000 [ 5792.421734] Lustre: server umount lustre-MDT0000 complete [ 5821.637473] Lustre: *** cfs_fail_loc=707, val=0*** [ 5824.773806] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5837.032789] Lustre: lustre-MDT0000: Client 9ec6cbd8-2c30-4333-93cc-d1e175076eca (at 192.168.202.37@tcp) reconnected, waiting for 1 clients in recovery for 0:54 [ 5837.817945] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5358 to 0x240000400:5377) [ 5837.823655] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5327 to 0x280000400:5345) [ 5844.404342] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5846.302746] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5857.101748] Lustre: DEBUG MARKER: == replay-single test 65a: AT: verify early replies ====== 11:06:46 (1786633606) [ 5889.287320] LustreError: 141429:0:(service.c:2558:ptlrpc_server_handle_request()) @@@ HIT req@ffff9b390138aa00 x1873415094265472/t0(0) o101->9ec6cbd8-2c30-4333-93cc-d1e175076eca@192.168.202.37@tcp:141/0 lens 664/0 e 0 to 0 dl 1786633651 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 5889.301282] LustreError: 141429:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a sleeping for 11000ms [ 5900.351132] LustreError: 141429:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a awake [ 5900.378990] LustreError: 141431:0:(service.c:2558:ptlrpc_server_handle_request()) @@@ HIT req@ffff9b38c7b06680 x1873415094266240/t0(0) o35->9ec6cbd8-2c30-4333-93cc-d1e175076eca@192.168.202.37@tcp:158/0 lens 392/0 e 0 to 0 dl 1786633668 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 5902.904540] LustreError: 142867:0:(service.c:2558:ptlrpc_server_handle_request()) @@@ HIT req@ffff9b38c7b56a00 x1873415094272128/t0(0) o101->9ec6cbd8-2c30-4333-93cc-d1e175076eca@192.168.202.37@tcp:194/0 lens 576/0 e 0 to 0 dl 1786633704 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'unlinkmany.0' uid:0 gid:0 projid:0 [ 5902.936251] LustreError: 142867:0:(service.c:2558:ptlrpc_server_handle_request()) Skipped 27 previous similar messages [ 5909.691735] LustreError: 36629:0:(service.c:2558:ptlrpc_server_handle_request()) @@@ HIT req@ffff9b37c7a52a00 x1873415114503552/t0(0) o6->lustre-MDT0000-mdtlov_UUID@0@lo:161/0 lens 544/0 e 0 to 0 dl 1786633671 ref 1 fl Interpret:/200/ffffffff rc 0/-1 job:'osp-syn-1-0.0' uid:0 gid:0 projid:4294967295 [ 5909.723838] LustreError: 36629:0:(service.c:2558:ptlrpc_server_handle_request()) Skipped 26 previous similar messages [ 5919.092483] Lustre: DEBUG MARKER: == replay-single test 65b: AT: verify early replies on packed reply / bulk ========================================================== 11:07:48 (1786633668) [ 5950.548101] LustreError: 6695:0:(tgt_handler.c:2830:tgt_brw_write()) cfs_fail_timeout id 224 sleeping for 11000ms [ 5961.583143] LustreError: 6695:0:(tgt_handler.c:2830:tgt_brw_write()) cfs_fail_timeout id 224 awake [ 5972.770642] Lustre: DEBUG MARKER: == replay-single test 66a: AT: verify MDT service time adjusts with no early replies ========================================================== 11:08:42 (1786633722) [ 6003.184855] LustreError: 142708:0:(service.c:2558:ptlrpc_server_handle_request()) @@@ HIT req@ffff9b38d1e6f480 x1873415094288256/t0(0) o101->9ec6cbd8-2c30-4333-93cc-d1e175076eca@192.168.202.37@tcp:255/0 lens 576/0 e 0 to 0 dl 1786633765 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 6003.199535] LustreError: 142708:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a sleeping for 5000ms [ 6008.207132] LustreError: 142708:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a awake [ 6015.529740] LustreError: 35018:0:(service.c:2558:ptlrpc_server_handle_request()) @@@ HIT req@ffff9b38f7392300 x1873415114526336/t0(0) o6->lustre-MDT0000-mdtlov_UUID@0@lo:267/0 lens 544/0 e 0 to 0 dl 1786633777 ref 1 fl Interpret:/200/ffffffff rc 0/-1 job:'osp-syn-0-0.0' uid:0 gid:0 projid:4294967295 [ 6015.553201] LustreError: 35018:0:(service.c:2558:ptlrpc_server_handle_request()) Skipped 108 previous similar messages [ 6020.503951] LustreError: 141430:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a awake [ 6037.811864] Lustre: DEBUG MARKER: == replay-single test 66b: AT: verify net latency adjusts ========================================================== 11:09:47 (1786633787) [ 6142.376892] Lustre: DEBUG MARKER: == replay-single test 67a: AT: verify slow request processing doesn't induce reconnects ========================================================== 11:11:31 (1786633891) [ 6171.863160] LustreError: 141429:0:(service.c:2558:ptlrpc_server_handle_request()) @@@ HIT req@ffff9b3901388e00 x1873415094364928/t0(0) o101->9ec6cbd8-2c30-4333-93cc-d1e175076eca@192.168.202.37@tcp:424/0 lens 576/0 e 0 to 0 dl 1786633934 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 6171.888572] LustreError: 141429:0:(service.c:2558:ptlrpc_server_handle_request()) Skipped 101 previous similar messages [ 6171.894699] LustreError: 141429:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a sleeping for 400ms [ 6171.903191] LustreError: 141429:0:(service.c:2559:ptlrpc_server_handle_request()) Skipped 1 previous similar message [ 6172.327206] LustreError: 141429:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a awake [ 6188.286744] LustreError: 141431:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a sleeping for 400ms [ 6188.302167] LustreError: 141431:0:(service.c:2559:ptlrpc_server_handle_request()) Skipped 37 previous similar messages [ 6188.743143] LustreError: 141431:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a awake [ 6188.751570] LustreError: 141431:0:(service.c:2559:ptlrpc_server_handle_request()) Skipped 37 previous similar messages [ 6203.867306] LustreError: 141430:0:(service.c:2558:ptlrpc_server_handle_request()) @@@ HIT req@ffff9b38d084f480 x1873415094382848/t0(0) o101->9ec6cbd8-2c30-4333-93cc-d1e175076eca@192.168.202.37@tcp:456/0 lens 576/0 e 0 to 0 dl 1786633966 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'unlinkmany.0' uid:0 gid:0 projid:0 [ 6203.890387] LustreError: 141430:0:(service.c:2558:ptlrpc_server_handle_request()) Skipped 75 previous similar messages [ 6228.238806] Lustre: DEBUG MARKER: == replay-single test 67b: AT: verify instant slowdown doesn't induce reconnects ========================================================== 11:12:57 (1786633977) [ 6265.074351] Lustre: DEBUG MARKER: phase 2 [ 6275.600314] Lustre: DEBUG MARKER: == replay-single test 68: AT: verify slowing locks ======= 11:13:45 (1786634025) [ 6358.624377] Lustre: DEBUG MARKER: == replay-single test 70a: check multi client t-f ======== 11:15:08 (1786634108) [ 6360.277108] Lustre: DEBUG MARKER: SKIP: replay-single test_70a Need two or more clients, have 1 [ 6361.855253] Lustre: DEBUG MARKER: == replay-single test 70b: dbench 1mdts recovery; 1 clients ========================================================== 11:15:11 (1786634111) [ 6366.471678] Lustre: DEBUG MARKER: Started rundbench load pid=128841 ... [ 6370.878535] LustreError: 148240:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 6370.887287] LustreError: 148240:0:(osd_handler.c:715:osd_ro()) Skipped 2 previous similar messages [ 6372.217346] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 6375.175655] Lustre: DEBUG MARKER: test_70b fail mds1 1 times [ 6376.891504] Lustre: Failing over lustre-MDT0000 [ 6376.928194] 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 [ 6376.935698] Lustre: Skipped 13 previous similar messages [ 6377.167514] Lustre: server umount lustre-MDT0000 complete [ 6395.591204] LustreError: MGC192.168.202.137@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 6395.605185] LustreError: Skipped 5 previous similar messages [ 6396.139278] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 6396.144518] Lustre: Skipped 8 previous similar messages [ 6396.265236] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 6396.276532] Lustre: Skipped 8 previous similar messages [ 6397.103924] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 6397.115747] Lustre: Skipped 17 previous similar messages [ 6400.913607] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6415.554938] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 6415.558769] Lustre: Skipped 7 previous similar messages [ 6416.345508] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 6416.348433] Lustre: Skipped 8 previous similar messages [ 6416.432488] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5426 to 0x280000400:5441) [ 6416.432689] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5479 to 0x240000400:5505) [ 6423.761174] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6425.501459] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6433.501133] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 6436.327612] Lustre: DEBUG MARKER: test_70b fail mds1 2 times [ 6438.277121] Lustre: Failing over lustre-MDT0000 [ 6438.374980] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 6438.546596] Lustre: server umount lustre-MDT0000 complete [ 6463.497372] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6476.895791] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5469 to 0x280000400:5505) [ 6476.897536] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5532 to 0x240000400:5569) [ 6483.439040] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6485.121409] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6517.186192] Lustre: DEBUG MARKER: == replay-single test 70c: tar 1mdts recovery ============ 11:17:47 (1786634267) [ 6642.267282] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 6654.958103] Lustre: DEBUG MARKER: test_70c fail mds1 1 times [ 6657.096885] Lustre: Failing over lustre-MDT0000 [ 6657.484780] Lustre: server umount lustre-MDT0000 complete [ 6675.362263] Lustre: 3307:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786634410/real 1786634410] req@ffff9b38ffa62a00 x1873415115287040/t0(0) o400->MGC192.168.202.137@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1786634426 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6675.383752] Lustre: 3307:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 48 previous similar messages [ 6690.941479] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6701.748566] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6349 to 0x240000400:6369) [ 6701.772643] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6285 to 0x280000400:6305) [ 6707.965925] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6709.923824] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6788.788498] Lustre: DEBUG MARKER: == replay-single test 70d: mkdir/rmdir striped dir 1mdts recovery ========================================================== 11:22:18 (1786634538) [ 6790.461576] Lustre: DEBUG MARKER: SKIP: replay-single test_70d needs >= 2 MDTs [ 6792.174236] Lustre: DEBUG MARKER: == replay-single test 70e: rename cross-MDT with random fails ========================================================== 11:22:22 (1786634542) [ 6793.807319] Lustre: DEBUG MARKER: SKIP: replay-single test_70e needs >= 2 MDTs [ 6795.607185] Lustre: DEBUG MARKER: == replay-single test 70f: OSS O_DIRECT recovery with 1 clients ========================================================== 11:22:25 (1786634545) [ 6804.080525] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 6806.961860] Lustre: DEBUG MARKER: test_70f failing OST 1 times [ 6809.164791] Lustre: Failing over lustre-OST0000 [ 6809.237350] Lustre: server umount lustre-OST0000 complete [ 6809.572355] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 6809.589953] LustreError: 8780:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 6809.606716] LustreError: 8780:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 5 previous similar messages [ 6817.982747] LustreError: 36629:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.202.37@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 6818.026027] LustreError: 36629:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 2 previous similar messages [ 6836.494718] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6847.930744] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 6849.682686] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 6860.433790] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 6863.253698] Lustre: DEBUG MARKER: test_70f failing OST 2 times [ 6865.210545] Lustre: Failing over lustre-OST0000 [ 6865.329927] Lustre: server umount lustre-OST0000 complete [ 6866.405103] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 6866.416370] LustreError: 35019:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 6866.435835] LustreError: 35019:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 5 previous similar messages [ 6892.367141] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6903.293492] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 6905.203556] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 6916.503838] Lustre: DEBUG MARKER: == replay-single test 71a: mkdir/rmdir striped dir with 2 mdts recovery ========================================================== 11:24:26 (1786634666) [ 6918.030845] Lustre: DEBUG MARKER: SKIP: replay-single test_71a needs >= 2 MDTs [ 6919.509413] Lustre: DEBUG MARKER: == replay-single test 73a: open(O_CREAT), unlink, replay, reconnect before open replay, close ========================================================== 11:24:29 (1786634669) [ 6923.557714] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 6926.432329] Lustre: Failing over lustre-MDT0000 [ 6926.655177] Lustre: server umount lustre-MDT0000 complete [ 6945.990697] Lustre: *** cfs_fail_loc=302, val=2147483648*** [ 6946.402207] Lustre: 3308:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786634681/real 1786634681] req@ffff9b38e70bfb80 x1873415115713152/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786634697 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6946.439763] Lustre: 3308:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 8 previous similar messages [ 6950.241378] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6962.416395] Lustre: lustre-MDT0000: Client 9ec6cbd8-2c30-4333-93cc-d1e175076eca (at 192.168.202.37@tcp) reconnected, waiting for 1 clients in recovery for 0:53 [ 6962.719075] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6533 to 0x280000400:6561) [ 6962.721893] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6598 to 0x240000400:6625) [ 6968.515162] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6969.813496] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6978.746942] Lustre: DEBUG MARKER: == replay-single test 73b: open(O_CREAT), unlink, replay, reconnect at open_replay reply, close ========================================================== 11:25:28 (1786634728) [ 6982.957143] LustreError: 158446:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 6982.962632] LustreError: 158446:0:(osd_handler.c:715:osd_ro()) Skipped 5 previous similar messages [ 6984.258870] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 6987.724191] Lustre: Failing over lustre-MDT0000 [ 6988.095096] Lustre: server umount lustre-MDT0000 complete [ 7008.004938] LustreError: MGC192.168.202.137@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 7008.011628] LustreError: Skipped 3 previous similar messages [ 7008.209319] 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 [ 7008.218864] Lustre: Skipped 9 previous similar messages [ 7008.222886] LustreError: 159091:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 7008.244322] LustreError: 159091:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 6 previous similar messages [ 7008.526552] Lustre: lustre-MDT0000: Not available for connect from 192.168.202.37@tcp (not set up) [ 7008.547092] Lustre: Skipped 1 previous similar message [ 7008.826356] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 7008.831453] Lustre: Skipped 5 previous similar messages [ 7008.902415] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 7008.910794] Lustre: Skipped 5 previous similar messages [ 7010.359260] Lustre: *** cfs_fail_loc=157, val=2147483648*** [ 7010.370063] LustreError: 159111:0:(ldlm_lib.c:3346:target_send_reply_msg()) @@@ dropping reply req@ffff9b38e70bfb80 x1873415102948736/t335007449091(335007449091) o101->9ec6cbd8-2c30-4333-93cc-d1e175076eca@192.168.202.37@tcp:507/0 lens 592/608 e 0 to 0 dl 1786634772 ref 1 fl Interpret:/604/0 rc 301/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 7013.397511] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7013.872073] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 7013.881887] Lustre: Skipped 9 previous similar messages [ 7025.880325] Lustre: lustre-MDT0000: Client 9ec6cbd8-2c30-4333-93cc-d1e175076eca (at 192.168.202.37@tcp) reconnected, waiting for 1 clients in recovery for 0:54 [ 7025.900270] Lustre: 159091:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9b38dfecd180 x1873415102948736/t335007449091(335007449091) o101->9ec6cbd8-2c30-4333-93cc-d1e175076eca@192.168.202.37@tcp:523/0 lens 592/3488 e 0 to 0 dl 1786634788 ref 1 fl Interpret:/606/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 7025.978945] Lustre: lustre-MDT0000: Recovery over after 0:15, of 1 clients 1 recovered and 0 were evicted. [ 7025.987699] Lustre: Skipped 5 previous similar messages [ 7026.017794] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6598 to 0x240000400:6657) [ 7026.018679] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6563 to 0x280000400:6593) [ 7033.003304] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 7035.050310] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7044.889180] Lustre: DEBUG MARKER: == replay-single test 74: Ensure applications don't fail waiting for OST recovery ========================================================== 11:26:34 (1786634794) [ 7049.192907] Lustre: Failing over lustre-OST0000 [ 7049.307250] Lustre: server umount lustre-OST0000 complete [ 7053.445174] Lustre: Failing over lustre-MDT0000 [ 7053.917659] Lustre: server umount lustre-MDT0000 complete [ 7080.419807] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x70e172d4b125ab13 [ 7080.808483] LustreError: 36626:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 7080.823817] LustreError: 36626:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 1 previous similar message [ 7081.123458] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6563 to 0x280000400:6625) [ 7086.578772] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7096.292752] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 7096.298660] Lustre: Skipped 6 previous similar messages [ 7096.454457] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6598 to 0x240000400:6689) [ 7101.882797] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7113.274155] Lustre: DEBUG MARKER: == replay-single test 80a: DNE: create remote dir, drop update rep from MDT0, fail MDT0 ========================================================== 11:27:42 (1786634862) [ 7114.943655] Lustre: DEBUG MARKER: SKIP: replay-single test_80a needs >= 2 MDTs [ 7117.084239] Lustre: DEBUG MARKER: == replay-single test 80b: DNE: create remote dir, drop update rep from MDT0, fail MDT1 ========================================================== 11:27:46 (1786634866) [ 7118.742688] Lustre: DEBUG MARKER: SKIP: replay-single test_80b needs >= 2 MDTs [ 7120.597939] Lustre: DEBUG MARKER: == replay-single test 80c: DNE: create remote dir, drop update rep from MDT1, fail MDT[0,1] ========================================================== 11:27:50 (1786634870) [ 7122.308144] Lustre: DEBUG MARKER: SKIP: replay-single test_80c needs >= 2 MDTs [ 7123.645992] Lustre: DEBUG MARKER: == replay-single test 80d: DNE: create remote dir, drop update rep from MDT1, fail 2 MDTs ========================================================== 11:27:53 (1786634873) [ 7125.405991] Lustre: DEBUG MARKER: SKIP: replay-single test_80d needs >= 2 MDTs [ 7127.489434] Lustre: DEBUG MARKER: == replay-single test 80e: DNE: create remote dir, drop MDT1 rep, fail MDT0 ========================================================== 11:27:57 (1786634877) [ 7129.268346] Lustre: DEBUG MARKER: SKIP: replay-single test_80e needs >= 2 MDTs [ 7131.216955] Lustre: DEBUG MARKER: == replay-single test 80f: DNE: create remote dir, drop MDT1 rep, fail MDT1 ========================================================== 11:28:00 (1786634880) [ 7132.839697] Lustre: DEBUG MARKER: SKIP: replay-single test_80f needs >= 2 MDTs [ 7134.796834] Lustre: DEBUG MARKER: == replay-single test 80g: DNE: create remote dir, drop MDT1 rep, fail MDT0, then MDT1 ========================================================== 11:28:04 (1786634884) [ 7136.321910] Lustre: DEBUG MARKER: SKIP: replay-single test_80g needs >= 2 MDTs [ 7138.166171] Lustre: DEBUG MARKER: == replay-single test 80h: DNE: create remote dir, drop MDT1 rep, fail 2 MDTs ========================================================== 11:28:08 (1786634888) [ 7140.047930] Lustre: DEBUG MARKER: SKIP: replay-single test_80h needs >= 2 MDTs [ 7142.066904] Lustre: DEBUG MARKER: == replay-single test 81a: DNE: unlink remote dir, drop MDT0 update rep, fail MDT1 ========================================================== 11:28:11 (1786634891) [ 7143.525132] Lustre: DEBUG MARKER: SKIP: replay-single test_81a needs >= 2 MDTs [ 7145.735802] Lustre: DEBUG MARKER: == replay-single test 81b: DNE: unlink remote dir, drop MDT0 update reply, fail MDT0 ========================================================== 11:28:15 (1786634895) [ 7147.834861] Lustre: DEBUG MARKER: SKIP: replay-single test_81b needs >= 2 MDTs [ 7149.756802] Lustre: DEBUG MARKER: == replay-single test 81c: DNE: unlink remote dir, drop MDT0 update reply, fail MDT0,MDT1 ========================================================== 11:28:19 (1786634899) [ 7151.775753] Lustre: DEBUG MARKER: SKIP: replay-single test_81c needs >= 2 MDTs [ 7153.917784] Lustre: DEBUG MARKER: == replay-single test 81d: DNE: unlink remote dir, drop MDT0 update reply, fail 2 MDTs ========================================================== 11:28:23 (1786634903) [ 7155.511051] Lustre: DEBUG MARKER: SKIP: replay-single test_81d needs >= 2 MDTs [ 7157.047644] Lustre: DEBUG MARKER: == replay-single test 81e: DNE: unlink remote dir, drop MDT1 req reply, fail MDT0 ========================================================== 11:28:27 (1786634907) [ 7158.452452] Lustre: DEBUG MARKER: SKIP: replay-single test_81e needs >= 2 MDTs [ 7160.128665] Lustre: DEBUG MARKER: == replay-single test 81f: DNE: unlink remote dir, drop MDT1 req reply, fail MDT1 ========================================================== 11:28:30 (1786634910) [ 7161.640695] Lustre: DEBUG MARKER: SKIP: replay-single test_81f needs >= 2 MDTs [ 7163.091560] Lustre: DEBUG MARKER: == replay-single test 81g: DNE: unlink remote dir, drop req reply, fail M0, then M1 ========================================================== 11:28:33 (1786634913) [ 7164.786361] Lustre: DEBUG MARKER: SKIP: replay-single test_81g needs >= 2 MDTs [ 7166.573511] Lustre: DEBUG MARKER: == replay-single test 81h: DNE: unlink remote dir, drop request reply, fail 2 MDTs ========================================================== 11:28:36 (1786634916) [ 7167.975523] Lustre: DEBUG MARKER: SKIP: replay-single test_81h needs >= 2 MDTs [ 7169.660979] Lustre: DEBUG MARKER: == replay-single test 84a: stale open during export disconnect ========================================================== 11:28:39 (1786634919) [ 7171.475904] Lustre: 163728:0:(genops.c:1795:obd_export_evict_by_uuid()) lustre-MDT0000: evicting dd6dc492-e793-43cc-911f-3e49d4d3442f at adminstrative request [ 7182.927851] Lustre: DEBUG MARKER: == replay-single test 85a: check the cancellation of unused locks during recovery(IBITS) ========================================================== 11:28:52 (1786634932) [ 7191.372595] Lustre: Failing over lustre-MDT0000 [ 7191.894203] Lustre: server umount lustre-MDT0000 complete [ 7208.927103] Lustre: 3308:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786634944/real 1786634944] req@ffff9b38d8381500 x1873415115781376/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786634960 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 7208.974392] Lustre: 3308:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 18 previous similar messages [ 7219.172936] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x70e172d4b125d146 [ 7225.565109] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7233.521591] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6677 to 0x280000400:6721) [ 7233.522268] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6741 to 0x240000400:6785) [ 7238.991545] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 7241.021229] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7251.152320] Lustre: DEBUG MARKER: == replay-single test 85b: check the cancellation of unused locks during recovery(EXTENT) ========================================================== 11:30:00 (1786635000) [ 7268.485424] Lustre: Failing over lustre-OST0000 [ 7268.553117] Lustre: lustre-OST0000: Not available for connect from 192.168.202.37@tcp (stopping) [ 7268.654047] Lustre: server umount lustre-OST0000 complete [ 7269.867150] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 7269.886169] LustreError: 36626:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 7269.918540] LustreError: 36626:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 5 previous similar messages [ 7299.048776] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7310.723531] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 7312.227276] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 7323.650310] Lustre: DEBUG MARKER: == replay-single test 86: umount server after clear nid_stats should not hit LBUG ========================================================== 11:31:13 (1786635073) [ 7329.718569] Lustre: Failing over lustre-MDT0000 [ 7330.052216] Lustre: server umount lustre-MDT0000 complete [ 7339.663959] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6677 to 0x280000400:6753) [ 7339.675863] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6886 to 0x240000400:6913) [ 7344.340544] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7354.645825] Lustre: DEBUG MARKER: == replay-single test 87a: write replay ================== 11:31:44 (1786635104) [ 7360.086820] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 7362.609466] Lustre: Failing over lustre-OST0000 [ 7362.649056] Lustre: server umount lustre-OST0000 complete [ 7389.879743] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7401.433545] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 7403.254353] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 7412.931218] Lustre: DEBUG MARKER: == replay-single test 87b: write replay with changed data (checksum resend) ========================================================== 11:32:42 (1786635162) [ 7418.697114] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 7422.830235] Lustre: Failing over lustre-OST0000 [ 7422.888378] Lustre: server umount lustre-OST0000 complete [ 7443.389174] LustreError: lustre-OST0000: BAD WRITE CHECKSUM: from 12345-192.168.202.37@tcp inode [0x2000284a1:0x5:0x0] object 0x240000400:6914 extent [0-1048575]: client csum a18b803b, server csum 7c36e0d1 [ 7448.094529] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7458.437317] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 7460.409739] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 7469.262816] Lustre: DEBUG MARKER: == replay-single test 88: MDS should not assign same objid to different files ========================================================== 11:33:39 (1786635219) [ 7473.335222] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 7477.339360] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 7483.987031] Lustre: Failing over lustre-MDT0000 [ 7484.433871] Lustre: server umount lustre-MDT0000 complete [ 7488.891197] LustreError: 152933:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1786635240 with bad export cookie 8133908659838519342 [ 7499.232656] Lustre: Failing over lustre-OST0000 [ 7499.295448] Lustre: server umount lustre-OST0000 complete [ 7508.961192] Lustre: 3306:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786635244/real 1786635244] req@ffff9b38c568bb80 x1873415115872000/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786635260 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 7509.015351] Lustre: 3306:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 12 previous similar messages [ 7526.076408] LustreError: 36635:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.202.37@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 7526.088523] LustreError: 36635:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 29 previous similar messages [ 7534.560542] LustreError: 3305:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9b38c568bb80 x1873415115873024/t0(0) o250->MGC192.168.202.137@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 0 ref 1 fl Rpc:NQU/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 7541.209801] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7547.283859] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6794 to 0x280000400:6817) [ 7566.928206] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6915 to 0x240000400:6945) [ 7569.234980] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7586.435859] Lustre: DEBUG MARKER: == replay-single test 89: no disk space leak on late ost connection ========================================================== 11:35:36 (1786635336) [ 7603.088622] Lustre: Failing over lustre-OST0000 [ 7603.240958] Lustre: server umount lustre-OST0000 complete [ 7607.760480] Lustre: Failing over lustre-MDT0000 [ 7607.780333] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 7608.254252] Lustre: server umount lustre-MDT0000 complete [ 7627.212657] LustreError: MGC192.168.202.137@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 7627.217514] LustreError: Skipped 4 previous similar messages [ 7627.837125] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 7627.842359] Lustre: Skipped 9 previous similar messages [ 7627.959832] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 7627.982312] Lustre: Skipped 7 previous similar messages [ 7628.700424] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 7628.710792] Lustre: Skipped 7 previous similar messages [ 7628.745279] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6794 to 0x280000400:6849) [ 7628.772916] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 7628.787160] Lustre: Skipped 14 previous similar messages [ 7632.371712] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7646.943034] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7649.408090] Lustre: lustre-OST0000: Denying connection for new client ba38d83f-a5c0-4291-bf5d-aa6d7de9f25f (at 192.168.202.37@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 1:06 [ 7649.438556] Lustre: Skipped 11 previous similar messages [ 7659.710668] Lustre: lustre-OST0000: Denying connection for new client ba38d83f-a5c0-4291-bf5d-aa6d7de9f25f (at 192.168.202.37@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 0:55 [ 7659.741232] Lustre: Skipped 1 previous similar message [ 7680.191179] Lustre: lustre-OST0000: Denying connection for new client ba38d83f-a5c0-4291-bf5d-aa6d7de9f25f (at 192.168.202.37@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 0:35 [ 7680.211327] Lustre: Skipped 3 previous similar messages [ 7715.500115] Lustre: lustre-OST0000: recovery is timed out, evict stale exports [ 7715.510807] Lustre: 176077:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-OST0000: disconnect stale client a01cbd54-1a7f-4047-a923-30cf703ef78b@ [ 7715.523358] Lustre: lustre-OST0000: disconnecting 1 stale clients [ 7715.629854] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6956 to 0x240000400:6977) [ 7719.076286] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 60 sec [ 7733.491842] Lustre: DEBUG MARKER: free_before: 7520256 free_after: 7520256 [ 7739.689720] Lustre: DEBUG MARKER: == replay-single test 90: lfs find identifies the missing striped file segments ========================================================== 11:38:09 (1786635489) [ 7743.856894] Lustre: Failing over lustre-OST0000 [ 7743.948980] Lustre: server umount lustre-OST0000 complete [ 7746.528304] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 7746.536326] 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 [ 7746.545462] Lustre: Skipped 12 previous similar messages [ 7766.063549] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 7766.078756] Lustre: Skipped 8 previous similar messages [ 7770.569743] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7780.751179] Lustre: DEBUG MARKER: == replay-single test 93a: replay + reconnect ============ 11:38:50 (1786635530) [ 7784.799426] Lustre: Failing over lustre-OST0000 [ 7784.868122] Lustre: server umount lustre-OST0000 complete [ 7803.757338] LustreError: 179158:0:(ldlm_lib.c:2905:target_recovery_thread()) cfs_fail_timeout id 715 sleeping for 40000ms [ 7803.769746] LustreError: 179158:0:(ldlm_lib.c:2905:target_recovery_thread()) Skipped 80 previous similar messages [ 7807.525040] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7809.504806] Lustre: *** cfs_fail_loc=715, val=40*** [ 7819.231513] Lustre: lustre-OST0000: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnected, waiting for 2 clients in recovery for 1:25 [ 7820.005754] Lustre: lustre-OST0000: Client ba38d83f-a5c0-4291-bf5d-aa6d7de9f25f (at 192.168.202.37@tcp) reconnected, waiting for 2 clients in recovery for 1:24 [ 7825.392234] Lustre: *** cfs_fail_loc=715, val=40*** [ 7825.396872] Lustre: Skipped 1 previous similar message [ 7826.399670] Lustre: *** cfs_fail_loc=715, val=40*** [ 7835.616770] Lustre: lustre-OST0000: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnected, waiting for 2 clients in recovery for 1:08 [ 7841.759175] Lustre: *** cfs_fail_loc=715, val=40*** [ 7843.823507] LustreError: 179158:0:(ldlm_lib.c:2905:target_recovery_thread()) cfs_fail_timeout id 715 awake [ 7843.832323] LustreError: 179158:0:(ldlm_lib.c:2905:target_recovery_thread()) Skipped 80 previous similar messages [ 7849.611771] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 7851.235866] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 7861.045457] Lustre: DEBUG MARKER: == replay-single test 93b: replay + reconnect on mds ===== 11:40:10 (1786635610) [ 7865.245758] Lustre: Failing over lustre-MDT0000 [ 7865.739795] Lustre: server umount lustre-MDT0000 complete [ 7894.780158] LustreError: 180766:0:(ldlm_lib.c:2905:target_recovery_thread()) cfs_fail_timeout id 715 sleeping for 80000ms [ 7898.223860] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7901.151233] Lustre: *** cfs_fail_loc=715, val=80*** [ 7901.154203] Lustre: Skipped 1 previous similar message [ 7911.107354] Lustre: lustre-MDT0000: Client ba38d83f-a5c0-4291-bf5d-aa6d7de9f25f (at 192.168.202.37@tcp) reconnected, waiting for 1 clients in recovery for 0:53 [ 7911.123360] Lustre: Skipped 1 previous similar message [ 7917.535107] Lustre: *** cfs_fail_loc=715, val=80*** [ 7927.482978] Lustre: lustre-MDT0000: Client ba38d83f-a5c0-4291-bf5d-aa6d7de9f25f (at 192.168.202.37@tcp) reconnected, waiting for 1 clients in recovery for 0:37 [ 7933.919782] Lustre: *** cfs_fail_loc=715, val=80*** [ 7942.843411] Lustre: lustre-MDT0000: Client ba38d83f-a5c0-4291-bf5d-aa6d7de9f25f (at 192.168.202.37@tcp) reconnected, waiting for 1 clients in recovery for 0:21 [ 7959.227223] Lustre: lustre-MDT0000: Client ba38d83f-a5c0-4291-bf5d-aa6d7de9f25f (at 192.168.202.37@tcp) reconnected, waiting for 1 clients in recovery for 0:05 [ 7974.847101] LustreError: 180766:0:(ldlm_lib.c:2905:target_recovery_thread()) cfs_fail_timeout id 715 awake [ 7974.927640] Lustre: 180766:0:(ldlm_lib.c:2951:target_recovery_thread()) too long recovery - read logs [ 7974.934308] LustreError: dumping log to /tmp/lustre-log.1786635726.180766 [ 7975.203243] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6862 to 0x280000400:6881) [ 7975.203921] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6991 to 0x240000400:7009) [ 7981.951892] Lustre: DEBUG MARKER: oleg237-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 7983.678754] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7993.146558] Lustre: DEBUG MARKER: == replay-single test complete, duration 7690 sec ======== 11:42:22 (1786635742) [ 7995.010532] Lustre: DEBUG MARKER: === replay-single: start cleanup 11:42:24 (1786635744) === [ 8003.756136] Lustre: DEBUG MARKER: === replay-single: finish cleanup 11:42:33 (1786635753) === [ 8034.732983] Lustre: server umount lustre-MDT0000 complete [ 8038.909797] LustreError: 8518:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1786635790 with bad export cookie 8133908659838531837 [ 8049.185096] Lustre: server umount lustre-OST0000 complete [ 8053.248769] Lustre: server umount lustre-OST0001 complete [ 8067.301815] Lustre: DEBUG MARKER: oleg237-server.virtnet: executing unload_modules_local [ 8070.911906] Key type lgssc unregistered [ 8071.204403] LNet: 182905:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 8071.219280] LNetError: 182905:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 8072.295983] LNet: Removed LNI 192.168.202.137@tcp [ 8073.223197] Key type .llcrypt unregistered [ 8073.229512] Key type ._llcrypt unregistered