[ 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 465850633 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, 524580K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] ftrace: allocating 41240 entries in 162 pages [ 0.000000] ftrace: allocated 162 pages with 3 groups [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] rcu: RCU event tracing is enabled. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ 0.000000] rcu: RCU callback double-/use-after-free debug enabled. [ 0.000000] Rude variant of Tasks RCU enabled. [ 0.000000] Tracing variant of Tasks RCU enabled. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 0.000000] NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16 [ 0.000000] random: get_random_bytes called from start_kernel+0x622/0x9a8 with crng_init=0 [ 0.001000] Console: colour *CGA 80x25 [ 0.001000] printk: console [ttyS1] enabled [ 0.001000] ACPI: Core revision 20220331 [ 0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.001012] APIC: Switch to symmetric I/O mode setup [ 0.003198] x2apic enabled [ 0.004008] Switched APIC routing to physical x2apic. [ 0.005013] kvm-guest: setup PV IPIs [ 0.008457] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.009000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.009023] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.010014] pid_max: default: 32768 minimum: 301 [ 0.011138] LSM: Security Framework initializing [ 0.012054] Yama: becoming mindful. [ 0.013037] SELinux: Initializing. [ 0.014063] *** VALIDATE selinux *** [ 0.021822] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.025750] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.026152] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.027110] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.028117] *** VALIDATE tmpfs *** [ 0.030305] *** VALIDATE proc *** [ 0.031229] *** VALIDATE cgroup *** [ 0.032008] *** VALIDATE cgroup2 *** [ 0.034188] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.035145] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.036008] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.037032] Spectre V2 : User space: Vulnerable [ 0.038008] Speculative Store Bypass: Vulnerable [ 0.041157] debug: unmapping init [mem 0xffffffff86c59000-0xffffffff86c60fff] [ 0.043191] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.044658] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.045023] ... version: 2 [ 0.046010] ... bit width: 48 [ 0.047011] ... generic registers: 4 [ 0.048010] ... value mask: 0000ffffffffffff [ 0.049013] ... max period: 00007fffffffffff [ 0.050012] ... fixed-purpose events: 3 [ 0.050910] ... event mask: 000000070000000f [ 0.051273] rcu: Hierarchical SRCU implementation. [ 0.053321] smp: Bringing up secondary CPUs ... [ 0.054550] x86: Booting SMP configuration: [ 0.055022] .... node #0, CPUs: #1 #2 #3 [ 0.064097] smp: Brought up 1 node, 4 CPUs [ 0.066013] smpboot: Max logical packages: 1 [ 0.067018] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.106040] node 0 deferred pages initialised in 37ms [ 0.109636] devtmpfs: initialized [ 0.110209] x86/mm: Memory block size: 128MB [ 0.112993] gcov: version magic: 0x41383552 [ 0.114137] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.115077] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.116236] pinctrl core: initialized pinctrl subsystem [ 0.117181] [ 0.117998] ************************************************************* [ 0.118012] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.119013] ** ** [ 0.120013] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.121013] ** ** [ 0.122011] ** This means that this kernel is built to expose internal ** [ 0.123009] ** IOMMU data structures, which may compromise security on ** [ 0.124011] ** your system. ** [ 0.125013] ** ** [ 0.126011] ** If you see this message and you are not debugging the ** [ 0.127013] ** kernel, report this immediately to your vendor! ** [ 0.128012] ** ** [ 0.129010] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.130012] ************************************************************* [ 0.131754] NET: Registered protocol family 16 [ 0.132537] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.133060] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.134058] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.136049] cpuidle: using governor menu [ 0.137946] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.140593] PCI: Using configuration type 1 for base access [ 0.143163] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.153182] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.154020] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.157036] cryptd: max_cpu_qlen set to 1000 [ 0.160213] ACPI: Added _OSI(Module Device) [ 0.161009] ACPI: Added _OSI(Processor Device) [ 0.163016] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.165011] ACPI: Added _OSI(Processor Aggregator Device) [ 0.169000] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.178341] ACPI: Interpreter enabled [ 0.179061] ACPI: PM: (supports S0 S3 S4 S5) [ 0.180016] ACPI: Using IOAPIC for interrupt routing [ 0.181090] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.182389] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.193000] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.195040] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.197022] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.201085] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.205561] acpiphp: Slot [2] registered [ 0.207108] acpiphp: Slot [5] registered [ 0.208095] acpiphp: Slot [6] registered [ 0.209166] acpiphp: Slot [7] registered [ 0.211094] acpiphp: Slot [8] registered [ 0.212109] acpiphp: Slot [9] registered [ 0.213102] acpiphp: Slot [10] registered [ 0.215096] acpiphp: Slot [3] registered [ 0.216073] acpiphp: Slot [4] registered [ 0.217097] acpiphp: Slot [11] registered [ 0.218080] acpiphp: Slot [12] registered [ 0.219083] acpiphp: Slot [13] registered [ 0.221091] acpiphp: Slot [14] registered [ 0.222219] acpiphp: Slot [15] registered [ 0.224104] acpiphp: Slot [16] registered [ 0.225083] acpiphp: Slot [17] registered [ 0.226126] acpiphp: Slot [18] registered [ 0.228081] acpiphp: Slot [19] registered [ 0.229130] acpiphp: Slot [20] registered [ 0.230075] acpiphp: Slot [21] registered [ 0.231105] acpiphp: Slot [22] registered [ 0.232156] acpiphp: Slot [23] registered [ 0.234097] acpiphp: Slot [24] registered [ 0.235122] acpiphp: Slot [25] registered [ 0.237105] acpiphp: Slot [26] registered [ 0.239100] acpiphp: Slot [27] registered [ 0.240077] acpiphp: Slot [28] registered [ 0.241088] acpiphp: Slot [29] registered [ 0.243085] acpiphp: Slot [30] registered [ 0.244088] acpiphp: Slot [31] registered [ 0.245138] PCI host bridge to bus 0000:00 [ 0.246015] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.248018] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.250017] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.253021] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.255017] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.257020] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.259273] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.262000] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.264188] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.277014] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.280505] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.283015] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.285011] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.287014] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.290433] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.292763] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.295037] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.297847] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.303015] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.316013] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.321015] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.328152] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.340038] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.350024] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.375024] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.386833] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.414029] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.442022] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.521025] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.542000] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.584041] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.622024] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.645028] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.670098] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.698034] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.726019] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.757019] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.777179] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.803038] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.809021] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.830021] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 0.848347] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.875019] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.895016] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.956020] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 0.967946] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.971409] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.973406] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.975433] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.978259] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.983142] iommu: Default domain type: Passthrough [ 0.985342] SCSI subsystem initialized [ 0.987173] ACPI: bus type USB registered [ 0.988125] usbcore: registered new interface driver usbfs [ 0.990091] usbcore: registered new interface driver hub [ 0.992087] usbcore: registered new device driver usb [ 0.993176] pps_core: LinuxPPS API ver. 1 registered [ 0.995012] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.998079] PTP clock support registered [ 1.001028] EDAC MC: Ver: 3.0.0 [ 1.002542] PCI: Using ACPI for IRQ routing [ 1.003675] NetLabel: Initializing [ 1.005013] NetLabel: domain hash size = 128 [ 1.006007] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 1.008071] NetLabel: unlabeled traffic allowed by default [ 1.009133] vgaarb: loaded [ 1.010206] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 1.012012] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 1.018389] clocksource: Switched to clocksource kvm-clock [ 1.129026] VFS: Disk quotas dquot_6.6.0 [ 1.130271] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 1.132085] *** VALIDATE ramfs *** [ 1.132974] *** VALIDATE hugetlbfs *** [ 1.134367] pnp: PnP ACPI init [ 1.136557] pnp: PnP ACPI: found 6 devices [ 1.154566] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 1.157076] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 1.158752] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 1.160346] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 1.162161] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 1.163983] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 1.166059] NET: Registered protocol family 2 [ 1.168155] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 1.172259] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 1.175075] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 1.179600] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 1.182389] TCP: Hash tables configured (established 65536 bind 65536) [ 1.184814] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 1.187316] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 1.189531] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 1.191733] NET: Registered protocol family 1 [ 1.194070] RPC: Registered named UNIX socket transport module. [ 1.195984] RPC: Registered udp transport module. [ 1.197256] RPC: Registered tcp transport module. [ 1.198407] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 1.200344] NET: Registered protocol family 44 [ 1.201656] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 1.203374] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 1.205032] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 1.206687] PCI: CLS 0 bytes, default 64 [ 1.208805] Unpacking initramfs... [ 2.664276] debug: unmapping init [mem 0xffff92113cc54000-0xffff92113ffbffff] [ 2.667584] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.669244] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.671359] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 3.170997] Initialise system trusted keyrings [ 3.172853] Key type blacklist registered [ 3.174733] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 3.183525] zbud: loaded [ 3.186316] *** VALIDATE nfs *** [ 3.187246] *** VALIDATE nfs4 *** [ 3.188395] pstore: using deflate compression [ 3.191489] Platform Keyring initialized [ 3.289918] NET: Registered protocol family 38 [ 3.291635] Key type asymmetric registered [ 3.292797] Asymmetric key parser 'x509' registered [ 3.294401] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 3.297285] io scheduler mq-deadline registered [ 3.299137] io scheduler kyber registered [ 3.300414] io scheduler bfq registered [ 3.302160] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 3.305493] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 3.308308] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 3.311053] ACPI: Power Button [PWRF] [ 3.315906] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 3.322952] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 3.336907] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 3.343814] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 3.363165] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 3.389613] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.416410] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.420248] Non-volatile memory driver v1.3 [ 3.421460] Linux agpgart interface v0.103 [ 3.453828] virtio_blk virtio1: [vda] 145904 512-byte logical blocks (74.7 MB/71.2 MiB) [ 3.456594] vda: detected capacity change from 0 to 74702848 [ 3.479238] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.482159] vdb: detected capacity change from 0 to 1073741824 [ 3.513058] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.516401] vdc: detected capacity change from 0 to 2621440000 [ 3.530109] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.533532] vdd: detected capacity change from 0 to 2621440000 [ 3.548150] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.550884] vde: detected capacity change from 0 to 4294967296 [ 3.571050] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.573932] vdf: detected capacity change from 0 to 4294967296 [ 3.581312] libphy: Fixed MDIO Bus: probed [ 3.613206] usbcore: registered new interface driver usbserial_generic [ 3.615171] usbserial: USB Serial support registered for generic [ 3.617295] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.622346] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.624201] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.627504] mousedev: PS/2 mouse device common for all mice [ 3.630283] rtc_cmos 00:05: RTC can wake from S4 [ 3.633383] rtc_cmos 00:05: registered as rtc0 [ 3.635388] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.636644] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.642444] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.643070] intel_pstate: CPU model not supported [ 3.647931] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.651966] hid: raw HID events driver (C) Jiri Kosina [ 3.653635] usbcore: registered new interface driver usbhid [ 3.655326] usbhid: USB HID core driver [ 3.656609] drop_monitor: Initializing network drop monitor service [ 3.658546] Initializing XFRM netlink socket [ 3.660131] NET: Registered protocol family 10 [ 3.662769] Segment Routing with IPv6 [ 3.664284] NET: Registered protocol family 17 [ 3.666121] mpls_gso: MPLS GSO support [ 3.673673] RAS: Correctable Errors collector initialized. [ 3.675708] AVX version of gcm_enc/dec engaged. [ 3.677035] AES CTR mode by8 optimization enabled [ 3.757412] sched_clock: Marking stable (3757366351, 0)->(4702198810, -944832459) [ 3.760937] registered taskstats version 1 [ 3.762880] Loading compiled-in X.509 certificates [ 3.765067] zswap: loaded using pool lzo/zbud [ 3.796850] Key type big_key registered [ 3.810962] Key type encrypted registered [ 3.812717] ima: No TPM chip found, activating TPM-bypass! [ 3.814442] ima: Allocated hash algorithm: sha1 [ 3.815961] ima: No architecture policies found [ 3.817543] evm: Initialising EVM extended attributes: [ 3.819385] evm: security.selinux [ 3.820607] evm: security.ima [ 3.821495] evm: security.capability [ 3.822500] evm: HMAC attrs: 0x1 [ 3.824524] rtc_cmos 00:05: setting system clock to 2026-07-30 06:32:12 UTC (1785393132) [ 3.830481] debug: unmapping init [mem 0xffffffff87c03000-0xffffffff87dfffff] [ 3.833957] debug: unmapping init [mem 0xffffffff86982000-0xffffffff86c58fff] [ 3.847120] Write protecting the kernel read-only data: 28672k [ 3.850123] debug: unmapping init [mem 0xffffffff85003000-0xffffffff851fffff] [ 3.852619] debug: unmapping init [mem 0xffffffff85914000-0xffffffff859fffff] [ 3.892427] 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.900995] systemd[1]: Detected virtualization kvm. [ 3.902957] systemd[1]: Detected architecture x86-64. [ 3.904735] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.932371] systemd[1]: No hostname configured. [ 3.934245] systemd[1]: Set hostname to . [ 3.936527] random: systemd: uninitialized urandom read (16 bytes read) [ 3.939102] systemd[1]: Initializing machine ID from random generator. [ 4.093478] random: systemd: uninitialized urandom read (16 bytes read) [ 4.095924] systemd[1]: Listening on udev Control Socket. [ OK ] Listening on udev Control Socket. [ 4.100421] random: systemd: uninitialized urandom read (16 bytes read) [ 4.103295] systemd[1]: Listening on Journal Socket. [ OK ] Listening on Journal Socket. [ 4.112460] systemd[1]: Starting Setup Virtual Console... Starting Setup Virtual Console... [ OK ] Reached target Local File Systems. [ OK ] Listening on udev Kernel Socket. [ OK ] Reached target Swap. [ OK ] Reached target Timers. Starting Create list of required st…ce nodes for the current kernel... Starting Apply Kernel Variables... Starting Create Volatile Files and Directories... [ OK ] Started Memstrack Anylazing Service. [ OK ] Reached target Slices. [ 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 ] Listening on Journal Socket (/dev/log). [ OK ] Reached target Sockets. Starting Journal Service... [ OK ] Started Setup Virtual Console. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Apply Kernel Variables. [ OK ] Started Create Volatile Files and Directories. Starting Create Static Device Nodes in /dev... Starting dracut cmdline hook... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started Journal Service. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 4.719415] device-mapper: uevent: version 1.0.3 [ 4.721795] device-mapper: ioctl: 4.46.0-ioctl (2022-02-22) initialised: dm-devel@redhat.com [ OK ] Started dracut pre-udev hook. Starting udev Kernel Device Manager... [ OK ] Started udev Kernel Device Manager. Starting dracut pre-trigger hook... [ OK ] Started dracut pre-trigger hook. Starting udev Coldplug all Devices... Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting dracut initqueue hook... [ 5.490050] random: fast init done [ 5.509295] virtio_net virtio0 ens2: renamed from eth0 [ 5.544686] scsi host0: ata_piix [ 5.559433] scsi host1: ata_piix [ 5.561301] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 5.563527] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 9.337541] dracut-initqueue[577]: RTNETLINK answers: File exists [ 10.327990] random: crng init done [ 10.329606] random: 7 urandom warning(s) missed due to ratelimiting Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. Mounting /sysroot... [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. [ 10.780429] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped target Timers. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Paths. [ OK ] Stopped target Sockets. [ OK ] Stopped target Slices. [ OK ] Stopped target System Initialization. [ OK ] Stopped target Swap. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. [ OK ] Stopped Create Volatile Files and Directories. Stopping udev Kernel Device Manager... [ OK ] Stopped target Local File Systems. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Closed udev 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.958930] printk: systemd: 26 output lines suppressed due to ratelimiting [ 12.195887] SELinux: Disabled at runtime. [ 12.252613] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 12.258700] systemd[1]: Detected virtualization kvm. [ 12.260025] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 12.713155] systemd[1]: initrd-switch-root.service: Succeeded. [ 12.716690] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 12.721468] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 12.725442] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 12.728702] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 12.737821] systemd[1]: Starting Journal Service... Starting Journal Service... [ 12.747570] systemd[1]: Starting Create list of required static device nodes for the current kernel... Starting Create list of required st…ce nodes for the current kernel... [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Created slice User and Session Slice. [ OK ] Created slice system-getty.slice. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Listening on Process Core Dump Socket. [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Listening on initctl Compatibility Named Pipe. [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd Root File System. Activating swap /dev/disk/by-label/SWAP... Starting Apply Kernel Variables... [ OK ] Reached target Paths. [ OK ] Stopped target Initrd File Systems. [ OK ] Listening on udev Kernel Socket. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Listening on RPCbind Server Activation Socket. [ 12.850404] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS [ OK ] Reached target RPC Port Mapper. [ OK ] Reached target Slices. [ OK ] Reached target rpc_pipefs.target. Mounting POSIX Message Queue File System... Mounting Huge Pages File System... [ OK ] Listening on udev Control Socket. Starting udev Coldplug all Devices... Starting Remount Root and Kernel File Systems... Mounting Kernel Debug File System... [ OK ] Started Journal Service. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Started Apply Kernel Variables. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Mounted Huge Pages File System. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Mounted Kernel Debug File System. Starting Configure read-only root support... [ OK ] Reached target Swap. Starting Create Static Device Nodes in /dev... Starting Flush Journal to Persistent Storage... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Reached target Local File Systems (Pre). Mounting /mnt... Mounting /home/green/git/lustre-release... Starting udev Kernel Device Manager... [ OK ] Mounted /mnt. [ 13.240773] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Started udev Coldplug all Devices. [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 13.599814] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 13.616875] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 13.732289] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 13.753881] EDAC sbridge: Ver: 1.1.2 [ 15.215704] Key type dns_resolver registered [ 15.520882] NFS: Registering the id_resolver key type [ 15.522818] Key type id_resolver registered [ 15.524133] Key type id_legacy registered [ OK ] Started Configure read-only root support. Starting Load/Save Random Seed... [ OK ] Reached target Local File Systems. Starting Rebuild Dynamic Linker Cache... Starting Mark the need to relabel after reboot... Starting Create Volatile Files and Directories... [ OK ] Started Load/Save Random Seed. [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Create Volatile Files and Directories. Starting RPC Bind... Starting Update UTMP about System Boot/Shutdown... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Reached target Basic System. Starting Login Service... [ OK ] Started irqbalance daemon. Starting Restore /run/initramfs on shutdown... [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Started dnf makecache --timer. [ OK ] Reached target Timers. [ OK ] Started D-Bus System Message Bus. Starting Network Manager... [ OK ] Reached target sshd-keygen.target. [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Login Service. [ OK ] Started Network Manager. [ OK ] Reached target Network. Starting Dynamic System Tuning Daemon... Starting OpenSSH server daemon... Starting GSSAPI Proxy Daemon... Starting Network Manager Wait Online... Starting Hostname Service... [ OK ] Started OpenSSH server daemon. [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... [ OK ] Started Permit User Sessions. [ OK ] Started Command Scheduler. [ OK ] Started Getty on tty1. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Serial Getty on ttyS1. [ 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 System Logging Service... Starting Crash recovery kernel arming... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Starting Authorization Manager... [ OK ] Started Authorization Manager. [ OK ] Started Dynamic System Tuning Daemon. [ OK ] Reached target Multi-User System. [ OK ] Reached target Graphical Interface. Starting Update UTMP about System Runlevel Changes... [ OK ] Started Update UTMP about System Runlevel Changes. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg145-server login: [ 33.658631] spl: loading out-of-tree module taints kernel. [ 36.440481] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 41.229321] Key type ._llcrypt registered [ 41.230938] Key type .llcrypt registered [ 41.282475] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_hostid [ 57.511949] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing load_modules_local [ 59.768704] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 59.809772] alg: No test for adler32 (adler32-zlib) [ 61.579175] Lustre: Lustre: Build Version: 2.17.56_2_geb69296 [ 62.952335] LNet: Added LNI 192.168.201.145@tcp [8/256/0/180] [ 64.855706] Key type lgssc registered [ 66.883329] Lustre: Echo OBD driver; http://www.lustre.org/ [ 80.032481] vdc: vdc1 vdc9 [ 93.599799] vde: vde1 vde9 [ 110.697449] vdf: vdf1 vdf9 [ 134.379271] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing load_modules_local [ 146.883079] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 148.429556] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 148.966402] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 149.152538] Lustre: lustre-MDT0000: new disk, initializing [ 149.888102] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 150.036565] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 156.178211] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 162.160439] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 170.435611] Lustre: lustre-OST0000: new disk, initializing [ 170.441968] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 170.452758] Lustre: Skipped 1 previous similar message [ 170.896254] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 175.676063] hrtimer: interrupt took 4993341 ns [ 176.311753] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:0:ost [ 176.336521] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:0:ost] [ 176.626399] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x240000400 [ 180.925564] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 195.605860] Lustre: lustre-OST0001: new disk, initializing [ 195.610307] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 195.756049] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 204.529566] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:1:ost [ 204.535958] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:1:ost] [ 204.750877] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x280000400 [ 207.079985] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 224.250488] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 233.756732] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 242.254791] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing check_logdir /tmp/testlogs/ [ 249.226972] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing yml_node [ 254.219514] Lustre: DEBUG MARKER: Client: 2.17.56.2 [ 257.316660] Lustre: DEBUG MARKER: MDS: 2.17.56.2 [ 260.650908] Lustre: DEBUG MARKER: OSS: 2.17.56.2 [ 262.964883] Lustre: DEBUG MARKER: -----============= acceptance-small: replay-single ============----- Thu Jul 30 02:36:29 EDT 2026 [ 283.415551] Lustre: DEBUG MARKER: excepting tests: 59 36 [ 286.861917] Lustre: DEBUG MARKER: === replay-single: start setup 02:36:52 (1785393412) === [ 294.349719] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing check_config_client /mnt/lustre [ 317.226153] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 323.698139] Lustre: 11178:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 329.212075] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 334.821588] Lustre: DEBUG MARKER: === replay-single: finish setup 02:37:41 (1785393461) === [ 337.786654] Lustre: DEBUG MARKER: == replay-single test 0a: empty replay =================== 02:37:43 (1785393463) [ 341.405793] LustreError: 11673:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 342.812959] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 345.813462] Lustre: Failing over lustre-MDT0000 [ 346.407382] Lustre: server umount lustre-MDT0000 complete [ 364.000335] Lustre: 3299:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1785393476/real 1785393476] req@ffff9211bafeb800 x1872120450710272/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1785393492 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 364.001402] LustreError: MGC192.168.201.145@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 364.049749] Lustre: 3299:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 364.049876] 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 [ 369.183390] Lustre: 3299:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1785393481/real 1785393481] req@ffff9211bf5aed80 x1872120450710656/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1785393497 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 369.228852] Lustre: 3299:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 373.343193] Lustre: 3297:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1785393486/real 1785393486] req@ffff9211bf5ad500 x1872120450710912/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1785393502 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 373.385666] Lustre: 3297:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 374.241893] LustreError: 3296:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9211bf5ad500 x1872120450711936/t0(0) o250->MGC192.168.201.145@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 [ 375.066940] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 376.143021] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 376.279298] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 378.911095] Lustre: 3299:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1785393491/real 1785393491] req@ffff9211ba9d6680 x1872120450711296/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1785393507 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 378.959866] Lustre: 3299:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 381.200345] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 388.593547] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 395.796660] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 399.180487] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 412.980157] Lustre: DEBUG MARKER: == replay-single test 0b: ensure object created after recover exists. (3284) ========================================================== 02:38:59 (1785393539) [ 415.994451] Lustre: Failing over lustre-OST0000 [ 416.166187] Lustre: server umount lustre-OST0000 complete [ 419.296631] 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 [ 419.317949] Lustre: Skipped 1 previous similar message [ 422.214370] LustreError: 6600:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.201.45@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 422.243132] LustreError: 6600:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 3 previous similar messages [ 424.416672] LustreError: 7762: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. [ 427.343686] LustreError: 6601:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.201.45@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 429.543152] LustreError: 6599: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. [ 434.663362] LustreError: 6601: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. [ 434.669870] LustreError: 6601:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 1 previous similar message [ 437.635421] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 439.377517] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 439.522886] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 439.524804] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 439.562033] Lustre: Skipped 1 previous similar message [ 446.534698] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 459.114842] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 460.942579] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 471.917492] Lustre: DEBUG MARKER: == replay-single test 0c: check replay-barrier =========== 02:39:58 (1785393598) [ 475.358451] LustreError: 14614:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 476.470290] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 479.041206] Lustre: Failing over lustre-MDT0000 [ 479.595046] Lustre: server umount lustre-MDT0000 complete [ 500.000167] Lustre: 3300:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1785393612/real 1785393612] req@ffff9211bab8fb80 x1872120450747264/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1785393628 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 500.016741] LustreError: MGC192.168.201.145@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 500.038274] Lustre: 3300:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 500.038334] 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 [ 509.415134] Lustre: 3299:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1785393622/real 1785393622] req@ffff9211baf73800 x1872120450747904/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1785393638 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 509.419797] LustreError: 3296:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9211baf71c00 x1872120450749056/t0(0) o250->MGC192.168.201.145@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 [ 509.447925] Lustre: 3299:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 510.353373] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 517.607941] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 521.127389] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 521.139275] Lustre: lustre-MDT0000: Denying connection for new client bbde12af-9688-45af-8929-5068b14880e3 (at 192.168.201.45@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 1:00 [ 524.424112] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 526.144971] Lustre: lustre-MDT0000: Denying connection for new client bbde12af-9688-45af-8929-5068b14880e3 (at 192.168.201.45@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:55 [ 531.267871] Lustre: lustre-MDT0000: Denying connection for new client bbde12af-9688-45af-8929-5068b14880e3 (at 192.168.201.45@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:50 [ 536.388093] Lustre: lustre-MDT0000: Denying connection for new client bbde12af-9688-45af-8929-5068b14880e3 (at 192.168.201.45@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:45 [ 541.507774] Lustre: lustre-MDT0000: Denying connection for new client bbde12af-9688-45af-8929-5068b14880e3 (at 192.168.201.45@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:39 [ 551.754934] Lustre: lustre-MDT0000: Denying connection for new client bbde12af-9688-45af-8929-5068b14880e3 (at 192.168.201.45@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:29 [ 551.777536] Lustre: Skipped 1 previous similar message [ 572.226897] Lustre: lustre-MDT0000: Denying connection for new client bbde12af-9688-45af-8929-5068b14880e3 (at 192.168.201.45@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:09 [ 572.257415] Lustre: Skipped 3 previous similar messages [ 581.500192] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 581.505074] Lustre: 15216:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client abe3589a-7b8a-490c-ad24-e022147786bd@ [ 581.520855] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 581.586578] Lustre: lustre-MDT0000: Recovery over after 1:00, of 1 clients 0 recovered and 1 was evicted. [ 581.696686] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:44 to 0x280000400:65) [ 581.696686] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:44 to 0x240000400:65) [ 595.158182] Lustre: DEBUG MARKER: == replay-single test 0d: expired recovery with no clients ========================================================== 02:42:01 (1785393721) [ 599.439659] LustreError: 15954:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 600.678841] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 603.607581] Lustre: Failing over lustre-MDT0000 [ 604.072721] Lustre: server umount lustre-MDT0000 complete [ 622.816077] Lustre: 3300:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1785393735/real 1785393735] req@ffff9211bb42aa00 x1872120450772480/t0(0) o400->MGC192.168.201.145@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1785393751 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 622.847455] Lustre: 3300:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 4 previous similar messages [ 622.855041] LustreError: MGC192.168.201.145@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 622.881349] 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 [ 622.900437] Lustre: Skipped 1 previous similar message [ 634.135769] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 634.296878] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 640.548540] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 643.412573] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 643.420101] Lustre: lustre-MDT0000: Denying connection for new client e3d8042e-f791-4a8b-9922-ea59ed21bdb2 (at 192.168.201.45@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 1:00 [ 643.436554] Lustre: Skipped 1 previous similar message [ 648.293587] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 648.295730] Lustre: Skipped 1 previous similar message [ 703.502147] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 703.508943] Lustre: 16554:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client bbde12af-9688-45af-8929-5068b14880e3@ [ 703.537449] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 703.714148] Lustre: lustre-MDT0000: Recovery over after 1:00, of 1 clients 0 recovered and 1 was evicted. [ 703.831570] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:44 to 0x280000400:97) [ 703.831660] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:44 to 0x240000400:97) [ 717.763116] Lustre: DEBUG MARKER: == replay-single test 1: simple create =================== 02:44:04 (1785393844) [ 721.246654] LustreError: 17293:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 722.376662] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 724.544846] Lustre: Failing over lustre-MDT0000 [ 725.015370] Lustre: server umount lustre-MDT0000 complete [ 741.732746] Lustre: 3297:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1785393854/real 1785393854] req@ffff9211bab8df80 x1872120450797312/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1785393870 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 741.752985] Lustre: 3297:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 8 previous similar messages [ 741.762592] 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 [ 741.778918] Lustre: Skipped 1 previous similar message [ 741.784838] LustreError: MGC192.168.201.145@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 752.101168] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xe4f321ee34c4c85c [ 752.128227] Lustre: MGC192.168.201.145@tcp: Connection restored to 0@lo (at 0@lo) [ 752.144104] Lustre: Skipped 1 previous similar message [ 752.454206] Lustre: lustre-MDT0000: Not available for connect from 192.168.201.45@tcp (not set up) [ 752.748466] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 752.859735] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 754.089513] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 754.270612] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 754.359746] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:44 to 0x240000400:129) [ 754.360590] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:44 to 0x280000400:129) [ 758.074723] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 766.964826] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 769.856687] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 772.023813] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 783.429897] Lustre: DEBUG MARKER: == replay-single test 2a: touch ========================== 02:45:09 (1785393909) [ 787.678054] LustreError: 18829:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 788.857421] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 792.149849] Lustre: Failing over lustre-MDT0000 [ 792.563758] 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 [ 792.572744] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 792.588358] Lustre: Skipped 2 previous similar messages [ 792.822645] Lustre: server umount lustre-MDT0000 complete [ 814.053239] Lustre: 3298:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1785393926/real 1785393926] req@ffff9211bab8e680 x1872120450814976/t0(0) o400->MGC192.168.201.145@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1785393942 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 814.090377] Lustre: 3298:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 9 previous similar messages [ 814.110880] LustreError: MGC192.168.201.145@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 824.728734] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 824.905085] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 832.995361] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 833.006617] Lustre: Skipped 1 previous similar message [ 833.086868] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 834.431423] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 834.724190] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 834.829648] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:44 to 0x280000400:161) [ 834.833650] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:131 to 0x240000400:161) [ 846.028276] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 848.002031] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 856.958592] Lustre: DEBUG MARKER: == replay-single test 2b: touch ========================== 02:46:23 (1785393983) [ 861.118305] LustreError: 20366:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 862.132689] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 864.804307] Lustre: Failing over lustre-MDT0000 [ 865.140873] Lustre: lustre-MDT0000: Not available for connect from 192.168.201.45@tcp (stopping) [ 865.147623] Lustre: Skipped 1 previous similar message [ 865.344734] Lustre: server umount lustre-MDT0000 complete [ 885.215582] LustreError: MGC192.168.201.145@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 885.235755] 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 [ 885.263354] Lustre: Skipped 1 previous similar message [ 894.434433] LustreError: 3296:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9211bf7cbb80 x1872120450834432/t0(0) o250->MGC192.168.201.145@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 [ 895.322451] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 900.648458] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 905.150612] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 905.478808] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 905.595140] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:131 to 0x240000400:193) [ 905.599775] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:163 to 0x280000400:193) [ 909.423722] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 909.432370] Lustre: Skipped 1 previous similar message [ 913.251067] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 915.860967] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 928.945947] Lustre: DEBUG MARKER: == replay-single test 2c: setstripe replay =============== 02:47:34 (1785394054) [ 933.142547] LustreError: 21918:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 934.600759] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 937.627231] Lustre: Failing over lustre-MDT0000 [ 938.081882] Lustre: server umount lustre-MDT0000 complete [ 956.639813] Lustre: 3299:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1785394069/real 1785394069] req@ffff9211ba9d5180 x1872120450851456/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1785394085 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 956.674699] Lustre: 3299:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 9 previous similar messages [ 956.682548] 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 [ 957.662714] LustreError: MGC192.168.201.145@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 957.716724] LustreError: 22479: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. [ 958.157892] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 958.160945] Lustre: Skipped 1 previous similar message [ 958.253511] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 964.145102] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 966.975412] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 967.257477] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 967.324944] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:225) [ 967.346986] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:225) [ 976.654399] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 978.661835] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 989.387932] Lustre: DEBUG MARKER: == replay-single test 2d: setdirstripe replay ============ 02:48:35 (1785394115) [ 993.220716] LustreError: 23464:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 994.919336] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 997.775184] Lustre: Failing over lustre-MDT0000 [ 998.275876] Lustre: server umount lustre-MDT0000 complete [ 1014.560967] LustreError: MGC192.168.201.145@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1025.900347] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1029.687028] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:257) [ 1029.692936] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:257) [ 1031.468679] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1039.778406] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 1039.796170] Lustre: Skipped 3 previous similar messages [ 1044.322798] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1046.399824] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1057.702938] Lustre: DEBUG MARKER: == replay-single test 2e: O_CREAT|O_EXCL create replay === 02:49:44 (1785394184) [ 1059.053730] Lustre: *** cfs_fail_loc=13b, val=315*** [ 1059.057951] Lustre: *** cfs_fail_loc=13b, val=2147483648*** [ 1059.064194] LustreError: 24024:0:(ldlm_lib.c:3345:target_send_reply_msg()) @@@ dropping reply req@ffff921198b0dc00 x1872120429803136/t38654705666(0) o35->e3d8042e-f791-4a8b-9922-ea59ed21bdb2@192.168.201.45@tcp:404/0 lens 392/456 e 0 to 0 dl 1785394204 ref 1 fl Interpret:/600/0 rc 0/0 job:'openfile.0' uid:0 gid:0 projid:0 [ 1064.088580] LustreError: 25053:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 1065.253357] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1067.712972] Lustre: Failing over lustre-MDT0000 [ 1068.188827] Lustre: server umount lustre-MDT0000 complete [ 1086.945204] LustreError: MGC192.168.201.145@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1086.948505] 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 [ 1086.970684] Lustre: Skipped 4 previous similar messages [ 1097.183944] LustreError: 3296:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff921083244a80 x1872120450889216/t0(0) o250->MGC192.168.201.145@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 [ 1098.202543] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1104.199197] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1106.367740] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1106.385672] Lustre: Skipped 1 previous similar message [ 1106.468312] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1106.470725] Lustre: Skipped 1 previous similar message [ 1106.573609] Lustre: 25611:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9211bf6e7100 x1872120429803136/t38654705666(0) o35->e3d8042e-f791-4a8b-9922-ea59ed21bdb2@192.168.201.45@tcp:452/0 lens 392/456 e 0 to 0 dl 1785394252 ref 1 fl Interpret:/602/0 rc 0/0 job:'openfile.0' uid:0 gid:0 projid:0 [ 1106.586542] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:289) [ 1106.618671] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:289) [ 1115.925386] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1117.683447] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1128.848075] Lustre: DEBUG MARKER: == replay-single test 3a: replay failed open(O_DIRECTORY) ========================================================== 02:50:55 (1785394255) [ 1133.401186] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1135.885493] Lustre: Failing over lustre-MDT0000 [ 1136.395392] Lustre: server umount lustre-MDT0000 complete [ 1165.731252] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xe4f321ee34c4e39f [ 1166.698879] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1172.216768] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1178.665772] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:321) [ 1178.670372] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:321) [ 1180.711925] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 1180.724051] Lustre: Skipped 5 previous similar messages [ 1185.491176] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1187.058120] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1198.213667] Lustre: DEBUG MARKER: == replay-single test 3b: replay failed open -ENOMEM ===== 02:52:04 (1785394324) [ 1203.054620] LustreError: 28128:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 1203.067360] LustreError: 28128:0:(osd_handler.c:720:osd_ro()) Skipped 1 previous similar message [ 1204.318170] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1205.495120] Lustre: *** cfs_fail_loc=114, val=0*** [ 1208.528585] Lustre: Failing over lustre-MDT0000 [ 1209.079502] Lustre: server umount lustre-MDT0000 complete [ 1227.747027] Lustre: 3300:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1785394340/real 1785394340] req@ffff9211b63e1f80 x1872120450923648/t0(0) o400->MGC192.168.201.145@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1785394356 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1227.753278] 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 [ 1227.791894] Lustre: 3300:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 37 previous similar messages [ 1227.791968] LustreError: MGC192.168.201.145@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1227.791971] LustreError: Skipped 1 previous similar message [ 1227.846202] Lustre: Skipped 2 previous similar messages [ 1238.593649] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1238.616614] Lustre: Skipped 3 previous similar messages [ 1238.878181] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1247.055724] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1250.136100] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1250.167578] Lustre: Skipped 1 previous similar message [ 1250.402609] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1250.407504] Lustre: Skipped 1 previous similar message [ 1250.564666] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:353) [ 1250.565068] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:353) [ 1261.963537] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1264.713951] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1277.687950] Lustre: DEBUG MARKER: == replay-single test 3c: replay failed open -ENOMEM ===== 02:53:24 (1785394404) [ 1283.337613] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1284.635803] Lustre: *** cfs_fail_loc=128, val=0*** [ 1289.960917] Lustre: Failing over lustre-MDT0000 [ 1290.217598] Lustre: server umount lustre-MDT0000 complete [ 1321.313977] LustreError: 3296:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9211bf5af480 x1872120450946176/t0(0) o250->MGC192.168.201.145@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 [ 1327.986781] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1332.257831] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:385) [ 1332.258805] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:385) [ 1340.802731] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1343.180320] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1353.132763] Lustre: DEBUG MARKER: == replay-single test 4a: |x| 10 open(O_CREAT)s ========== 02:54:39 (1785394479) [ 1357.872561] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1360.617116] Lustre: Failing over lustre-MDT0000 [ 1360.863874] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1361.140401] Lustre: server umount lustre-MDT0000 complete [ 1380.385984] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1380.388357] Lustre: Skipped 1 previous similar message [ 1385.970719] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1389.826408] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:391 to 0x280000400:417) [ 1389.827421] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:391 to 0x240000400:417) [ 1398.631801] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1401.327337] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1415.553994] Lustre: DEBUG MARKER: == replay-single test 4b: |x| rm 10 files ================ 02:55:41 (1785394541) [ 1421.546780] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1423.688991] Lustre: Failing over lustre-MDT0000 [ 1423.973785] Lustre: server umount lustre-MDT0000 complete [ 1442.785486] Lustre: MGS: Not available for connect from 0@lo (not set up) [ 1442.793512] Lustre: Skipped 1 previous similar message [ 1446.159854] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:423 to 0x240000400:449) [ 1446.167454] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:423 to 0x280000400:449) [ 1448.947898] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 1448.956297] Lustre: Skipped 6 previous similar messages [ 1450.166461] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1463.374944] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1466.473495] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1480.284410] Lustre: DEBUG MARKER: == replay-single test 5: |x| 220 open(O_CREAT) =========== 02:56:47 (1785394607) [ 1483.216636] LustreError: 34471:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 1483.224365] LustreError: 34471:0:(osd_handler.c:720:osd_ro()) Skipped 3 previous similar messages [ 1484.508355] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1497.798048] Lustre: Failing over lustre-MDT0000 [ 1498.293475] Lustre: server umount lustre-MDT0000 complete [ 1515.487450] 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 [ 1515.501329] Lustre: Skipped 7 previous similar messages [ 1516.256369] LustreError: MGC192.168.201.145@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1516.264603] LustreError: Skipped 3 previous similar messages [ 1529.025618] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1529.034217] Lustre: Skipped 3 previous similar messages [ 1531.887968] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1534.449389] Lustre: lustre-MDT0000: Recovery over after 0:05, of 1 clients 1 recovered and 0 were evicted. [ 1534.458123] Lustre: Skipped 3 previous similar messages [ 1534.504255] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:577) [ 1534.508521] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:577) [ 1542.454611] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1544.437091] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1575.057204] Lustre: DEBUG MARKER: == replay-single test 6a: mkdir + contained create ======= 02:58:21 (1785394701) [ 1579.328987] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1581.672966] Lustre: Failing over lustre-MDT0000 [ 1582.107786] Lustre: server umount lustre-MDT0000 complete [ 1603.069640] Lustre: lustre-MDT0000: Not available for connect from 0@lo (not set up) [ 1610.294480] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1611.387288] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:609) [ 1611.387630] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:609) [ 1623.484294] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1625.542156] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1640.501259] Lustre: DEBUG MARKER: == replay-single test 6b: |X| rmdir ====================== 02:59:26 (1785394766) [ 1645.364718] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1649.207561] Lustre: Failing over lustre-MDT0000 [ 1649.634471] Lustre: server umount lustre-MDT0000 complete [ 1681.151303] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1681.167922] Lustre: Skipped 3 previous similar messages [ 1685.277649] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1693.247154] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:641) [ 1693.250169] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:641) [ 1701.950570] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1703.667876] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1716.018835] Lustre: DEBUG MARKER: == replay-single test 7: mkdir |X| contained create ====== 03:00:41 (1785394841) [ 1721.274942] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1723.858619] Lustre: Failing over lustre-MDT0000 [ 1724.448973] Lustre: server umount lustre-MDT0000 complete [ 1743.267244] Lustre: 3300:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1785394855/real 1785394855] req@ffff9211c1e26a00 x1872120451115520/t0(0) o400->MGC192.168.201.145@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1785394871 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1743.307834] Lustre: 3300:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 50 previous similar messages [ 1752.545880] LustreError: 3296:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9211b4833b80 x1872120451117440/t0(0) o250->MGC192.168.201.145@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 [ 1753.266318] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1753.271997] Lustre: Skipped 6 previous similar messages [ 1755.710357] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:673) [ 1755.716442] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:673) [ 1758.577259] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1769.369660] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1771.192461] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1781.458955] Lustre: DEBUG MARKER: == replay-single test 8: creat open |X| close ============ 03:01:47 (1785394907) [ 1786.160042] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1789.078624] Lustre: Failing over lustre-MDT0000 [ 1789.430594] Lustre: server umount lustre-MDT0000 complete [ 1825.568400] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1833.646096] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:705) [ 1833.647085] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:705) [ 1842.505596] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1844.856335] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1857.780715] Lustre: DEBUG MARKER: == replay-single test 9: |X| create (same inum/gen) ====== 03:03:04 (1785394984) [ 1863.605560] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1866.469314] Lustre: Failing over lustre-MDT0000 [ 1867.071587] Lustre: server umount lustre-MDT0000 complete [ 1905.351115] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1910.331615] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:737) [ 1910.332424] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:737) [ 1918.489133] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1920.443571] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1930.126644] Lustre: DEBUG MARKER: == replay-single test 10: create |X| rename unlink ======= 03:04:16 (1785395056) [ 1935.837942] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1938.016825] Lustre: Failing over lustre-MDT0000 [ 1938.494588] Lustre: server umount lustre-MDT0000 complete [ 1968.033465] LustreError: 3296:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff92118ad10380 x1872120451173248/t0(0) o250->MGC192.168.201.145@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 [ 1974.284103] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1982.000495] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:769) [ 1982.008051] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:769) [ 1982.115759] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 1982.122135] Lustre: Skipped 13 previous similar messages [ 1988.495807] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1990.275759] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2000.376640] Lustre: DEBUG MARKER: == replay-single test 11: create open write rename |X| create-old-name read ========================================================== 03:05:27 (1785395127) [ 2004.724594] LustreError: 45349:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 2004.731056] LustreError: 45349:0:(osd_handler.c:720:osd_ro()) Skipped 6 previous similar messages [ 2005.877862] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2008.262230] Lustre: Failing over lustre-MDT0000 [ 2008.673806] Lustre: server umount lustre-MDT0000 complete [ 2034.660879] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xe4f321ee34c5b57c [ 2038.479423] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:771 to 0x280000400:801) [ 2038.493701] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:771 to 0x240000400:801) [ 2042.139281] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2053.171386] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2055.082925] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2063.415530] Lustre: DEBUG MARKER: == replay-single test 12: open, unlink |X| close ========= 03:06:30 (1785395190) [ 2068.270586] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2070.807546] Lustre: Failing over lustre-MDT0000 [ 2071.351632] Lustre: server umount lustre-MDT0000 complete [ 2091.159732] LustreError: MGC192.168.201.145@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2091.167195] LustreError: Skipped 7 previous similar messages [ 2091.598764] 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 [ 2091.608788] Lustre: Skipped 16 previous similar messages [ 2097.079420] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2100.557053] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 2100.567948] Lustre: Skipped 7 previous similar messages [ 2100.785414] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 2100.792180] Lustre: Skipped 7 previous similar messages [ 2100.844087] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:771 to 0x280000400:833) [ 2100.850394] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:771 to 0x240000400:833) [ 2108.527258] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2110.554080] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2121.849179] Lustre: DEBUG MARKER: == replay-single test 13: open chmod 0 |x| write close === 03:07:28 (1785395248) [ 2127.278786] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2129.529135] Lustre: Failing over lustre-MDT0000 [ 2129.763674] Lustre: server umount lustre-MDT0000 complete [ 2149.324581] LustreError: 48987: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. [ 2155.492740] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2157.174980] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:771 to 0x280000400:865) [ 2157.176681] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:835 to 0x240000400:865) [ 2166.159671] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2168.144778] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2179.951805] Lustre: DEBUG MARKER: == replay-single test 14: open(O_CREAT), unlink |X| close ========================================================== 03:08:26 (1785395306) [ 2186.245691] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2190.089157] Lustre: Failing over lustre-MDT0000 [ 2190.662690] Lustre: server umount lustre-MDT0000 complete [ 2222.455397] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 2222.474665] Lustre: Skipped 7 previous similar messages [ 2229.350363] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2234.034492] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:867 to 0x240000400:897) [ 2234.035772] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:771 to 0x280000400:897) [ 2244.520345] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2247.662357] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2260.959266] Lustre: DEBUG MARKER: == replay-single test 15: open(O_CREAT), unlink |X| touch new, close ========================================================== 03:09:46 (1785395386) [ 2265.675917] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2268.191621] Lustre: Failing over lustre-MDT0000 [ 2268.689507] Lustre: server umount lustre-MDT0000 complete [ 2299.551910] LustreError: 3296:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9211bb2e3480 x1872120451263232/t0(0) o250->MGC192.168.201.145@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 [ 2306.325830] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2310.899686] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:899 to 0x240000400:929) [ 2310.900300] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:899 to 0x280000400:929) [ 2317.871569] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2319.928221] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2329.425838] Lustre: DEBUG MARKER: == replay-single test 16: |X| open(O_CREAT), unlink, touch new, unlink new ========================================================== 03:10:56 (1785395456) [ 2334.342407] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2336.422432] Lustre: Failing over lustre-MDT0000 [ 2336.856323] Lustre: server umount lustre-MDT0000 complete [ 2354.659184] Lustre: 3300:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1785395467/real 1785395467] req@ffff9211bf5cbb80 x1872120451278208/t0(0) o400->MGC192.168.201.145@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1785395483 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2354.710300] Lustre: 3300:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 79 previous similar messages [ 2364.899845] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xe4f321ee34c5cde0 [ 2366.420247] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 2366.422724] Lustre: Skipped 8 previous similar messages [ 2367.444573] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:899 to 0x240000400:961) [ 2367.475594] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:931 to 0x280000400:961) [ 2378.058037] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2392.445967] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2394.246632] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2406.058459] Lustre: DEBUG MARKER: == replay-single test 17: |X| open(O_CREAT), |replay| close ========================================================== 03:12:12 (1785395532) [ 2410.434265] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2412.818158] Lustre: Failing over lustre-MDT0000 [ 2413.184068] Lustre: server umount lustre-MDT0000 complete [ 2450.026531] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2453.094642] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:963 to 0x280000400:993) [ 2453.094959] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:899 to 0x240000400:993) [ 2462.132842] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2463.727911] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2475.415814] Lustre: DEBUG MARKER: == replay-single test 18: open(O_CREAT), unlink, touch new, close, touch, unlink ========================================================== 03:13:21 (1785395601) [ 2480.233471] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2483.771553] Lustre: Failing over lustre-MDT0000 [ 2484.668498] Lustre: server umount lustre-MDT0000 complete [ 2515.615732] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:995 to 0x280000400:1025) [ 2515.620100] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:995 to 0x240000400:1025) [ 2519.508605] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2530.564122] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2532.896108] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2542.656946] Lustre: DEBUG MARKER: == replay-single test 19: mcreate, open, write, rename === 03:14:29 (1785395669) [ 2547.317488] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2549.920614] Lustre: Failing over lustre-MDT0000 [ 2550.343098] Lustre: server umount lustre-MDT0000 complete [ 2578.912194] LustreError: 3296:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9211b4838380 x1872120451335040/t0(0) o250->MGC192.168.201.145@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 [ 2586.084568] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2592.326605] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1027 to 0x280000400:1057) [ 2592.333937] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1027 to 0x240000400:1057) [ 2593.846153] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 2593.855365] Lustre: Skipped 19 previous similar messages [ 2599.978980] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2602.210358] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2613.338083] Lustre: DEBUG MARKER: == replay-single test 20a: |X| open(O_CREAT), unlink, replay, close (test mds_cleanup_orphans) ========================================================== 03:15:39 (1785395739) [ 2616.962926] LustreError: 59230:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 2616.966547] LustreError: 59230:0:(osd_handler.c:720:osd_ro()) Skipped 8 previous similar messages [ 2617.963532] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2620.434583] Lustre: Failing over lustre-MDT0000 [ 2620.849434] Lustre: server umount lustre-MDT0000 complete [ 2657.979883] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2663.984280] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1027 to 0x280000400:1089) [ 2663.985995] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1059 to 0x240000400:1089) [ 2672.519335] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2676.295747] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2694.513230] Lustre: DEBUG MARKER: == replay-single test 20b: write, unlink, eviction, replay (test mds_cleanup_orphans) ========================================================== 03:16:59 (1785395819) [ 2702.353632] Lustre: 60828:0:(genops.c:1795:obd_export_evict_by_uuid()) lustre-MDT0000: evicting e3d8042e-f791-4a8b-9922-ea59ed21bdb2 at adminstrative request [ 2710.084727] Lustre: Failing over lustre-MDT0000 [ 2710.499097] Lustre: server umount lustre-MDT0000 complete [ 2727.327200] LustreError: MGC192.168.201.145@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2727.337475] LustreError: Skipped 8 previous similar messages [ 2728.358352] 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 [ 2728.372757] Lustre: Skipped 16 previous similar messages [ 2737.503873] LustreError: 3296:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9211bfbbdf80 x1872120451374720/t0(0) o250->MGC192.168.201.145@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 [ 2737.540668] LustreError: 3296:0:(client.c:1391:ptlrpc_import_delay_req()) Skipped 1 previous similar message [ 2741.574130] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 2741.586414] Lustre: Skipped 8 previous similar messages [ 2741.697364] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 2741.706354] Lustre: Skipped 8 previous similar messages [ 2741.782727] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1091 to 0x240000400:1121) [ 2741.785093] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1027 to 0x280000400:1121) [ 2745.323993] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2758.363748] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2760.429668] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2768.542526] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 2785.567985] Lustre: DEBUG MARKER: before 4096, after 4096 [ 2796.713948] Lustre: DEBUG MARKER: == replay-single test 20c: check that client eviction does not affect file content ========================================================== 03:18:42 (1785395922) [ 2798.113762] Lustre: 62857:0:(genops.c:1795:obd_export_evict_by_uuid()) lustre-MDT0000: evicting e3d8042e-f791-4a8b-9922-ea59ed21bdb2 at adminstrative request [ 2814.093904] Lustre: DEBUG MARKER: == replay-single test 21: |X| open(O_CREAT), unlink touch new, replay, close (test mds_cleanup_orphans) ========================================================== 03:19:00 (1785395940) [ 2821.335287] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2823.966587] Lustre: Failing over lustre-MDT0000 [ 2826.385939] Lustre: server umount lustre-MDT0000 complete [ 2853.353749] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xe4f321ee34c5ecbf [ 2854.553882] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 2854.577723] Lustre: Skipped 7 previous similar messages [ 2855.742750] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1124 to 0x240000400:1153) [ 2855.750505] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1123 to 0x280000400:1153) [ 2862.002629] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2875.119720] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2876.994259] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2886.916670] Lustre: DEBUG MARKER: == replay-single test 22: open(O_CREAT), |X| unlink, replay, close (test mds_cleanup_orphans) ========================================================== 03:20:13 (1785396013) [ 2893.233179] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2896.080410] Lustre: Failing over lustre-MDT0000 [ 2896.221514] Lustre: lustre-MDT0000: Not available for connect from 192.168.201.45@tcp (stopping) [ 2896.234414] Lustre: Skipped 1 previous similar message [ 2896.711328] Lustre: server umount lustre-MDT0000 complete [ 2925.956151] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xe4f321ee34c5f1c7 [ 2933.910865] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2936.348660] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1155 to 0x280000400:1185) [ 2936.349702] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1155 to 0x240000400:1185) [ 2945.355425] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2947.126818] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2956.535584] Lustre: DEBUG MARKER: == replay-single test 23: open(O_CREAT), |X| unlink touch new, replay, close (test mds_cleanup_orphans) ========================================================== 03:21:23 (1785396083) [ 2961.415779] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2963.681190] Lustre: Failing over lustre-MDT0000 [ 2963.946692] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2963.953729] Lustre: Skipped 1 previous similar message [ 2964.128686] Lustre: server umount lustre-MDT0000 complete [ 2984.416587] Lustre: 3300:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1785396097/real 1785396097] req@ffff9211a5107100 x1872120451445632/t0(0) o400->MGC192.168.201.145@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1785396113 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2984.448806] Lustre: 3300:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 72 previous similar messages [ 2995.265630] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 2995.269586] Lustre: Skipped 7 previous similar messages [ 3000.631278] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3008.118097] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1187 to 0x280000400:1217) [ 3008.123808] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1187 to 0x240000400:1217) [ 3014.317456] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3016.598918] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3028.172751] Lustre: DEBUG MARKER: == replay-single test 24: open(O_CREAT), replay, unlink, close (test mds_cleanup_orphans) ========================================================== 03:22:34 (1785396154) [ 3034.243773] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3036.636257] Lustre: Failing over lustre-MDT0000 [ 3037.040725] Lustre: server umount lustre-MDT0000 complete [ 3064.803586] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xe4f321ee34c5fb83 [ 3072.494504] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3079.697026] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1219 to 0x240000400:1249) [ 3079.700720] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1219 to 0x280000400:1249) [ 3086.355723] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3088.285505] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3098.637619] Lustre: DEBUG MARKER: == replay-single test 25: open(O_CREAT), unlink, replay, close (test mds_cleanup_orphans) ========================================================== 03:23:45 (1785396225) [ 3104.036049] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3107.265734] Lustre: Failing over lustre-MDT0000 [ 3107.669826] Lustre: server umount lustre-MDT0000 complete [ 3136.483242] LustreError: 3296:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9211c166b100 x1872120451481728/t0(0) o250->MGC192.168.201.145@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 [ 3136.506867] LustreError: 3296:0:(client.c:1391:ptlrpc_import_delay_req()) Skipped 62 previous similar messages [ 3136.866192] Lustre: lustre-MDT0000: Not available for connect from 192.168.201.45@tcp (not set up) [ 3139.049725] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1219 to 0x240000400:1281) [ 3139.052974] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1251 to 0x280000400:1281) [ 3145.272376] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3160.810697] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3163.207290] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3173.544419] Lustre: DEBUG MARKER: == replay-single test 26: |X| open(O_CREAT), unlink two, close one, replay, close one (test mds_cleanup_orphans) ========================================================== 03:25:00 (1785396300) [ 3178.493444] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3182.096067] Lustre: Failing over lustre-MDT0000 [ 3182.593303] Lustre: server umount lustre-MDT0000 complete [ 3212.522327] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xe4f321ee34c6058c [ 3212.532647] Lustre: MGC192.168.201.145@tcp: Connection restored to 0@lo (at 0@lo) [ 3212.544164] Lustre: Skipped 18 previous similar messages [ 3212.617126] LustreError: 71466:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.201.45@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3212.652075] LustreError: 71466:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 1 previous similar message [ 3214.897443] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1283 to 0x240000400:1313) [ 3214.899381] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1283 to 0x280000400:1313) [ 3220.284490] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3232.163955] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3234.193393] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3242.843689] Lustre: DEBUG MARKER: == replay-single test 27: |X| open(O_CREAT), unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 03:26:09 (1785396369) [ 3246.187812] LustreError: 72455:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 3246.190516] LustreError: 72455:0:(osd_handler.c:720:osd_ro()) Skipped 6 previous similar messages [ 3247.329247] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3249.366831] Lustre: Failing over lustre-MDT0000 [ 3249.573453] Lustre: server umount lustre-MDT0000 complete [ 3269.256823] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1315 to 0x280000400:1345) [ 3269.257487] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1315 to 0x240000400:1345) [ 3274.699736] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3288.132412] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3290.848631] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3304.899863] Lustre: DEBUG MARKER: == replay-single test 28: open(O_CREAT), |X| unlink two, close one, replay, close one (test mds_cleanup_orphans) ========================================================== 03:27:10 (1785396430) [ 3310.713682] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3313.074391] Lustre: Failing over lustre-MDT0000 [ 3313.563801] Lustre: server umount lustre-MDT0000 complete [ 3330.912137] 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 [ 3330.934550] Lustre: Skipped 15 previous similar messages [ 3331.040248] LustreError: MGC192.168.201.145@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3331.057606] LustreError: Skipped 7 previous similar messages [ 3349.570649] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3356.033892] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 3356.045064] Lustre: Skipped 7 previous similar messages [ 3356.268209] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 3356.279871] Lustre: Skipped 7 previous similar messages [ 3356.388890] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1347 to 0x240000400:1377) [ 3356.389037] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1347 to 0x280000400:1377) [ 3363.981828] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3366.258836] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3376.417255] Lustre: DEBUG MARKER: == replay-single test 29: open(O_CREAT), |X| unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 03:28:23 (1785396503) [ 3381.744717] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3384.251775] Lustre: Failing over lustre-MDT0000 [ 3384.659520] Lustre: server umount lustre-MDT0000 complete [ 3421.858514] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3427.978782] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1379 to 0x280000400:1409) [ 3427.979761] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1379 to 0x240000400:1409) [ 3435.390927] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3437.335368] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3447.771612] Lustre: DEBUG MARKER: == replay-single test 30: open(O_CREAT) two, unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 03:29:34 (1785396574) [ 3453.577698] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3456.683160] Lustre: Failing over lustre-MDT0000 [ 3457.334626] Lustre: server umount lustre-MDT0000 complete [ 3484.576958] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xe4f321ee34c61b11 [ 3485.710621] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 3485.736237] Lustre: Skipped 8 previous similar messages [ 3490.292630] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3499.618713] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1411 to 0x240000400:1441) [ 3499.626175] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1411 to 0x280000400:1441) [ 3506.239882] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3509.104558] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3521.911940] Lustre: DEBUG MARKER: == replay-single test 31: open(O_CREAT) two, unlink one, |X| unlink one, close two (test mds_cleanup_orphans) ========================================================== 03:30:47 (1785396647) [ 3528.879812] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3531.825486] Lustre: Failing over lustre-MDT0000 [ 3532.435757] Lustre: server umount lustre-MDT0000 complete [ 3561.091488] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1443 to 0x240000400:1473) [ 3561.096934] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1443 to 0x280000400:1473) [ 3565.590741] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3579.003099] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3581.225873] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3592.110308] Lustre: DEBUG MARKER: == replay-single test 32: close() notices client eviction; close() after client eviction ========================================================== 03:31:59 (1785396719) [ 3593.742953] Lustre: 80096:0:(genops.c:1795:obd_export_evict_by_uuid()) lustre-MDT0000: evicting e3d8042e-f791-4a8b-9922-ea59ed21bdb2 at adminstrative request [ 3606.969546] Lustre: DEBUG MARKER: == replay-single test 33a: fid seq shouldn't be reused after abort recovery ========================================================== 03:32:13 (1785396733) [ 3611.067421] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3613.939287] Lustre: Failing over lustre-MDT0000 [ 3614.370452] Lustre: server umount lustre-MDT0000 complete [ 3628.883824] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3628.893433] Lustre: Skipped 8 previous similar messages [ 3629.100691] Lustre: lustre-MDT0000: Aborting client recovery [ 3629.110281] LustreError: 80966:0:(ldlm_lib.c:3003:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 3629.120995] Lustre: 81014:0:(ldlm_lib.c:2403:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 3629.134381] Lustre: 81014:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client e3d8042e-f791-4a8b-9922-ea59ed21bdb2@ [ 3629.149038] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 3629.369606] Lustre: lustre-MDT0000-osd: cancel update llog [0x200000400:0x1:0x0] [ 3629.867527] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1480 to 0x280000400:1505) [ 3629.869766] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1479 to 0x240000400:1505) [ 3630.879072] Lustre: 3299:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1785396743/real 1785396743] req@ffff9211af4b3800 x1872120451613056/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1785396759 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3630.933026] Lustre: 3299:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 70 previous similar messages [ 3636.578177] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3653.363421] Lustre: DEBUG MARKER: == replay-single test 33b: test fid seq allocation ======= 03:32:59 (1785396779) [ 3659.584511] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3662.643523] Lustre: Failing over lustre-MDT0000 [ 3663.191772] LustreError: 80978:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.201.45@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3663.423716] Lustre: server umount lustre-MDT0000 complete [ 3678.602965] Lustre: *** cfs_fail_loc=1311, val=0*** [ 3678.657764] Lustre: lustre-MDT0000: Aborting client recovery [ 3678.662805] LustreError: 82294:0:(ldlm_lib.c:3003:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 3678.673464] Lustre: 82341:0:(ldlm_lib.c:2403:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 3678.680357] Lustre: 82341:0:(ldlm_lib.c:2403:target_recovery_overseer()) Skipped 2 previous similar messages [ 3678.686761] Lustre: 82341:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client e3d8042e-f791-4a8b-9922-ea59ed21bdb2@ [ 3678.700656] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 3678.841559] Lustre: lustre-MDT0000-osd: cancel update llog [0x200015bc0:0x1:0x0] [ 3679.064526] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1516 to 0x280000400:1537) [ 3679.104337] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1516 to 0x240000400:1537) [ 3685.739546] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3693.114576] Lustre: *** cfs_fail_loc=1311, val=0*** [ 3705.559795] Lustre: DEBUG MARKER: == replay-single test 34: abort recovery before client does replay (test mds_cleanup_orphans) ========================================================== 03:33:51 (1785396831) [ 3712.696927] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3716.437553] Lustre: Failing over lustre-MDT0000 [ 3717.159208] Lustre: server umount lustre-MDT0000 complete [ 3732.723411] Lustre: lustre-MDT0000: Aborting client recovery [ 3732.737291] LustreError: 83623:0:(ldlm_lib.c:3003:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 3732.766253] Lustre: 83672:0:(ldlm_lib.c:2403:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 3732.779456] Lustre: 83672:0:(ldlm_lib.c:2403:target_recovery_overseer()) Skipped 2 previous similar messages [ 3732.793462] Lustre: 83672:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client e3d8042e-f791-4a8b-9922-ea59ed21bdb2@ [ 3732.811356] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 3732.930255] Lustre: lustre-MDT0000-osd: cancel update llog [0x200016778:0x1:0x0] [ 3733.209430] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1544 to 0x280000400:1569) [ 3733.216290] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1543 to 0x240000400:1569) [ 3740.035875] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3759.501782] Lustre: DEBUG MARKER: == replay-single test 35: test recovery from llog for unlink op ========================================================== 03:34:45 (1785396885) [ 3760.479152] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 3760.485459] LustreError: 83633:0:(ldlm_lib.c:3345:target_send_reply_msg()) @@@ dropping reply req@ffff9211a5105880 x1872120430858240/t201863462916(0) o36->e3d8042e-f791-4a8b-9922-ea59ed21bdb2@192.168.201.45@tcp:80/0 lens 512/456 e 0 to 0 dl 1785396900 ref 1 fl Interpret:/200/0 rc 0/0 job:'rm.0' uid:0 gid:0 projid:4294967295 [ 3765.256695] Lustre: Failing over lustre-MDT0000 [ 3765.564599] Lustre: server umount lustre-MDT0000 complete [ 3778.557104] LustreError: 84806: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. [ 3778.588592] LustreError: 84806:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 1 previous similar message [ 3779.591587] Lustre: lustre-MDT0000: Aborting client recovery [ 3779.595033] LustreError: 84793:0:(ldlm_lib.c:3003:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 3779.627168] Lustre: 84842:0:(ldlm_lib.c:2403:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 3779.630135] Lustre: 84842:0:(ldlm_lib.c:2403:target_recovery_overseer()) Skipped 2 previous similar messages [ 3779.647113] Lustre: 84842:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client e3d8042e-f791-4a8b-9922-ea59ed21bdb2@ [ 3779.650843] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 3779.812742] Lustre: lustre-MDT0000-osd: cancel update llog [0x200017330:0x1:0x0] [ 3780.099085] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1543 to 0x240000400:1601) [ 3780.107160] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1571 to 0x280000400:1601) [ 3786.462943] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3802.055422] Lustre: DEBUG MARKER: SKIP: replay-single test_36 skipping ALWAYS excluded test 36 [ 3804.691613] Lustre: DEBUG MARKER: == replay-single test 37: abort recovery before client does replay (test mds_cleanup_orphans for directories) ========================================================== 03:35:31 (1785396931) [ 3810.168294] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3814.240080] Lustre: Failing over lustre-MDT0000 [ 3814.657810] Lustre: server umount lustre-MDT0000 complete [ 3829.878875] Lustre: lustre-MDT0000: Aborting client recovery [ 3829.894312] LustreError: 86218:0:(ldlm_lib.c:3003:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 3829.919201] Lustre: 86265:0:(ldlm_lib.c:2403:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 3829.944670] Lustre: 86265:0:(ldlm_lib.c:2403:target_recovery_overseer()) Skipped 2 previous similar messages [ 3829.988948] Lustre: 86265:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client e3d8042e-f791-4a8b-9922-ea59ed21bdb2@ [ 3830.042828] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 3830.315654] Lustre: lustre-MDT0000-osd: cancel update llog [0x200017b00:0x1:0x0] [ 3830.761435] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1543 to 0x240000400:1633) [ 3830.772688] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1571 to 0x280000400:1633) [ 3834.856801] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 3834.864769] Lustre: Skipped 21 previous similar messages [ 3838.080865] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3857.695959] Lustre: DEBUG MARKER: == replay-single test 38: test recovery from unlink llog (test llog_gen_rec) ========================================================== 03:36:24 (1785396984) [ 3901.736108] LustreError: 87355:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 3901.739458] LustreError: 87355:0:(osd_handler.c:720:osd_ro()) Skipped 8 previous similar messages [ 3903.306935] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3906.438910] Lustre: Failing over lustre-MDT0000 [ 3906.953465] Lustre: server umount lustre-MDT0000 complete [ 3933.634339] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3935.782387] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2034 to 0x280000400:2049) [ 3935.785358] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2034 to 0x240000400:2049) [ 3945.529098] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3947.699759] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3980.263247] Lustre: DEBUG MARKER: == replay-single test 39: test recovery from unlink llog (test llog_gen_rec) ========================================================== 03:38:26 (1785397106) [ 4012.914544] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4026.313312] Lustre: Failing over lustre-MDT0000 [ 4026.926644] Lustre: server umount lustre-MDT0000 complete [ 4046.096126] LustreError: MGC192.168.201.145@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4046.110452] LustreError: Skipped 9 previous similar messages [ 4046.596877] 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 [ 4046.616107] Lustre: Skipped 19 previous similar messages [ 4054.037796] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4054.340422] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4054.358458] Lustre: Skipped 4 previous similar messages [ 4060.376462] Lustre: lustre-MDT0000: Recovery over after 0:06, of 1 clients 1 recovered and 0 were evicted. [ 4060.402528] Lustre: Skipped 4 previous similar messages [ 4060.478924] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2450 to 0x280000400:2465) [ 4060.493128] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2450 to 0x240000400:2465) [ 4068.907527] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4070.755693] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4097.693586] Lustre: DEBUG MARKER: == replay-single test 41: read from a valid osc while other oscs are invalid ========================================================== 03:40:24 (1785397224) [ 4100.513929] Lustre: setting import lustre-OST0001_UUID INACTIVE by administrator request [ 4101.795960] Lustre: lustre-OST0001: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnecting [ 4101.813650] LustreError: lustre-OST0001-osc-MDT0000: This client was evicted by lustre-OST0001; in progress operations using this service will fail. [ 4110.673644] Lustre: DEBUG MARKER: == replay-single test 42: recovery after ost failure ===== 03:40:37 (1785397237) [ 4135.792192] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 4151.267681] Lustre: Failing over lustre-OST0000 [ 4151.430074] Lustre: server umount lustre-OST0000 complete [ 4151.654664] LustreError: 33797:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.201.45@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4152.410475] LustreError: lustre-OST0000-osc-MDT0000: operation ost_destroy to node 0@lo failed: rc = -107 [ 4152.428382] LustreError: Skipped 4 previous similar messages [ 4156.736402] LustreError: 35734:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.201.45@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4156.768690] LustreError: 35734:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 2 previous similar messages [ 4166.980674] LustreError: 14378:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.201.45@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4167.023848] LustreError: 14378:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 3 previous similar messages [ 4172.578800] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 4172.581814] Lustre: Skipped 18 previous similar messages [ 4182.189687] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4247.901893] Lustre: DEBUG MARKER: == replay-single test 43: mds osc import failure during recovery; don't LBUG ========================================================== 03:42:54 (1785397374) [ 4253.239073] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4256.787067] Lustre: Failing over lustre-MDT0000 [ 4257.239989] Lustre: server umount lustre-MDT0000 complete [ 4276.063068] Lustre: 3299:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1785397388/real 1785397388] req@ffff92108307d880 x1872120452154368/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1785397404 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4276.092185] Lustre: 3299:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 35 previous similar messages [ 4285.407719] LustreError: 3296:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9211982e9880 x1872120452156416/t0(0) o250->MGC192.168.201.145@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 [ 4285.432995] LustreError: 3296:0:(client.c:1391:ptlrpc_import_delay_req()) Skipped 3 previous similar messages [ 4286.396512] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4286.404313] Lustre: Skipped 7 previous similar messages [ 4292.235442] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4300.293851] Lustre: *** cfs_fail_loc=204, val=2147483648*** [ 4300.295128] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2867 to 0x240000400:2913) [ 4308.433945] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4310.217779] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4315.617579] LustreError: 94065:0:(osp_precreate.c:974:osp_precreate_cleanup_orphans()) lustre-OST0001-osc-MDT0000: cannot cleanup orphans: rc = -11 [ 4315.622269] Lustre: lustre-OST0001: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnecting [ 4316.640045] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2866 to 0x280000400:2881) [ 4331.968606] Lustre: DEBUG MARKER: == replay-single test 44a: race in target handle connect ========================================================== 03:44:18 (1785397458) [ 4339.139905] LustreError: 94037:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_race id 701 sleeping [ 4344.287412] LustreError: 94037:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 4344.300235] Lustre: lustre-MDT0000: Client e3d8042e-f791-4a8b-9922-ea59ed21bdb2 (at 192.168.201.45@tcp) reconnecting [ 4344.383898] LustreError: 33797:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_fail_race id 701 waking [ 4346.872946] LustreError: 94770:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_race id 701 sleeping [ 4351.967379] LustreError: 94770:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 4351.984875] Lustre: lustre-MDT0000: Client e3d8042e-f791-4a8b-9922-ea59ed21bdb2 (at 192.168.201.45@tcp) reconnecting [ 4354.786624] LustreError: 94037:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_race id 701 sleeping [ 4360.159340] LustreError: 94037:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 4360.175194] Lustre: lustre-MDT0000: Client e3d8042e-f791-4a8b-9922-ea59ed21bdb2 (at 192.168.201.45@tcp) reconnecting [ 4362.536858] LustreError: 94040:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_race id 701 sleeping [ 4367.839245] LustreError: 94040:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 4370.452907] LustreError: 94041:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_race id 701 sleeping [ 4375.519127] LustreError: 94041:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 4375.530416] Lustre: lustre-MDT0000: Client e3d8042e-f791-4a8b-9922-ea59ed21bdb2 (at 192.168.201.45@tcp) reconnecting [ 4375.544104] Lustre: Skipped 1 previous similar message [ 4385.587722] LustreError: 94770:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_race id 701 sleeping [ 4385.591557] LustreError: 94770:0:(ldlm_lib.c:1178:target_handle_connect()) Skipped 1 previous similar message [ 4390.879279] LustreError: 94770:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 4390.885457] LustreError: 94770:0:(ldlm_lib.c:1178:target_handle_connect()) Skipped 1 previous similar message [ 4398.559136] Lustre: lustre-MDT0000: Client e3d8042e-f791-4a8b-9922-ea59ed21bdb2 (at 192.168.201.45@tcp) reconnecting [ 4398.571231] Lustre: Skipped 2 previous similar messages [ 4408.848943] LustreError: 94770:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_race id 701 sleeping [ 4408.866903] LustreError: 94770:0:(ldlm_lib.c:1178:target_handle_connect()) Skipped 2 previous similar messages [ 4413.919835] LustreError: 94770:0:(ldlm_lib.c:1178:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 4413.935185] LustreError: 94770:0:(ldlm_lib.c:1178:target_handle_connect()) Skipped 2 previous similar messages [ 4425.555183] Lustre: DEBUG MARKER: == replay-single test 44b: race in target handle connect ========================================================== 03:45:52 (1785397552) [ 4428.298878] LustreError: 94041:0:(ldlm_lib.c:1435:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 4438.354910] Lustre: lustre-MDT0000: Export ffff92118a8e2000 already connecting from 192.168.201.45@tcp [ 4439.359843] Lustre: lustre-MDT0000: Export ffff92118a8e2000 already connecting from 192.168.201.45@tcp [ 4444.479556] Lustre: lustre-MDT0000: Export ffff92118a8e2000 already connecting from 192.168.201.45@tcp [ 4449.601199] Lustre: lustre-MDT0000: Export ffff92118a8e2000 already connecting from 192.168.201.45@tcp [ 4454.720600] Lustre: lustre-MDT0000: Export ffff92118a8e2000 already connecting from 192.168.201.45@tcp [ 4454.726767] Lustre: Skipped 1 previous similar message [ 4464.959118] Lustre: lustre-MDT0000: Export ffff92118a8e2000 already connecting from 192.168.201.45@tcp [ 4464.973610] Lustre: Skipped 1 previous similar message [ 4468.391314] LustreError: 94041:0:(ldlm_lib.c:1435:target_handle_connect()) cfs_fail_timeout id 704 awake [ 4468.431177] Lustre: 94041:0:(service.c:2582:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/21s); client may timeout req@ffff9211c1e24e00 x1872120433507328/t0(0) o38->e3d8042e-f791-4a8b-9922-ea59ed21bdb2@192.168.201.45@tcp:0/0 lens 520/416 e 0 to 0 dl 1785397576 ref 1 fl Complete:H/200/0 rc 0/0 job:'lctl.0' uid:0 gid:0 projid:4294967295 [ 4470.078878] Lustre: lustre-MDT0000: Client e3d8042e-f791-4a8b-9922-ea59ed21bdb2 (at 192.168.201.45@tcp) reconnecting [ 4470.082599] Lustre: Skipped 3 previous similar messages [ 4470.099714] LustreError: 94770:0:(ldlm_lib.c:1435:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 4494.691257] Lustre: lustre-MDT0000: Export ffff92118a8e2000 already connecting from 192.168.201.45@tcp [ 4510.177055] LustreError: 94770:0:(ldlm_lib.c:1435:target_handle_connect()) cfs_fail_timeout id 704 awake [ 4510.203287] Lustre: 94770:0:(service.c:2582:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/20s); client may timeout req@ffff9211bb309180 x1872120433510400/t0(0) o38->e3d8042e-f791-4a8b-9922-ea59ed21bdb2@192.168.201.45@tcp:0/0 lens 520/416 e 0 to 0 dl 1785397618 ref 1 fl Complete:H/200/0 rc 0/0 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4515.138891] LustreError: 94041:0:(ldlm_lib.c:1435:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 4539.716233] Lustre: lustre-MDT0000: Export ffff92118a8e2000 already connecting from 192.168.201.45@tcp [ 4539.729643] Lustre: Skipped 4 previous similar messages [ 4555.199166] LustreError: 94041:0:(ldlm_lib.c:1435:target_handle_connect()) cfs_fail_timeout id 704 awake [ 4555.223932] Lustre: 94041:0:(service.c:2582:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/20s); client may timeout req@ffff92118569c700 x1872120433512576/t0(0) o38->e3d8042e-f791-4a8b-9922-ea59ed21bdb2@192.168.201.45@tcp:0/0 lens 520/416 e 0 to 0 dl 1785397663 ref 1 fl Complete:H/200/0 rc 0/0 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4560.195731] Lustre: lustre-MDT0000: Client e3d8042e-f791-4a8b-9922-ea59ed21bdb2 (at 192.168.201.45@tcp) reconnecting [ 4560.202808] Lustre: Skipped 1 previous similar message [ 4560.208659] LustreError: 94770:0:(ldlm_lib.c:1435:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 4600.307218] LustreError: 94770:0:(ldlm_lib.c:1435:target_handle_connect()) cfs_fail_timeout id 704 awake [ 4600.320602] Lustre: 94770:0:(service.c:2582:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/20s); client may timeout req@ffff9211bb2e1180 x1872120433514752/t0(0) o38->e3d8042e-f791-4a8b-9922-ea59ed21bdb2@192.168.201.45@tcp:0/0 lens 520/416 e 0 to 0 dl 1785397708 ref 1 fl Complete:H/200/0 rc 0/0 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4605.258022] LustreError: 94040:0:(ldlm_lib.c:1435:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 4629.855934] Lustre: lustre-MDT0000: Export ffff92118a8e2000 already connecting from 192.168.201.45@tcp [ 4629.870214] Lustre: Skipped 9 previous similar messages [ 4645.351104] LustreError: 94040:0:(ldlm_lib.c:1435:target_handle_connect()) cfs_fail_timeout id 704 awake [ 4645.362437] Lustre: 94040:0:(service.c:2582:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/21s); client may timeout req@ffff9211a5106300 x1872120433516928/t0(0) o38->e3d8042e-f791-4a8b-9922-ea59ed21bdb2@192.168.201.45@tcp:0/0 lens 520/416 e 0 to 0 dl 1785397753 ref 1 fl Complete:H/200/0 rc 0/0 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4648.254484] LustreError: 94041:0:(ldlm_lib.c:1435:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 4668.188117] LustreError: 94041:0:(ldlm_lib.c:1435:target_handle_connect()) cfs_fail_timeout interrupted [ 4676.960727] Lustre: DEBUG MARKER: == replay-single test 44c: race in target handle connect ========================================================== 03:50:03 (1785397803) [ 4681.482449] LustreError: 97900:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 4681.492466] LustreError: 97900:0:(osd_handler.c:720:osd_ro()) Skipped 3 previous similar messages [ 4682.753667] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4688.879160] Lustre: Failing over lustre-MDT0000 [ 4689.272171] LustreError: 94041:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.201.45@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4689.288658] LustreError: 94041:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 2 previous similar messages [ 4689.387382] 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 [ 4689.404812] Lustre: Skipped 6 previous similar messages [ 4689.511951] Lustre: server umount lustre-MDT0000 complete [ 4699.892174] LustreError: MGC192.168.201.145@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4699.910608] LustreError: Skipped 1 previous similar message [ 4700.449325] Lustre: *** cfs_fail_loc=712, val=0*** [ 4700.471065] LustreError: 35732:0:(service.c:1394:ptlrpc_check_req()) @@@ Invalid replay without recovery req@ffff9211981bea00 x1872120452246400/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 [ 4700.786130] Lustre: lustre-MDT0000: Aborting client recovery [ 4700.788396] LustreError: 98526:0:(ldlm_lib.c:3003:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 4700.793696] Lustre: 98575:0:(ldlm_lib.c:2403:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 4700.800701] Lustre: 98575:0:(ldlm_lib.c:2403:target_recovery_overseer()) Skipped 2 previous similar messages [ 4700.804370] Lustre: 98575:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client e3d8042e-f791-4a8b-9922-ea59ed21bdb2@ [ 4700.809537] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 4700.853095] Lustre: lustre-MDT0000-osd: cancel update llog [0x2000182d0:0x1:0x0] [ 4701.043088] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2866 to 0x280000400:2913) [ 4701.049604] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2867 to 0x240000400:2945) [ 4707.492914] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4714.854388] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 4714.861584] Lustre: Skipped 10 previous similar messages [ 4718.262440] Lustre: Failing over lustre-MDT0000 [ 4718.935514] Lustre: server umount lustre-MDT0000 complete [ 4754.357419] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4759.881429] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4759.883783] Lustre: Skipped 2 previous similar messages [ 4759.991473] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4759.997035] Lustre: Skipped 2 previous similar messages [ 4760.090552] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2867 to 0x240000400:2977) [ 4760.092874] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2866 to 0x280000400:2945) [ 4767.890158] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4770.340863] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4780.919746] Lustre: DEBUG MARKER: == replay-single test 45: Handle failed close ============ 03:51:47 (1785397907) [ 4781.190632] Lustre: lustre-MDT0000: Client e3d8042e-f791-4a8b-9922-ea59ed21bdb2 (at 192.168.201.45@tcp) reconnecting [ 4781.205078] Lustre: Skipped 2 previous similar messages [ 4792.932498] Lustre: DEBUG MARKER: == replay-single test 46: Don't leak file handle after open resend (3325) ========================================================== 03:51:58 (1785397918) [ 4794.350475] Lustre: *** cfs_fail_loc=122, val=2147483648*** [ 4794.357897] LustreError: 99452:0:(ldlm_lib.c:3345:target_send_reply_msg()) @@@ dropping reply req@ffff9211857a3b80 x1872120433575808/t0(0) o700->e3d8042e-f791-4a8b-9922-ea59ed21bdb2@192.168.201.45@tcp:359/0 lens 264/248 e 0 to 0 dl 1785397934 ref 1 fl Interpret:/200/0 rc 0/0 job:'touch.0' uid:0 gid:0 projid:4294967295 [ 4815.708200] Lustre: Failing over lustre-MDT0000 [ 4816.286407] Lustre: server umount lustre-MDT0000 complete [ 4844.006368] LustreError: 3296:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9211c1e27480 x1872120452279552/t0(0) o250->MGC192.168.201.145@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 [ 4845.111699] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4845.121419] Lustre: Skipped 5 previous similar messages [ 4847.702301] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2979 to 0x240000400:3009) [ 4847.712240] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2947 to 0x280000400:2977) [ 4851.708033] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4864.893542] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4866.962397] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4882.646561] Lustre: DEBUG MARKER: == replay-single test 47: MDS->OSC failure during precreate cleanup (2824) ========================================================== 03:53:29 (1785398009) [ 4886.214901] Lustre: Failing over lustre-OST0000 [ 4886.359675] Lustre: server umount lustre-OST0000 complete [ 4888.387475] LustreError: 33797:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.201.45@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4908.645435] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 4908.658160] Lustre: Skipped 3 previous similar messages [ 4916.185356] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4928.357985] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 4930.648264] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 5007.542636] Lustre: DEBUG MARKER: == replay-single test 48: MDS->OSC failure during precreate cleanup (2824) ========================================================== 03:55:34 (1785398134) [ 5012.794436] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5015.726179] Lustre: Failing over lustre-MDT0000 [ 5016.037623] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5016.239145] Lustre: server umount lustre-MDT0000 complete [ 5042.488289] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5043.158623] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2998 to 0x280000400:3041) [ 5043.161398] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3030 to 0x240000400:3073) [ 5109.928612] Lustre: *** cfs_fail_loc=216, val=0*** [ 5124.106978] Lustre: DEBUG MARKER: == replay-single test 50: Double OSC recovery, don't LASSERT (3812) ========================================================== 03:57:29 (1785398249) [ 5126.551906] Lustre: lustre-OST0000: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnecting [ 5126.558920] Lustre: Skipped 2 previous similar messages [ 5141.558976] Lustre: DEBUG MARKER: == replay-single test 52: time out lock replay (3764) ==== 03:57:48 (1785398268) [ 5145.874141] Lustre: Failing over lustre-MDT0000 [ 5146.564230] Lustre: server umount lustre-MDT0000 complete [ 5163.743266] Lustre: 3300:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1785398276/real 1785398276] req@ffff92118a3ef480 x1872120452363904/t0(0) o400->MGC192.168.201.145@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1785398292 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5163.778029] Lustre: 3300:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 29 previous similar messages [ 5173.985210] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xe4f321ee34caa699 [ 5175.886955] Lustre: *** cfs_fail_loc=157, val=2147483648*** [ 5175.891345] LustreError: 105757:0:(ldlm_lib.c:3345:target_send_reply_msg()) @@@ dropping reply req@ffff921185dfd500 x1872120433700992/t0(0) o101->e3d8042e-f791-4a8b-9922-ea59ed21bdb2@192.168.201.45@tcp:740/0 lens 328/344 e 0 to 0 dl 1785398315 ref 1 fl Complete:/240/0 rc 0/0 job:'ldlm_lock_repla.0' uid:0 gid:0 projid:4294967295 [ 5180.461538] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5192.509640] Lustre: lustre-MDT0000: Client e3d8042e-f791-4a8b-9922-ea59ed21bdb2 (at 192.168.201.45@tcp) reconnected, waiting for 1 clients in recovery for 1:23 [ 5192.701357] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3052 to 0x280000400:3073) [ 5192.707731] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3085 to 0x240000400:3105) [ 5200.828707] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5202.724630] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5215.226236] Lustre: DEBUG MARKER: == replay-single test 53a: |X| close request while two MDC requests in flight ========================================================== 03:59:01 (1785398341) [ 5218.210419] Lustre: *** cfs_fail_loc=115, val=2147483648*** [ 5224.841322] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5227.733517] Lustre: Failing over lustre-MDT0000 [ 5228.097844] Lustre: server umount lustre-MDT0000 complete [ 5259.169618] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3107 to 0x240000400:3137) [ 5259.177226] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3052 to 0x280000400:3105) [ 5264.593574] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5276.334260] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5278.518281] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5290.313933] Lustre: DEBUG MARKER: == replay-single test 53b: |X| open request while two MDC requests in flight ========================================================== 04:00:16 (1785398416) [ 5292.184250] Lustre: *** cfs_fail_loc=107, val=2147483648*** [ 5298.274606] LustreError: 108519:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 5298.286418] LustreError: 108519:0:(osd_handler.c:720:osd_ro()) Skipped 2 previous similar messages [ 5299.813576] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5302.120350] Lustre: Failing over lustre-MDT0000 [ 5302.414992] Lustre: server umount lustre-MDT0000 complete [ 5318.431126] LustreError: MGC192.168.201.145@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5318.446754] LustreError: Skipped 5 previous similar messages [ 5319.455127] 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 [ 5319.462823] Lustre: Skipped 14 previous similar messages [ 5330.276888] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 5330.288783] Lustre: Skipped 15 previous similar messages [ 5333.604513] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3107 to 0x240000400:3169) [ 5333.605150] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3107 to 0x280000400:3137) [ 5337.420425] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5350.655114] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5353.725642] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5368.448358] Lustre: DEBUG MARKER: == replay-single test 53c: |X| open request and close request while two MDC requests in flight ========================================================== 04:01:34 (1785398494) [ 5370.028861] Lustre: *** cfs_fail_loc=107, val=2147483648*** [ 5372.372896] Lustre: *** cfs_fail_loc=115, val=2147483648*** [ 5377.502983] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5380.124277] Lustre: Failing over lustre-MDT0000 [ 5380.500463] Lustre: server umount lustre-MDT0000 complete [ 5408.226559] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xe4f321ee34cab660 [ 5412.168884] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 5412.180741] Lustre: Skipped 6 previous similar messages [ 5412.323260] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 5412.333923] Lustre: Skipped 6 previous similar messages [ 5412.399343] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3171 to 0x240000400:3201) [ 5412.401236] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3107 to 0x280000400:3169) [ 5414.829392] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5430.222226] Lustre: DEBUG MARKER: == replay-single test 53d: close reply while two MDC requests in flight ========================================================== 04:02:36 (1785398556) [ 5432.347190] Lustre: *** cfs_fail_loc=13b, val=315*** [ 5432.349602] Lustre: *** cfs_fail_loc=13b, val=2147483648*** [ 5432.360219] LustreError: 110734:0:(ldlm_lib.c:3345:target_send_reply_msg()) @@@ dropping reply req@ffff9211a51e7480 x1872120433756416/t257698037777(0) o35->e3d8042e-f791-4a8b-9922-ea59ed21bdb2@192.168.201.45@tcp:242/0 lens 392/456 e 0 to 0 dl 1785398572 ref 1 fl Interpret:/600/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 5436.033449] Lustre: Failing over lustre-MDT0000 [ 5436.361394] Lustre: server umount lustre-MDT0000 complete [ 5465.064495] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xe4f321ee34cabc80 [ 5466.264911] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 5466.271777] Lustre: Skipped 6 previous similar messages [ 5472.799795] Lustre: 111979:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff921183596a00 x1872120433756416/t257698037777(0) o35->e3d8042e-f791-4a8b-9922-ea59ed21bdb2@192.168.201.45@tcp:282/0 lens 392/456 e 0 to 0 dl 1785398612 ref 1 fl Interpret:/602/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 5472.800588] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5472.809167] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3171 to 0x280000400:3201) [ 5472.812195] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3171 to 0x240000400:3233) [ 5487.891688] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5490.868139] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5502.367720] Lustre: DEBUG MARKER: == replay-single test 53e: |X| open reply while two MDC requests in flight ========================================================== 04:03:49 (1785398629) [ 5503.878434] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 5503.888943] LustreError: 112531:0:(ldlm_lib.c:3345:target_send_reply_msg()) @@@ dropping reply req@ffff921183594000 x1872120433772032/t261993005072(0) o36->e3d8042e-f791-4a8b-9922-ea59ed21bdb2@192.168.201.45@tcp:313/0 lens 504/448 e 0 to 0 dl 1785398643 ref 1 fl Interpret:/200/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 5513.599951] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5516.668697] Lustre: Failing over lustre-MDT0000 [ 5517.256282] Lustre: server umount lustre-MDT0000 complete [ 5546.975884] LustreError: 3296:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9211c1e26a00 x1872120452461312/t0(0) o250->MGC192.168.201.145@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 [ 5548.138533] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 5548.150992] Lustre: Skipped 6 previous similar messages [ 5554.920027] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5565.382144] Lustre: 113622:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff921183597b80 x1872120433772032/t261993005072(0) o36->e3d8042e-f791-4a8b-9922-ea59ed21bdb2@192.168.201.45@tcp:375/0 lens 504/2880 e 0 to 0 dl 1785398705 ref 1 fl Interpret:/202/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 5565.416718] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3171 to 0x240000400:3265) [ 5565.422313] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3203 to 0x280000400:3233) [ 5573.409526] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5575.871484] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5587.670797] Lustre: DEBUG MARKER: == replay-single test 53f: |X| open reply and close reply while two MDC requests in flight ========================================================== 04:05:14 (1785398714) [ 5589.075421] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 5589.077655] LustreError: 113621:0:(ldlm_lib.c:3345:target_send_reply_msg()) @@@ dropping reply req@ffff9211b483d180 x1872120433787264/t266287972368(0) o36->e3d8042e-f791-4a8b-9922-ea59ed21bdb2@192.168.201.45@tcp:398/0 lens 504/448 e 0 to 0 dl 1785398728 ref 1 fl Interpret:/200/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 5591.486309] Lustre: *** cfs_fail_loc=13b, val=315*** [ 5596.534818] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5599.385451] Lustre: Failing over lustre-MDT0000 [ 5599.945983] Lustre: server umount lustre-MDT0000 complete [ 5630.232686] Lustre: lustre-MDT0000: Not available for connect from 192.168.201.45@tcp (not set up) [ 5630.254377] Lustre: Skipped 1 previous similar message [ 5632.117040] Lustre: 115254:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9211c1e27480 x1872120433787264/t266287972368(0) o36->e3d8042e-f791-4a8b-9922-ea59ed21bdb2@192.168.201.45@tcp:441/0 lens 504/2880 e 0 to 0 dl 1785398771 ref 1 fl Interpret:/202/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 5632.119980] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3171 to 0x240000400:3297) [ 5632.120193] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3235 to 0x280000400:3265) [ 5632.165070] Lustre: 115254:0:(mdt_recovery.c:102:mdt_req_from_lrd()) Skipped 1 previous similar message [ 5639.546452] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5655.602237] Lustre: DEBUG MARKER: == replay-single test 53g: |X| drop open reply and close request while close and open are both in flight ========================================================== 04:06:22 (1785398782) [ 5656.922159] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 5656.934593] Lustre: Skipped 1 previous similar message [ 5656.936243] LustreError: 115251:0:(ldlm_lib.c:3345:target_send_reply_msg()) @@@ dropping reply req@ffff9211bb30f100 x1872120433801344/t270582939664(0) o36->e3d8042e-f791-4a8b-9922-ea59ed21bdb2@192.168.201.45@tcp:466/0 lens 504/448 e 0 to 0 dl 1785398796 ref 1 fl Interpret:/200/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 5656.976859] LustreError: 115251:0:(ldlm_lib.c:3345:target_send_reply_msg()) Skipped 1 previous similar message [ 5659.224212] Lustre: *** cfs_fail_loc=115, val=2147483648*** [ 5665.440516] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5668.218672] Lustre: Failing over lustre-MDT0000 [ 5668.613424] Lustre: server umount lustre-MDT0000 complete [ 5698.946153] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3171 to 0x240000400:3329) [ 5698.947511] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3267 to 0x280000400:3297) [ 5698.988110] Lustre: 116743:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9211bfbbed80 x1872120433801344/t270582939664(0) o36->e3d8042e-f791-4a8b-9922-ea59ed21bdb2@192.168.201.45@tcp:508/0 lens 504/2880 e 0 to 0 dl 1785398838 ref 1 fl Interpret:/202/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 5704.867828] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5718.109714] Lustre: DEBUG MARKER: == replay-single test 53h: open request and close reply while two MDC requests in flight ========================================================== 04:07:24 (1785398844) [ 5719.872074] Lustre: *** cfs_fail_loc=107, val=2147483648*** [ 5722.011876] Lustre: *** cfs_fail_loc=13b, val=315*** [ 5722.016923] Lustre: *** cfs_fail_loc=13b, val=2147483648*** [ 5722.022982] LustreError: 116746:0:(ldlm_lib.c:3345:target_send_reply_msg()) @@@ dropping reply req@ffff9211a5106d80 x1872120433814400/t274877906960(0) o35->e3d8042e-f791-4a8b-9922-ea59ed21bdb2@192.168.201.45@tcp:531/0 lens 392/456 e 0 to 0 dl 1785398861 ref 1 fl Interpret:/600/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 5728.041372] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5730.723684] Lustre: Failing over lustre-MDT0000 [ 5731.190528] Lustre: server umount lustre-MDT0000 complete [ 5761.002086] Lustre: 118146:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9211bfb6e680 x1872120433814400/t274877906960(0) o35->e3d8042e-f791-4a8b-9922-ea59ed21bdb2@192.168.201.45@tcp:570/0 lens 392/456 e 0 to 0 dl 1785398900 ref 1 fl Interpret:/602/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 5761.023985] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3331 to 0x240000400:3361) [ 5761.040039] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3267 to 0x280000400:3329) [ 5764.583815] Lustre: 3298:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1785398876/real 1785398876] req@ffff9211bfbbf480 x1872120452515840/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1785398892 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5764.617446] Lustre: 3298:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 79 previous similar messages [ 5765.551088] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5780.608719] Lustre: DEBUG MARKER: == replay-single test 55: let MDS_CHECK_RESENT return the original return code instead of 0 ========================================================== 04:08:26 (1785398906) [ 5782.676952] Lustre: *** cfs_fail_loc=12b, val=2147483991*** [ 5782.703105] LustreError: 118548:0:(ldlm_lib.c:3345:target_send_reply_msg()) @@@ dropping reply req@ffff9211c1e26a00 x1872120433825280/t279172874255(0) o101->e3d8042e-f791-4a8b-9922-ea59ed21bdb2@192.168.201.45@tcp:592/0 lens 664/608 e 0 to 0 dl 1785398922 ref 1 fl Interpret:/600/0 rc 301/0 job:'touch.0' uid:0 gid:0 projid:0 [ 5799.234649] Lustre: lustre-MDT0000: Client e3d8042e-f791-4a8b-9922-ea59ed21bdb2 (at 192.168.201.45@tcp) reconnecting [ 5799.241568] Lustre: Skipped 1 previous similar message [ 5799.259751] Lustre: 118145:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff92118a3efb80 x1872120433825280/t279172874255(0) o101->e3d8042e-f791-4a8b-9922-ea59ed21bdb2@192.168.201.45@tcp:608/0 lens 664/3488 e 0 to 0 dl 1785398938 ref 1 fl Interpret:/602/0 rc 0/0 job:'touch.0' uid:0 gid:0 projid:0 [ 5809.144128] Lustre: DEBUG MARKER: == replay-single test 56: don't replay a symlink open request (3440) ========================================================== 04:08:55 (1785398935) [ 5814.215322] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5816.718245] Lustre: Failing over lustre-MDT0000 [ 5817.063465] Lustre: server umount lustre-MDT0000 complete [ 5837.269576] LustreError: 119838: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. [ 5837.283514] LustreError: 119838:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 7 previous similar messages [ 5838.827307] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3331 to 0x240000400:3393) [ 5838.835717] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3331 to 0x280000400:3361) [ 5844.904775] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5858.553457] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5860.706912] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5882.286907] Lustre: DEBUG MARKER: == replay-single test 57: test recovery from llog for setattr op ========================================================== 04:10:08 (1785399008) [ 5888.863665] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5891.203927] Lustre: Failing over lustre-MDT0000 [ 5891.498344] Lustre: server umount lustre-MDT0000 complete [ 5920.068121] Lustre: lustre-MDT0000: Not available for connect from 192.168.201.45@tcp (not set up) [ 5921.766921] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3363 to 0x280000400:3393) [ 5921.773143] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3331 to 0x240000400:3425) [ 5925.290394] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5934.821105] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 5934.843510] Lustre: Skipped 17 previous similar messages [ 5939.187902] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5941.257979] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5948.759065] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 5964.342241] Lustre: DEBUG MARKER: == replay-single test 58a: test recovery from llog for setattr op (test llog_gen_rec) ========================================================== 04:11:31 (1785399091) [ 6020.089671] LustreError: 123027:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 6020.100441] LustreError: 123027:0:(osd_handler.c:720:osd_ro()) Skipped 7 previous similar messages [ 6021.536358] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 6024.317019] Lustre: Failing over lustre-MDT0000 [ 6025.240822] Lustre: server umount lustre-MDT0000 complete [ 6042.339804] LustreError: MGC192.168.201.145@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 6042.360707] LustreError: Skipped 8 previous similar messages [ 6042.580365] 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 [ 6042.606854] Lustre: Skipped 17 previous similar messages [ 6052.576817] LustreError: 3296:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff92118569f100 x1872120452597760/t0(0) o250->MGC192.168.201.145@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 [ 6054.223377] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 6054.237546] Lustre: Skipped 7 previous similar messages [ 6055.121042] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 6055.124078] Lustre: Skipped 7 previous similar messages [ 6055.204854] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:4644 to 0x280000400:4673) [ 6055.205880] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:4676 to 0x240000400:4705) [ 6060.517702] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6072.756315] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6075.651696] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6150.069768] Lustre: DEBUG MARKER: == replay-single test 58b: test replay of setxattr op ==== 04:14:36 (1785399276) [ 6156.895424] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 6159.855472] Lustre: Failing over lustre-MDT0000 [ 6160.677097] Lustre: server umount lustre-MDT0000 complete [ 6191.237697] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 6191.244028] Lustre: Skipped 6 previous similar messages [ 6191.340739] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 6191.349307] Lustre: Skipped 7 previous similar messages [ 6197.902410] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6203.532407] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:4644 to 0x280000400:4705) [ 6203.532869] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:4707 to 0x240000400:4737) [ 6213.093269] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6215.261758] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6228.518768] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount FULL mgc.*.mgs_server_uuid 1475 0 [ 6231.238646] Lustre: DEBUG MARKER: mgc.*.mgs_server_uuid in FULL state after 0 sec [ 6240.394093] Lustre: DEBUG MARKER: == replay-single test 58c: resend/reconstruct setxattr op ========================================================== 04:16:06 (1785399366) [ 6248.927330] Lustre: *** cfs_fail_loc=123, val=2147483648*** [ 6272.071650] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 6272.080988] Lustre: Skipped 1 previous similar message [ 6272.088936] LustreError: 126513:0:(ldlm_lib.c:3345:target_send_reply_msg()) @@@ dropping reply req@ffff9211b42c5850 x1872120436615168/t296352743435(0) o36->e3d8042e-f791-4a8b-9922-ea59ed21bdb2@192.168.201.45@tcp:326/0 lens 66040/440 e 0 to 0 dl 1785399411 ref 1 fl Interpret:/600/0 rc 0/0 job:'setfattr.0' uid:0 gid:0 projid:0 [ 6288.220758] Lustre: 126512:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9211c1b69880 x1872120436615168/t296352743435(0) o36->e3d8042e-f791-4a8b-9922-ea59ed21bdb2@192.168.201.45@tcp:342/0 lens 66040/440 e 0 to 0 dl 1785399427 ref 1 fl Interpret:/602/0 rc 0/0 job:'setfattr.0' uid:0 gid:0 projid:0 [ 6302.796901] Lustre: DEBUG MARKER: SKIP: replay-single test_59 skipping ALWAYS excluded test 59 [ 6304.901915] Lustre: DEBUG MARKER: == replay-single test 60: test llog post recovery init vs llog unlink ========================================================== 04:17:11 (1785399431) [ 6318.728198] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 6322.068829] Lustre: Failing over lustre-MDT0000 [ 6322.195337] LustreError: 3297:0:(client.c:1381:ptlrpc_import_delay_req()) @@@ IMP_CLOSED req@ffff9211c1824700 x1872120453307904/t0(0) o6->lustre-OST0001-osc-MDT0000@0@lo:28/4 lens 544/432 e 0 to 0 dl 0 ref 1 fl Rpc:QU/200/ffffffff rc 0/-1 job:'osp-syn-1-0.0' uid:0 gid:0 projid:4294967295 [ 6322.480560] Lustre: server umount lustre-MDT0000 complete [ 6351.252145] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:4839 to 0x240000400:4865) [ 6351.253252] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:4806 to 0x280000400:4833) [ 6354.957347] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6366.519857] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6368.325451] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6386.066427] Lustre: DEBUG MARKER: == replay-single test 61a: test race llog recovery vs llog cleanup ========================================================== 04:18:31 (1785399511) [ 6418.669608] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 6436.116039] Lustre: Failing over lustre-OST0000 [ 6436.314345] Lustre: server umount lustre-OST0000 complete [ 6436.331628] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 6436.339954] LustreError: Skipped 3 previous similar messages [ 6436.357431] LustreError: 6601: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. [ 6436.380832] LustreError: 6601:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 1 previous similar message [ 6452.709988] LustreError: 35739: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. [ 6452.723386] LustreError: 35739:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 3 previous similar messages [ 6464.272166] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6479.346822] Lustre: Failing over lustre-OST0000 [ 6479.363397] LustreError: 130351:0:(ldlm_lib.c:3003:target_stop_recovery_thread()) lustre-OST0000: Aborting recovery [ 6479.370696] Lustre: 129789:0:(ldlm_lib.c:2403:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 6479.377651] Lustre: 129789:0:(ldlm_lib.c:2403:target_recovery_overseer()) Skipped 2 previous similar messages [ 6479.384782] Lustre: 129789:0:(ldlm_lib.c:1913:abort_req_replay_queue()) @@@ aborted: req@ffff9211bc03c700 x1872120453365632/t0(17179870644) o6->lustre-MDT0000-mdtlov_UUID@0@lo:537/0 lens 544/0 e 2 to 0 dl 1785399622 ref 1 fl Complete:/204/ffffffff rc 0/-1 job:'osp-syn-0-0.0' uid:0 gid:0 projid:4294967295 [ 6479.405251] LustreError: 129789:0:(ofd_obd.c:1324:ofd_iocontrol()) lustre-OST0000: iocontrol from 'tgt_recover_0' cmd=c00866c1 _IOWR('f', 193, 8) unrecognized: rc = -25 [ 6479.407065] LustreError: lustre-OST0000-osc-MDT0000: operation ost_destroy to node 0@lo failed: rc = -19 [ 6479.438832] Lustre: lustre-OST0000: Not available for connect from 0@lo (stopping) [ 6479.597195] Lustre: server umount lustre-OST0000 complete [ 6489.568303] LustreError: 35731: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. [ 6489.588360] LustreError: 35731:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 1 previous similar message [ 6507.262436] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6511.495663] LustreError: 3296:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 0, old was -19 req@ffff9211bb30fb80 x1872120453365632/t17179870644(17179870644) o6->lustre-OST0000-osc-MDT0000@0@lo:28/4 lens 544/432 e 3 to 0 dl 1785399658 ref 2 fl Interpret:RQU/204/0 rc 0/0 job:'osp-syn-0-0.0' uid:0 gid:0 projid:4294967295 [ 6519.439690] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 6521.553705] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 6563.908965] Lustre: DEBUG MARKER: == replay-single test 61b: test race mds llog sync vs llog cleanup ========================================================== 04:21:30 (1785399690) [ 6567.693635] Lustre: Failing over lustre-MDT0000 [ 6567.904187] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 6568.061671] Lustre: server umount lustre-MDT0000 complete [ 6588.383097] Lustre: 3298:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1785399701/real 1785399701] req@ffff9211c1bb6a00 x1872120453501568/t0(0) o400->MGC192.168.201.145@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1785399717 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6588.411982] Lustre: 3298:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 46 previous similar messages [ 6598.627942] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xe4f321ee34d0282b [ 6598.635542] Lustre: MGC192.168.201.145@tcp: Connection restored to 0@lo (at 0@lo) [ 6598.640206] Lustre: Skipped 8 previous similar messages [ 6604.277252] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6610.846934] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5234 to 0x280000400:5249) [ 6610.850229] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5266 to 0x240000400:5281) [ 6620.144831] Lustre: Failing over lustre-MDT0000 [ 6620.424851] Lustre: server umount lustre-MDT0000 complete [ 6649.312662] LustreError: 3296:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff92108ae55180 x1872120453516544/t0(0) o250->MGC192.168.201.145@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 [ 6655.221707] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6661.952984] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 6661.959559] Lustre: Skipped 5 previous similar messages [ 6662.044440] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 6662.056149] Lustre: Skipped 5 previous similar messages [ 6662.114453] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5266 to 0x240000400:5313) [ 6662.123762] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5234 to 0x280000400:5281) [ 6669.728475] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6671.569638] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6681.740223] Lustre: DEBUG MARKER: == replay-single test 61c: test race mds llog sync vs llog cleanup ========================================================== 04:23:28 (1785399808) [ 6696.867137] Lustre: Failing over lustre-OST0000 [ 6697.184475] Lustre: server umount lustre-OST0000 complete [ 6697.811316] LustreError: 7762:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.201.45@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 6697.835196] LustreError: 7762:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 1 previous similar message [ 6697.979399] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 6697.991771] 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 [ 6698.011703] Lustre: Skipped 10 previous similar messages [ 6725.087434] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6737.697872] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 6739.708817] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 6752.306047] Lustre: DEBUG MARKER: == replay-single test 61d: error in llog_setup should cleanup the llog context correctly ========================================================== 04:24:39 (1785399879) [ 6755.179499] Lustre: Failing over lustre-MDT0000 [ 6755.652749] Lustre: server umount lustre-MDT0000 complete [ 6766.731847] Lustre: *** cfs_fail_loc=605, val=0*** [ 6766.736956] LustreError: 136113:0:(llog_obd.c:192:llog_setup()) MGS: ctxt 0 lop_setup=ffffffffc11a9d40 failed: rc = -95 [ 6766.749672] LustreError: 136113:0:(obd_config.c:845:class_setup()) setup MGS failed (-95) [ 6766.759440] LustreError: 136113:0:(obd_mount.c:259:lustre_start_simple()) MGS setup error -95 [ 6766.773241] LustreError: 136113:0:(tgt_mount.c:116:server_deregister_mount()) MGS not registered [ 6766.807615] LustreError: Failed to start MGS 'MGS' (-95). Is the 'mgs' module loaded? [ 6766.809817] LustreError: 136113:0:(tgt_mount.c:2129:server_put_super()) no obd lustre-MDT0000 [ 6767.101388] Lustre: server umount lustre-MDT0000 complete [ 6767.106250] LustreError: 136113:0:(super25.c:178:lustre_fill_super()) llite: Unable to mount : rc = -95 [ 6773.933351] LustreError: MGC192.168.201.145@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 6773.938904] LustreError: Skipped 4 previous similar messages [ 6776.336757] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5283 to 0x280000400:5313) [ 6776.343943] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5315 to 0x240000400:5345) [ 6781.357707] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6792.409426] Lustre: DEBUG MARKER: == replay-single test 62: don't mis-drop resent replay === 04:25:18 (1785399918) [ 6796.268819] LustreError: 137114:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 6796.274247] LustreError: 137114:0:(osd_handler.c:720:osd_ro()) Skipped 3 previous similar messages [ 6797.500629] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 6801.834564] Lustre: Failing over lustre-MDT0000 [ 6802.380701] Lustre: server umount lustre-MDT0000 complete [ 6823.569489] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 6823.579966] Lustre: Skipped 7 previous similar messages [ 6823.746889] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 6823.749756] Lustre: Skipped 7 previous similar messages [ 6830.196698] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6830.938563] Lustre: *** cfs_fail_loc=707, val=0*** [ 6847.331763] Lustre: lustre-MDT0000: Client e3d8042e-f791-4a8b-9922-ea59ed21bdb2 (at 192.168.201.45@tcp) reconnected, waiting for 1 clients in recovery for 0:53 [ 6848.335903] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5359 to 0x240000400:5377) [ 6848.339781] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5326 to 0x280000400:5345) [ 6855.596263] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6858.517855] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6871.158705] Lustre: DEBUG MARKER: == replay-single test 65a: AT: verify early replies ====== 04:26:38 (1785399998) [ 6903.978863] LustreError: 137716:0:(service.c:2558:ptlrpc_server_handle_request()) @@@ HIT req@ffff9211bf5adf80 x1872120437496448/t0(0) o101->e3d8042e-f791-4a8b-9922-ea59ed21bdb2@192.168.201.45@tcp:203/0 lens 664/0 e 0 to 0 dl 1785400043 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 6904.009197] LustreError: 137716:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a sleeping for 11000ms [ 6915.049153] LustreError: 137716:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a awake [ 6915.097052] LustreError: 137718:0:(service.c:2558:ptlrpc_server_handle_request()) @@@ HIT req@ffff9211baf73800 x1872120437497472/t0(0) o35->e3d8042e-f791-4a8b-9922-ea59ed21bdb2@192.168.201.45@tcp:220/0 lens 392/0 e 0 to 0 dl 1785400060 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 6917.900419] LustreError: 137714:0:(service.c:2558:ptlrpc_server_handle_request()) @@@ HIT req@ffff9211b4b1ea00 x1872120437503360/t0(0) o101->e3d8042e-f791-4a8b-9922-ea59ed21bdb2@192.168.201.45@tcp:257/0 lens 576/0 e 0 to 0 dl 1785400097 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'unlinkmany.0' uid:0 gid:0 projid:0 [ 6917.930280] LustreError: 137714:0:(service.c:2558:ptlrpc_server_handle_request()) Skipped 27 previous similar messages [ 6920.295875] LustreError: 35726:0:(service.c:2558:ptlrpc_server_handle_request()) @@@ HIT req@ffff92108b33d880 x1872120453594624/t0(0) o6->lustre-MDT0000-mdtlov_UUID@0@lo:219/0 lens 544/0 e 0 to 0 dl 1785400059 ref 1 fl Interpret:/200/ffffffff rc 0/-1 job:'osp-syn-0-0.0' uid:0 gid:0 projid:4294967295 [ 6920.339244] LustreError: 35726:0:(service.c:2558:ptlrpc_server_handle_request()) Skipped 20 previous similar messages [ 6925.303723] LustreError: 35727:0:(service.c:2558:ptlrpc_server_handle_request()) @@@ HIT req@ffff92118a20d050 x1872120453596032/t0(0) o6->lustre-MDT0000-mdtlov_UUID@0@lo:224/0 lens 544/0 e 0 to 0 dl 1785400064 ref 1 fl Interpret:/200/ffffffff rc 0/-1 job:'osp-syn-0-0.0' uid:0 gid:0 projid:4294967295 [ 6925.368797] LustreError: 35727:0:(service.c:2558:ptlrpc_server_handle_request()) Skipped 7 previous similar messages [ 6938.263307] Lustre: DEBUG MARKER: == replay-single test 65b: AT: verify early replies on packed reply / bulk ========================================================== 04:27:44 (1785400064) [ 6972.848357] LustreError: 6606:0:(tgt_handler.c:2830:tgt_brw_write()) cfs_fail_timeout id 224 sleeping for 11000ms [ 6983.903514] LustreError: 6606:0:(tgt_handler.c:2830:tgt_brw_write()) cfs_fail_timeout id 224 awake [ 6998.895855] Lustre: DEBUG MARKER: == replay-single test 66a: AT: verify MDT service time adjusts with no early replies ========================================================== 04:28:45 (1785400125) [ 7030.045359] LustreError: 137714:0:(service.c:2558:ptlrpc_server_handle_request()) @@@ HIT req@ffff9211b63eea00 x1872120437522304/t0(0) o101->e3d8042e-f791-4a8b-9922-ea59ed21bdb2@192.168.201.45@tcp:329/0 lens 576/0 e 0 to 0 dl 1785400169 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 7030.079655] LustreError: 137714:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a sleeping for 5000ms [ 7035.087286] LustreError: 137714:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a awake [ 7038.745949] LustreError: 138987:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a sleeping for 10000ms [ 7048.759125] LustreError: 138987:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a awake [ 7048.775727] LustreError: 137715:0:(service.c:2558:ptlrpc_server_handle_request()) @@@ HIT req@ffff92108aeed180 x1872120437544832/t0(0) o101->e3d8042e-f791-4a8b-9922-ea59ed21bdb2@192.168.201.45@tcp:387/0 lens 664/0 e 0 to 0 dl 1785400227 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 7048.792370] LustreError: 137715:0:(service.c:2558:ptlrpc_server_handle_request()) Skipped 120 previous similar messages [ 7072.462402] Lustre: DEBUG MARKER: == replay-single test 66b: AT: verify net latency adjusts ========================================================== 04:29:59 (1785400199) [ 7174.347560] Lustre: DEBUG MARKER: == replay-single test 67a: AT: verify slow request processing doesn't induce reconnects ========================================================== 04:31:40 (1785400300) [ 7209.207930] LustreError: 140730:0:(service.c:2558:ptlrpc_server_handle_request()) @@@ HIT req@ffff9211bf7c9f80 x1872120437602944/t0(0) o101->e3d8042e-f791-4a8b-9922-ea59ed21bdb2@192.168.201.45@tcp:508/0 lens 576/0 e 0 to 0 dl 1785400348 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 7209.291031] LustreError: 140730:0:(service.c:2558:ptlrpc_server_handle_request()) Skipped 100 previous similar messages [ 7209.323773] LustreError: 140730:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a sleeping for 400ms [ 7209.767112] LustreError: 140730:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a awake [ 7225.936422] LustreError: 137715:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a awake [ 7225.951591] LustreError: 137715:0:(service.c:2559:ptlrpc_server_handle_request()) Skipped 36 previous similar messages [ 7241.545830] LustreError: 137716:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a sleeping for 400ms [ 7241.553043] LustreError: 137716:0:(service.c:2559:ptlrpc_server_handle_request()) Skipped 79 previous similar messages [ 7262.523368] Lustre: DEBUG MARKER: == replay-single test 67b: AT: verify instant slowdown doesn't induce reconnects ========================================================== 04:33:09 (1785400389) [ 7301.820954] Lustre: DEBUG MARKER: phase 2 [ 7313.550759] Lustre: DEBUG MARKER: == replay-single test 68: AT: verify slowing locks ======= 04:34:00 (1785400440) [ 7404.642204] Lustre: DEBUG MARKER: == replay-single test 70a: check multi client t-f ======== 04:35:30 (1785400530) [ 7407.084473] Lustre: DEBUG MARKER: SKIP: replay-single test_70a Need two or more clients, have 1 [ 7409.444978] Lustre: DEBUG MARKER: == replay-single test 70b: dbench 1mdts recovery; 1 clients ========================================================== 04:35:35 (1785400535) [ 7415.727394] Lustre: DEBUG MARKER: Started rundbench load pid=128385 ... [ 7420.901193] LustreError: 144538:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 7422.755898] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 7426.309580] Lustre: DEBUG MARKER: test_70b fail mds1 1 times [ 7429.068811] Lustre: Failing over lustre-MDT0000 [ 7429.245250] LustreError: 140730:0:(ldlm_lockd.c:1453:ldlm_handle_enqueue()) ### lock on destroyed export 000000009c4b70d6 ns: mdt-lustre-MDT0000_UUID lock: ffff921088db0800/0xe4f321ee34d097bb lrc: 3/0,0 mode: --/CW res: [0x20001a9e3:0xf02:0x0].0x0 bits 0x5/0x0 rrc: 2 type: IBT gid 0 flags: 0x50306400000000 nid: 192.168.201.45@tcp remote: 0x7e5e974ca4fe39cc expref: 4 pid: 140730 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 [ 7429.290936] LustreError: 5787:0:(client.c:1381:ptlrpc_import_delay_req()) @@@ IMP_CLOSED req@ffff9211afed0380 x1872120453734272/t0(0) o105->lustre-MDT0000@192.168.201.45@tcp:15/16 lens 336/224 e 0 to 0 dl 0 ref 1 fl Rpc:QU/0/ffffffff rc 0/-1 job:'' uid:4294967295 gid:4294967295 projid:4294967295 [ 7429.295524] LustreError: 144732:0:(ldlm_resource.c:1207:ldlm_resource_complain()) mdt-lustre-MDT0000_UUID: namespace resource [0x20001a9e3:0xf02:0x0].0x0 (ffff921182d8d700) refcount nonzero (2) after lock cleanup; forcing cleanup. [ 7429.311358] LustreError: 5787:0:(client.c:1381:ptlrpc_import_delay_req()) Skipped 2 previous similar messages [ 7430.623821] 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 [ 7430.627745] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 7430.661498] Lustre: Skipped 5 previous similar messages [ 7430.669455] Lustre: Skipped 1 previous similar message [ 7434.051801] Lustre: lustre-MDT0000: Not available for connect from 192.168.201.45@tcp (stopping) [ 7434.062374] Lustre: Skipped 1 previous similar message [ 7435.577415] Lustre: server umount lustre-MDT0000 complete [ 7452.129536] Lustre: 3298:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1785400564/real 1785400564] req@ffff9211c1bb7800 x1872120453735040/t0(0) o400->MGC192.168.201.145@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1785400580 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 7452.188206] Lustre: 3298:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 25 previous similar messages [ 7452.191555] LustreError: MGC192.168.201.145@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 7452.223894] LustreError: Skipped 1 previous similar message [ 7461.407980] LustreError: 3296:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9211bf8dbb80 x1872120453736192/t0(0) o250->MGC192.168.201.145@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 [ 7462.540845] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 7462.688077] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 7469.176455] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7470.565202] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 7470.579702] Lustre: Skipped 9 previous similar messages [ 7484.484145] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 7484.486644] Lustre: Skipped 3 previous similar messages [ 7485.481752] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 7485.487469] Lustre: Skipped 3 previous similar messages [ 7485.551033] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5479 to 0x240000400:5505) [ 7485.553121] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5425 to 0x280000400:5441) [ 7493.000382] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 7495.590401] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7504.738510] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 7508.016746] Lustre: DEBUG MARKER: test_70b fail mds1 2 times [ 7510.376240] Lustre: Failing over lustre-MDT0000 [ 7510.918760] Lustre: server umount lustre-MDT0000 complete [ 7548.613400] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7551.642063] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5526 to 0x240000400:5569) [ 7551.644411] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5463 to 0x280000400:5505) [ 7560.430542] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 7562.881685] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7574.535909] Lustre: DEBUG MARKER: == replay-single test 70c: tar 1mdts recovery ============ 04:38:20 (1785400700) [ 7702.037366] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 7716.590402] Lustre: DEBUG MARKER: test_70c fail mds1 1 times [ 7719.119564] Lustre: Failing over lustre-MDT0000 [ 7720.204425] Lustre: server umount lustre-MDT0000 complete [ 7748.586315] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xe4f321ee34d34720 [ 7755.341919] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7765.510483] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5941 to 0x280000400:5985) [ 7765.511120] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6005 to 0x240000400:6049) [ 7773.346734] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 7775.953477] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7896.115971] Lustre: DEBUG MARKER: == replay-single test 70d: mkdir/rmdir striped dir 1mdts recovery ========================================================== 04:43:42 (1785401022) [ 7900.008545] Lustre: DEBUG MARKER: SKIP: replay-single test_70d needs >= 2 MDTs [ 7904.167080] Lustre: DEBUG MARKER: == replay-single test 70e: rename cross-MDT with random fails ========================================================== 04:43:49 (1785401029) [ 7906.078714] Lustre: DEBUG MARKER: SKIP: replay-single test_70e needs >= 2 MDTs [ 7908.482739] Lustre: DEBUG MARKER: == replay-single test 70f: OSS O_DIRECT recovery with 1 clients ========================================================== 04:43:54 (1785401034) [ 7917.343160] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 7920.330093] Lustre: DEBUG MARKER: test_70f failing OST 1 times [ 7922.653625] Lustre: Failing over lustre-OST0000 [ 7922.706759] Lustre: server umount lustre-OST0000 complete [ 7924.719946] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 7924.744181] LustreError: 6600: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. [ 7924.763631] LustreError: 6600:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 8 previous similar messages [ 7942.636046] LustreError: 35734: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. [ 7942.671028] LustreError: 35734:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 6 previous similar messages [ 7954.417860] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7969.796291] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 7972.526857] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 7989.112725] Lustre: DEBUG MARKER: == replay-single test 71a: mkdir/rmdir striped dir with 2 mdts recovery ========================================================== 04:45:15 (1785401115) [ 7991.464258] Lustre: DEBUG MARKER: SKIP: replay-single test_71a needs >= 2 MDTs [ 7994.412575] Lustre: DEBUG MARKER: == replay-single test 73a: open(O_CREAT), unlink, replay, reconnect before open replay, close ========================================================== 04:45:20 (1785401120) [ 7999.730682] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 8003.226481] Lustre: Failing over lustre-MDT0000 [ 8003.626549] Lustre: server umount lustre-MDT0000 complete [ 8030.560348] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xe4f321ee34d6081a [ 8038.617268] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 8045.386556] Lustre: *** cfs_fail_loc=302, val=2147483648*** [ 8060.800778] Lustre: lustre-MDT0000: Client e3d8042e-f791-4a8b-9922-ea59ed21bdb2 (at 192.168.201.45@tcp) reconnected, waiting for 1 clients in recovery for 0:54 [ 8060.979607] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6177 to 0x280000400:6209) [ 8060.980518] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6243 to 0x240000400:6273) [ 8069.717654] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 8072.356962] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8083.363442] Lustre: DEBUG MARKER: == replay-single test 73b: open(O_CREAT), unlink, replay, reconnect at open_replay reply, close ========================================================== 04:46:50 (1785401210) [ 8087.279701] LustreError: 152961:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 8087.291197] LustreError: 152961:0:(osd_handler.c:720:osd_ro()) Skipped 4 previous similar messages [ 8088.532899] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 8092.267144] Lustre: Failing over lustre-MDT0000 [ 8093.039768] Lustre: server umount lustre-MDT0000 complete [ 8112.805179] LustreError: MGC192.168.201.145@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 8112.813706] LustreError: Skipped 3 previous similar messages [ 8113.039841] Lustre: lustre-MDT0000: Not available for connect from 192.168.201.45@tcp (not set up) [ 8113.119073] Lustre: 3297:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1785401225/real 1785401225] req@ffff921186a91f80 x1872120454439552/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1785401241 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 8113.124815] 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 [ 8113.156610] Lustre: 3297:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 29 previous similar messages [ 8113.184651] Lustre: Skipped 8 previous similar messages [ 8113.407127] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 8113.416955] Lustre: Skipped 4 previous similar messages [ 8113.511403] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 8113.530960] Lustre: Skipped 4 previous similar messages [ 8114.835017] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 8114.837677] Lustre: Skipped 4 previous similar messages [ 8114.894746] Lustre: *** cfs_fail_loc=157, val=2147483648*** [ 8114.902719] LustreError: 153559:0:(ldlm_lib.c:3345:target_send_reply_msg()) @@@ dropping reply req@ffff9211b4f70700 x1872120443136384/t335007449091(335007449091) o101->e3d8042e-f791-4a8b-9922-ea59ed21bdb2@192.168.201.45@tcp:659/0 lens 592/608 e 0 to 0 dl 1785401254 ref 1 fl Interpret:/604/0 rc 301/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 8118.759709] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 8118.777360] Lustre: Skipped 10 previous similar messages [ 8119.411695] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 8131.422502] Lustre: lustre-MDT0000: Client e3d8042e-f791-4a8b-9922-ea59ed21bdb2 (at 192.168.201.45@tcp) reconnected, waiting for 1 clients in recovery for 0:53 [ 8131.452054] Lustre: 153559:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff921184566d80 x1872120443136384/t335007449091(335007449091) o101->e3d8042e-f791-4a8b-9922-ea59ed21bdb2@192.168.201.45@tcp:676/0 lens 592/3488 e 0 to 0 dl 1785401271 ref 1 fl Interpret:/606/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 8131.716265] Lustre: lustre-MDT0000: Recovery over after 0:17, of 1 clients 1 recovered and 0 were evicted. [ 8131.738322] Lustre: Skipped 4 previous similar messages [ 8131.873765] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6211 to 0x280000400:6241) [ 8131.874302] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6243 to 0x240000400:6305) [ 8140.780462] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 8142.642201] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8151.648142] Lustre: DEBUG MARKER: == replay-single test 74: Ensure applications don't fail waiting for OST recovery ========================================================== 04:47:58 (1785401278) [ 8156.519083] Lustre: Failing over lustre-OST0000 [ 8156.678471] Lustre: server umount lustre-OST0000 complete [ 8157.666492] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 8157.682492] LustreError: 35734: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. [ 8157.714205] LustreError: 35734:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 1 previous similar message [ 8160.783501] Lustre: Failing over lustre-MDT0000 [ 8161.201405] Lustre: server umount lustre-MDT0000 complete [ 8181.209676] Lustre: lustre-MDT0000: Not available for connect from 0@lo (not set up) [ 8181.776156] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6211 to 0x280000400:6273) [ 8188.613496] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 8200.913243] Lustre: lustre-OST0000: Denying connection for new client 9d933f78-564d-474e-a0ef-173cd567b0aa (at 192.168.201.45@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:59 [ 8200.931056] Lustre: Skipped 11 previous similar messages [ 8204.927086] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6243 to 0x240000400:6337) [ 8209.922784] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 8226.439385] Lustre: DEBUG MARKER: == replay-single test 80a: DNE: create remote dir, drop update rep from MDT0, fail MDT0 ========================================================== 04:49:11 (1785401351) [ 8229.394423] Lustre: DEBUG MARKER: SKIP: replay-single test_80a needs >= 2 MDTs [ 8232.627383] Lustre: DEBUG MARKER: == replay-single test 80b: DNE: create remote dir, drop update rep from MDT0, fail MDT1 ========================================================== 04:49:18 (1785401358) [ 8234.713094] Lustre: DEBUG MARKER: SKIP: replay-single test_80b needs >= 2 MDTs [ 8237.297568] Lustre: DEBUG MARKER: == replay-single test 80c: DNE: create remote dir, drop update rep from MDT1, fail MDT[0,1] ========================================================== 04:49:23 (1785401363) [ 8240.470674] Lustre: DEBUG MARKER: SKIP: replay-single test_80c needs >= 2 MDTs [ 8244.073981] Lustre: DEBUG MARKER: == replay-single test 80d: DNE: create remote dir, drop update rep from MDT1, fail 2 MDTs ========================================================== 04:49:29 (1785401369) [ 8247.003616] Lustre: DEBUG MARKER: SKIP: replay-single test_80d needs >= 2 MDTs [ 8248.676469] Lustre: DEBUG MARKER: == replay-single test 80e: DNE: create remote dir, drop MDT1 rep, fail MDT0 ========================================================== 04:49:35 (1785401375) [ 8250.219905] Lustre: DEBUG MARKER: SKIP: replay-single test_80e needs >= 2 MDTs [ 8251.560959] Lustre: DEBUG MARKER: == replay-single test 80f: DNE: create remote dir, drop MDT1 rep, fail MDT1 ========================================================== 04:49:38 (1785401378) [ 8253.370827] Lustre: DEBUG MARKER: SKIP: replay-single test_80f needs >= 2 MDTs [ 8256.136587] Lustre: DEBUG MARKER: == replay-single test 80g: DNE: create remote dir, drop MDT1 rep, fail MDT0, then MDT1 ========================================================== 04:49:42 (1785401382) [ 8258.513840] Lustre: DEBUG MARKER: SKIP: replay-single test_80g needs >= 2 MDTs [ 8261.207196] Lustre: DEBUG MARKER: == replay-single test 80h: DNE: create remote dir, drop MDT1 rep, fail 2 MDTs ========================================================== 04:49:47 (1785401387) [ 8263.601911] Lustre: DEBUG MARKER: SKIP: replay-single test_80h needs >= 2 MDTs [ 8266.322950] Lustre: DEBUG MARKER: == replay-single test 81a: DNE: unlink remote dir, drop MDT0 update rep, fail MDT1 ========================================================== 04:49:52 (1785401392) [ 8268.858879] Lustre: DEBUG MARKER: SKIP: replay-single test_81a needs >= 2 MDTs [ 8271.572928] Lustre: DEBUG MARKER: == replay-single test 81b: DNE: unlink remote dir, drop MDT0 update reply, fail MDT0 ========================================================== 04:49:57 (1785401397) [ 8274.098028] Lustre: DEBUG MARKER: SKIP: replay-single test_81b needs >= 2 MDTs [ 8276.242290] Lustre: DEBUG MARKER: == replay-single test 81c: DNE: unlink remote dir, drop MDT0 update reply, fail MDT0,MDT1 ========================================================== 04:50:02 (1785401402) [ 8277.874524] Lustre: DEBUG MARKER: SKIP: replay-single test_81c needs >= 2 MDTs [ 8279.778535] Lustre: DEBUG MARKER: == replay-single test 81d: DNE: unlink remote dir, drop MDT0 update reply, fail 2 MDTs ========================================================== 04:50:06 (1785401406) [ 8281.775413] Lustre: DEBUG MARKER: SKIP: replay-single test_81d needs >= 2 MDTs [ 8283.780757] Lustre: DEBUG MARKER: == replay-single test 81e: DNE: unlink remote dir, drop MDT1 req reply, fail MDT0 ========================================================== 04:50:10 (1785401410) [ 8285.285497] Lustre: DEBUG MARKER: SKIP: replay-single test_81e needs >= 2 MDTs [ 8287.419106] Lustre: DEBUG MARKER: == replay-single test 81f: DNE: unlink remote dir, drop MDT1 req reply, fail MDT1 ========================================================== 04:50:13 (1785401413) [ 8289.217539] Lustre: DEBUG MARKER: SKIP: replay-single test_81f needs >= 2 MDTs [ 8291.556482] Lustre: DEBUG MARKER: == replay-single test 81g: DNE: unlink remote dir, drop req reply, fail M0, then M1 ========================================================== 04:50:18 (1785401418) [ 8293.792631] Lustre: DEBUG MARKER: SKIP: replay-single test_81g needs >= 2 MDTs [ 8296.784275] Lustre: DEBUG MARKER: == replay-single test 81h: DNE: unlink remote dir, drop request reply, fail 2 MDTs ========================================================== 04:50:22 (1785401422) [ 8299.393333] Lustre: DEBUG MARKER: SKIP: replay-single test_81h needs >= 2 MDTs [ 8301.816726] Lustre: DEBUG MARKER: == replay-single test 84a: stale open during export disconnect ========================================================== 04:50:28 (1785401428) [ 8304.596499] Lustre: 158116:0:(genops.c:1795:obd_export_evict_by_uuid()) lustre-MDT0000: evicting 9d933f78-564d-474e-a0ef-173cd567b0aa at adminstrative request [ 8317.641222] Lustre: DEBUG MARKER: == replay-single test 85a: check the cancellation of unused locks during recovery(IBITS) ========================================================== 04:50:43 (1785401443) [ 8333.022025] Lustre: Failing over lustre-MDT0000 [ 8333.547427] Lustre: server umount lustre-MDT0000 complete [ 8374.017437] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 8380.330586] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6389 to 0x240000400:6433) [ 8380.347703] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6325 to 0x280000400:6369) [ 8392.470929] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 8395.105730] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8406.669832] Lustre: DEBUG MARKER: == replay-single test 85b: check the cancellation of unused locks during recovery(EXTENT) ========================================================== 04:52:13 (1785401533) [ 8443.543533] Lustre: Failing over lustre-OST0000 [ 8444.050014] Lustre: server umount lustre-OST0000 complete [ 8444.854788] LustreError: 35728:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.201.45@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 8444.884789] LustreError: 35728:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 7 previous similar messages [ 8480.528832] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 8494.702388] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 8497.165467] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 8510.866232] Lustre: DEBUG MARKER: == replay-single test 86: umount server after clear nid_stats should not hit LBUG ========================================================== 04:53:56 (1785401636) [ 8518.904733] Lustre: Failing over lustre-MDT0000 [ 8521.432879] Lustre: server umount lustre-MDT0000 complete [ 8531.347157] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6534 to 0x240000400:6561) [ 8531.355849] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6325 to 0x280000400:6401) [ 8537.923585] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 8551.702725] Lustre: DEBUG MARKER: == replay-single test 87a: write replay ================== 04:54:37 (1785401677) [ 8559.754614] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 8564.395677] Lustre: Failing over lustre-OST0000 [ 8564.583459] Lustre: server umount lustre-OST0000 complete [ 8566.756735] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 8576.831700] LustreError: 35730:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.201.45@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 8576.873714] LustreError: 35730:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 15 previous similar messages [ 8593.197136] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 8609.220262] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 8611.618148] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 8625.635355] Lustre: DEBUG MARKER: == replay-single test 87b: write replay with changed data (checksum resend) ========================================================== 04:55:51 (1785401751) [ 8632.693630] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 8637.438602] Lustre: Failing over lustre-OST0000 [ 8637.476396] Lustre: server umount lustre-OST0000 complete [ 8638.453577] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 8662.050494] LustreError: lustre-OST0000: BAD WRITE CHECKSUM: from 12345-192.168.201.45@tcp inode [0x2000284a1:0x5:0x0] object 0x240000400:6563 extent [0-1048575]: client csum 66b36ae9, server csum 2f0a2114 [ 8670.304263] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 8687.801019] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 8691.066243] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 8700.926359] Lustre: DEBUG MARKER: == replay-single test 88: MDS should not assign same objid to different files ========================================================== 04:57:07 (1785401827) [ 8705.104914] LustreError: 165704:0:(osd_handler.c:720:osd_ro()) lustre-OST0000: *** setting device osd-zfs read-only *** [ 8705.107874] LustreError: 165704:0:(osd_handler.c:720:osd_ro()) Skipped 2 previous similar messages [ 8706.372928] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 8711.539879] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 8719.697222] Lustre: Failing over lustre-MDT0000 [ 8720.131300] Lustre: server umount lustre-MDT0000 complete [ 8724.602793] LustreError: 8323:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1785401853 with bad export cookie 16497567166960660027 [ 8724.623044] LustreError: MGC192.168.201.145@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 8724.635450] LustreError: Skipped 3 previous similar messages [ 8735.201216] Lustre: Failing over lustre-OST0000 [ 8735.293698] Lustre: server umount lustre-OST0000 complete [ 8737.695235] Lustre: 3298:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1785401850/real 1785401850] req@ffff9211c1405c00 x1872120454608640/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1785401866 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 8737.741734] Lustre: 3298:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 20 previous similar messages [ 8737.765929] 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 [ 8737.812924] Lustre: Skipped 9 previous similar messages [ 8770.419589] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 8770.424601] Lustre: Skipped 7 previous similar messages [ 8770.576831] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 8770.590841] Lustre: Skipped 5 previous similar messages [ 8777.400328] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 8782.147259] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 8782.162952] Lustre: Skipped 5 previous similar messages [ 8782.837551] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 8782.853131] Lustre: Skipped 10 previous similar messages [ 8783.702423] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 8783.706109] Lustre: Skipped 5 previous similar messages [ 8783.773510] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6440 to 0x280000400:6465) [ 8804.490088] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6564 to 0x240000400:6593) [ 8807.842775] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 8829.598741] Lustre: DEBUG MARKER: == replay-single test 89: no disk space leak on late ost connection ========================================================== 04:59:15 (1785401955) [ 8856.033373] Lustre: Failing over lustre-OST0000 [ 8856.036965] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -19 [ 8856.048708] Lustre: lustre-OST0000: Not available for connect from 0@lo (stopping) [ 8856.194709] Lustre: server umount lustre-OST0000 complete [ 8857.946275] LustreError: 6599:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.201.45@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 8857.972481] LustreError: 6599:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 34 previous similar messages [ 8862.208839] Lustre: Failing over lustre-MDT0000 [ 8862.810504] Lustre: server umount lustre-MDT0000 complete [ 8898.021416] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 8904.301099] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6440 to 0x280000400:6497) [ 8920.906462] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 8923.670342] Lustre: lustre-OST0000: Denying connection for new client a0138075-2a54-458f-93d3-09ac6120f001 (at 192.168.201.45@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 1:01 [ 8923.690707] Lustre: Skipped 1 previous similar message [ 8929.088024] Lustre: lustre-OST0000: Denying connection for new client a0138075-2a54-458f-93d3-09ac6120f001 (at 192.168.201.45@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 0:56 [ 8934.227858] Lustre: lustre-OST0000: Denying connection for new client a0138075-2a54-458f-93d3-09ac6120f001 (at 192.168.201.45@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 0:51 [ 8939.341112] Lustre: lustre-OST0000: Denying connection for new client a0138075-2a54-458f-93d3-09ac6120f001 (at 192.168.201.45@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 0:46 [ 8949.586379] Lustre: lustre-OST0000: Denying connection for new client a0138075-2a54-458f-93d3-09ac6120f001 (at 192.168.201.45@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 0:35 [ 8949.610180] Lustre: Skipped 1 previous similar message [ 8970.050252] Lustre: lustre-OST0000: Denying connection for new client a0138075-2a54-458f-93d3-09ac6120f001 (at 192.168.201.45@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 0:15 [ 8970.081582] Lustre: Skipped 3 previous similar messages [ 8985.500332] Lustre: lustre-OST0000: recovery is timed out, evict stale exports [ 8985.511566] Lustre: 170083:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-OST0000: disconnect stale client 9ddd5492-07c8-4df5-b5cc-8ccb75b508b3@ [ 8985.530685] Lustre: lustre-OST0000: disconnecting 1 stale clients [ 8985.656646] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6604 to 0x240000400:6625) [ 8994.525176] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 58 sec [ 9010.470217] Lustre: DEBUG MARKER: free_before: 7520256 free_after: 7520256 [ 9017.485502] Lustre: DEBUG MARKER: == replay-single test 90: lfs find identifies the missing striped file segments ========================================================== 05:02:24 (1785402144) [ 9022.746587] Lustre: Failing over lustre-OST0001 [ 9022.940614] Lustre: server umount lustre-OST0001 complete [ 9053.860615] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 9070.221733] Lustre: DEBUG MARKER: == replay-single test 93a: replay + reconnect ============ 05:03:15 (1785402195) [ 9075.949365] Lustre: Failing over lustre-OST0000 [ 9076.083393] Lustre: lustre-OST0000: Not available for connect from 192.168.201.45@tcp (stopping) [ 9076.178993] Lustre: server umount lustre-OST0000 complete [ 9098.076082] LustreError: 173068:0:(ldlm_lib.c:2904:target_recovery_thread()) cfs_fail_timeout id 715 sleeping for 40000ms [ 9098.079133] LustreError: 173068:0:(ldlm_lib.c:2904:target_recovery_thread()) Skipped 36 previous similar messages [ 9104.351156] Lustre: *** cfs_fail_loc=715, val=40*** [ 9107.145165] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 9113.569227] Lustre: lustre-OST0000: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnected, waiting for 2 clients in recovery for 1:24 [ 9114.429878] Lustre: lustre-OST0000: Client a0138075-2a54-458f-93d3-09ac6120f001 (at 192.168.201.45@tcp) reconnected, waiting for 2 clients in recovery for 1:24 [ 9119.711383] Lustre: *** cfs_fail_loc=715, val=40*** [ 9119.720813] Lustre: Skipped 1 previous similar message [ 9120.738055] Lustre: *** cfs_fail_loc=715, val=40*** [ 9129.791361] Lustre: lustre-OST0000: Client a0138075-2a54-458f-93d3-09ac6120f001 (at 192.168.201.45@tcp) reconnected, waiting for 2 clients in recovery for 1:08 [ 9136.095172] Lustre: *** cfs_fail_loc=715, val=40*** [ 9138.079130] LustreError: 173068:0:(ldlm_lib.c:2904:target_recovery_thread()) cfs_fail_timeout id 715 awake [ 9138.103907] LustreError: 173068:0:(ldlm_lib.c:2904:target_recovery_thread()) Skipped 79 previous similar messages [ 9147.749548] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 9150.046589] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 9162.191100] Lustre: DEBUG MARKER: == replay-single test 93b: replay + reconnect on mds ===== 05:04:48 (1785402288) [ 9167.078180] Lustre: Failing over lustre-MDT0000 [ 9167.362299] Lustre: server umount lustre-MDT0000 complete [ 9197.023983] LustreError: 3296:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9211afc8ad80 x1872120454709248/t0(0) o250->MGC192.168.201.145@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 [ 9197.375894] Lustre: lustre-MDT0000: Not available for connect from 192.168.201.45@tcp (not set up) [ 9198.591571] LustreError: 174620:0:(ldlm_lib.c:2904:target_recovery_thread()) cfs_fail_timeout id 715 sleeping for 80000ms [ 9204.705239] Lustre: *** cfs_fail_loc=715, val=80*** [ 9204.707091] Lustre: Skipped 1 previous similar message [ 9204.819516] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 9214.783554] Lustre: lustre-MDT0000: Client a0138075-2a54-458f-93d3-09ac6120f001 (at 192.168.201.45@tcp) reconnected, waiting for 1 clients in recovery for 0:53 [ 9214.794527] Lustre: Skipped 1 previous similar message [ 9221.087472] Lustre: *** cfs_fail_loc=715, val=80*** [ 9231.174156] Lustre: lustre-MDT0000: Client a0138075-2a54-458f-93d3-09ac6120f001 (at 192.168.201.45@tcp) reconnected, waiting for 1 clients in recovery for 0:37 [ 9237.473453] Lustre: *** cfs_fail_loc=715, val=80*** [ 9247.551066] Lustre: lustre-MDT0000: Client a0138075-2a54-458f-93d3-09ac6120f001 (at 192.168.201.45@tcp) reconnected, waiting for 1 clients in recovery for 0:20 [ 9263.936788] Lustre: lustre-MDT0000: Client a0138075-2a54-458f-93d3-09ac6120f001 (at 192.168.201.45@tcp) reconnected, waiting for 1 clients in recovery for 0:04 [ 9270.239259] Lustre: *** cfs_fail_loc=715, val=80*** [ 9270.248164] Lustre: Skipped 1 previous similar message [ 9278.592483] LustreError: 174620:0:(ldlm_lib.c:2904:target_recovery_thread()) cfs_fail_timeout id 715 awake [ 9278.773418] Lustre: 174620:0:(ldlm_lib.c:2950:target_recovery_thread()) too long recovery - read logs [ 9278.800569] LustreError: dumping log to /tmp/lustre-log.1785402407.174620 [ 9278.931442] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6510 to 0x280000400:6529) [ 9278.934701] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6639 to 0x240000400:6657) [ 9288.041233] Lustre: DEBUG MARKER: oleg145-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 9290.296465] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 9301.088110] Lustre: DEBUG MARKER: == replay-single test complete, duration 9036 sec ======== 05:07:07 (1785402427) [ 9302.942425] Lustre: DEBUG MARKER: === replay-single: start cleanup 05:07:09 (1785402429) === [ 9315.300612] Lustre: DEBUG MARKER: === replay-single: finish cleanup 05:07:21 (1785402441) === [ 9346.171951] Lustre: server umount lustre-MDT0000 complete [ 9353.139764] LustreError: 82865:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1785402481 with bad export cookie 16497567166960672375 [ 9353.173965] LustreError: MGC192.168.201.145@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 9353.191378] LustreError: Skipped 2 previous similar messages [ 9362.562377] Lustre: server umount lustre-OST0000 complete [ 9366.312320] Lustre: 3299:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1785402478/real 1785402478] req@ffff921184571f80 x1872120454791552/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1785402494 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 9366.345621] Lustre: 3299:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 21 previous similar messages [ 9366.359025] 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 [ 9366.378437] Lustre: Skipped 6 previous similar messages [ 9368.758327] Lustre: server umount lustre-OST0001 complete [ 9386.030575] Lustre: DEBUG MARKER: oleg145-server.virtnet: executing unload_modules_local [ 9390.443196] Key type lgssc unregistered [ 9390.928595] LNet: 176758:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 9390.942461] LNetError: 176758:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 9390.954732] LNet: Removed LNI 192.168.201.145@tcp [ 9392.062138] Key type .llcrypt unregistered [ 9392.064061] Key type ._llcrypt unregistered