[ 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 504201327 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: 2895240K/4306352K available (18435K kernel code, 11221K rwdata, 7248K rodata, 2908K init, 18040K bss, 524580K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] ftrace: allocating 41240 entries in 162 pages [ 0.000000] ftrace: allocated 162 pages with 3 groups [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] rcu: RCU event tracing is enabled. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ 0.000000] rcu: RCU callback double-/use-after-free debug enabled. [ 0.000000] Rude variant of Tasks RCU enabled. [ 0.000000] Tracing variant of Tasks RCU enabled. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 0.000000] NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16 [ 0.000000] random: get_random_bytes called from start_kernel+0x622/0x9a8 with crng_init=0 [ 0.001000] Console: colour *CGA 80x25 [ 0.001000] printk: console [ttyS1] enabled [ 0.001000] ACPI: Core revision 20220331 [ 0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.001011] APIC: Switch to symmetric I/O mode setup [ 0.003221] x2apic enabled [ 0.004008] Switched APIC routing to physical x2apic. [ 0.005011] kvm-guest: setup PV IPIs [ 0.009939] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.010000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.010022] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.011014] pid_max: default: 32768 minimum: 301 [ 0.012152] LSM: Security Framework initializing [ 0.013061] Yama: becoming mindful. [ 0.014044] SELinux: Initializing. [ 0.015069] *** VALIDATE selinux *** [ 0.022787] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.027257] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.028151] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.029104] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.031091] *** VALIDATE tmpfs *** [ 0.032440] *** VALIDATE proc *** [ 0.034181] *** VALIDATE cgroup *** [ 0.035009] *** VALIDATE cgroup2 *** [ 0.036278] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.037181] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.038008] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.039031] Spectre V2 : User space: Vulnerable [ 0.040006] Speculative Store Bypass: Vulnerable [ 0.043381] debug: unmapping init [mem 0xffffffffb7459000-0xffffffffb7460fff] [ 0.046255] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.047775] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.048023] ... version: 2 [ 0.049013] ... bit width: 48 [ 0.050010] ... generic registers: 4 [ 0.051013] ... value mask: 0000ffffffffffff [ 0.052014] ... max period: 00007fffffffffff [ 0.053014] ... fixed-purpose events: 3 [ 0.054013] ... event mask: 000000070000000f [ 0.055338] rcu: Hierarchical SRCU implementation. [ 0.057610] smp: Bringing up secondary CPUs ... [ 0.058425] x86: Booting SMP configuration: [ 0.059023] .... node #0, CPUs: #1 #2 #3 [ 0.062013] smp: Brought up 1 node, 4 CPUs [ 0.064008] smpboot: Max logical packages: 1 [ 0.065017] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.120048] node 0 deferred pages initialised in 53ms [ 0.124010] devtmpfs: initialized [ 0.125251] x86/mm: Memory block size: 128MB [ 0.128046] gcov: version magic: 0x41383552 [ 0.130359] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.131076] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.132297] pinctrl core: initialized pinctrl subsystem [ 0.133197] [ 0.133744] ************************************************************* [ 0.134013] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.135013] ** ** [ 0.136012] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.137018] ** ** [ 0.138014] ** This means that this kernel is built to expose internal ** [ 0.139012] ** IOMMU data structures, which may compromise security on ** [ 0.140015] ** your system. ** [ 0.141015] ** ** [ 0.142012] ** If you see this message and you are not debugging the ** [ 0.143021] ** kernel, report this immediately to your vendor! ** [ 0.144013] ** ** [ 0.145014] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.146011] ************************************************************* [ 0.147780] NET: Registered protocol family 16 [ 0.148695] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.149058] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.150063] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.151484] cpuidle: using governor menu [ 0.153960] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.156538] PCI: Using configuration type 1 for base access [ 0.159131] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.169391] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.170023] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.174136] cryptd: max_cpu_qlen set to 1000 [ 0.175548] ACPI: Added _OSI(Module Device) [ 0.176000] ACPI: Added _OSI(Processor Device) [ 0.178016] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.180014] ACPI: Added _OSI(Processor Aggregator Device) [ 0.185720] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.193084] ACPI: Interpreter enabled [ 0.194058] ACPI: PM: (supports S0 S3 S4 S5) [ 0.195012] ACPI: Using IOAPIC for interrupt routing [ 0.196087] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.197498] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.208359] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.209039] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.210020] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.211087] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.213566] acpiphp: Slot [2] registered [ 0.214115] acpiphp: Slot [5] registered [ 0.215165] acpiphp: Slot [6] registered [ 0.216116] acpiphp: Slot [7] registered [ 0.217156] acpiphp: Slot [8] registered [ 0.218096] acpiphp: Slot [9] registered [ 0.219121] acpiphp: Slot [10] registered [ 0.220156] acpiphp: Slot [3] registered [ 0.221125] acpiphp: Slot [4] registered [ 0.222107] acpiphp: Slot [11] registered [ 0.223172] acpiphp: Slot [12] registered [ 0.224138] acpiphp: Slot [13] registered [ 0.226116] acpiphp: Slot [14] registered [ 0.228105] acpiphp: Slot [15] registered [ 0.230114] acpiphp: Slot [16] registered [ 0.232112] acpiphp: Slot [17] registered [ 0.233285] acpiphp: Slot [18] registered [ 0.235106] acpiphp: Slot [19] registered [ 0.237133] acpiphp: Slot [20] registered [ 0.239103] acpiphp: Slot [21] registered [ 0.241105] acpiphp: Slot [22] registered [ 0.242088] acpiphp: Slot [23] registered [ 0.244108] acpiphp: Slot [24] registered [ 0.246123] acpiphp: Slot [25] registered [ 0.247225] acpiphp: Slot [26] registered [ 0.248082] acpiphp: Slot [27] registered [ 0.250077] acpiphp: Slot [28] registered [ 0.251205] acpiphp: Slot [29] registered [ 0.253098] acpiphp: Slot [30] registered [ 0.255093] acpiphp: Slot [31] registered [ 0.256088] PCI host bridge to bus 0000:00 [ 0.258073] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.260070] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.263018] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.266023] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.269025] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.271022] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.273176] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.277232] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.280502] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.292964] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.298138] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.300017] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.303018] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.306017] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.307552] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.311081] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.313175] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.318007] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.323017] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.336018] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.342014] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.347645] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.359018] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.370014] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.404027] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.413100] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.426022] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.437017] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.460019] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.478000] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.483013] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.488013] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.500016] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.508026] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.512014] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.516013] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.526016] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.540295] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.551050] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.559018] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.581017] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 0.590572] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.601017] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.607016] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.626015] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 0.635000] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.638564] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.641367] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.644380] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.646308] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.652082] iommu: Default domain type: Passthrough [ 0.654115] SCSI subsystem initialized [ 0.655165] ACPI: bus type USB registered [ 0.657133] usbcore: registered new interface driver usbfs [ 0.659086] usbcore: registered new interface driver hub [ 0.661142] usbcore: registered new device driver usb [ 0.663252] pps_core: LinuxPPS API ver. 1 registered [ 0.665012] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.668114] PTP clock support registered [ 0.671171] EDAC MC: Ver: 3.0.0 [ 0.673186] PCI: Using ACPI for IRQ routing [ 0.674733] NetLabel: Initializing [ 0.676015] NetLabel: domain hash size = 128 [ 0.678011] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.680085] NetLabel: unlabeled traffic allowed by default [ 0.683148] vgaarb: loaded [ 0.685342] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.687015] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.694607] clocksource: Switched to clocksource kvm-clock [ 0.809038] VFS: Disk quotas dquot_6.6.0 [ 0.810573] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.813018] *** VALIDATE ramfs *** [ 0.814280] *** VALIDATE hugetlbfs *** [ 0.815941] pnp: PnP ACPI init [ 0.819122] pnp: PnP ACPI: found 6 devices [ 0.835507] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.838723] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.840812] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.843056] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.845519] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.847855] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.850858] NET: Registered protocol family 2 [ 0.853283] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.858666] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.862497] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.867668] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.870933] TCP: Hash tables configured (established 65536 bind 65536) [ 0.873833] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.876858] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.879844] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.882981] NET: Registered protocol family 1 [ 0.885778] RPC: Registered named UNIX socket transport module. [ 0.888163] RPC: Registered udp transport module. [ 0.889944] RPC: Registered tcp transport module. [ 0.891739] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.894226] NET: Registered protocol family 44 [ 0.895883] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.898204] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.900517] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.902975] PCI: CLS 0 bytes, default 64 [ 0.905511] Unpacking initramfs... [ 2.431738] debug: unmapping init [mem 0xffff8c403cc54000-0xffff8c403ffbffff] [ 2.435583] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.437754] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.440452] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 2.949236] Initialise system trusted keyrings [ 2.950844] Key type blacklist registered [ 2.953185] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.968819] zbud: loaded [ 2.973966] *** VALIDATE nfs *** [ 2.975409] *** VALIDATE nfs4 *** [ 2.977233] pstore: using deflate compression [ 2.981453] Platform Keyring initialized [ 3.079136] NET: Registered protocol family 38 [ 3.080348] Key type asymmetric registered [ 3.081156] Asymmetric key parser 'x509' registered [ 3.082793] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 3.084977] io scheduler mq-deadline registered [ 3.085955] io scheduler kyber registered [ 3.087119] io scheduler bfq registered [ 3.088788] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 3.091240] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 3.093293] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 3.094949] ACPI: Power Button [PWRF] [ 3.099055] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 3.103419] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 3.111527] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 3.115777] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 3.125287] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 3.150612] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.177701] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.182557] Non-volatile memory driver v1.3 [ 3.184309] Linux agpgart interface v0.103 [ 3.213482] virtio_blk virtio1: [vda] 146008 512-byte logical blocks (74.8 MB/71.3 MiB) [ 3.216021] vda: detected capacity change from 0 to 74756096 [ 3.229944] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.232441] vdb: detected capacity change from 0 to 1073741824 [ 3.247607] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.250015] vdc: detected capacity change from 0 to 2621440000 [ 3.263636] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.266798] vdd: detected capacity change from 0 to 2621440000 [ 3.282305] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.284857] vde: detected capacity change from 0 to 4294967296 [ 3.303580] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.306563] vdf: detected capacity change from 0 to 4294967296 [ 3.319916] libphy: Fixed MDIO Bus: probed [ 3.328906] usbcore: registered new interface driver usbserial_generic [ 3.331068] usbserial: USB Serial support registered for generic [ 3.333251] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.337763] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.339199] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.341695] mousedev: PS/2 mouse device common for all mice [ 3.343889] rtc_cmos 00:05: RTC can wake from S4 [ 3.346274] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.350570] rtc_cmos 00:05: registered as rtc0 [ 3.351256] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.351989] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.357638] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.359029] intel_pstate: CPU model not supported [ 3.364300] hid: raw HID events driver (C) Jiri Kosina [ 3.365851] usbcore: registered new interface driver usbhid [ 3.367255] usbhid: USB HID core driver [ 3.368532] drop_monitor: Initializing network drop monitor service [ 3.370171] Initializing XFRM netlink socket [ 3.371677] NET: Registered protocol family 10 [ 3.374667] Segment Routing with IPv6 [ 3.376139] NET: Registered protocol family 17 [ 3.377650] mpls_gso: MPLS GSO support [ 3.384426] RAS: Correctable Errors collector initialized. [ 3.386651] AVX version of gcm_enc/dec engaged. [ 3.388273] AES CTR mode by8 optimization enabled [ 3.470992] sched_clock: Marking stable (3470967137, 0)->(4473467875, -1002500738) [ 3.474841] registered taskstats version 1 [ 3.477245] Loading compiled-in X.509 certificates [ 3.479163] zswap: loaded using pool lzo/zbud [ 3.504287] Key type big_key registered [ 3.515184] Key type encrypted registered [ 3.516809] ima: No TPM chip found, activating TPM-bypass! [ 3.518275] ima: Allocated hash algorithm: sha1 [ 3.519704] ima: No architecture policies found [ 3.521156] evm: Initialising EVM extended attributes: [ 3.523868] evm: security.selinux [ 3.525403] evm: security.ima [ 3.526599] evm: security.capability [ 3.527949] evm: HMAC attrs: 0x1 [ 3.529854] rtc_cmos 00:05: setting system clock to 2026-08-19 04:50:50 UTC (1787115050) [ 3.535581] debug: unmapping init [mem 0xffffffffb8403000-0xffffffffb85fffff] [ 3.539019] debug: unmapping init [mem 0xffffffffb7182000-0xffffffffb7458fff] [ 3.549090] Write protecting the kernel read-only data: 28672k [ 3.553101] debug: unmapping init [mem 0xffffffffb5803000-0xffffffffb59fffff] [ 3.556248] debug: unmapping init [mem 0xffffffffb6114000-0xffffffffb61fffff] [ 3.597932] 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.606750] systemd[1]: Detected virtualization kvm. [ 3.609095] systemd[1]: Detected architecture x86-64. [ 3.611402] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.640114] systemd[1]: No hostname configured. [ 3.641785] systemd[1]: Set hostname to . [ 3.644085] random: systemd: uninitialized urandom read (16 bytes read) [ 3.646826] systemd[1]: Initializing machine ID from random generator. [ 3.772934] random: systemd: uninitialized urandom read (16 bytes read) [ 3.776625] systemd[1]: Listening on udev Control Socket. [ OK ] Listening on udev Control Socket. [ 3.781938] random: systemd: uninitialized urandom read (16 bytes read) [ 3.784707] systemd[1]: Reached target Local File Systems. [ OK ] Reached target Local File Systems. [ 3.789667] systemd[1]: Listening on udev Kernel Socket. [ OK ] Listening on udev Kernel Socket. [ OK ] Reached target Timers. [ OK ] Reached target Slices. [ OK ] Reached target Initrd Root Device. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Paths. [ OK ] Listening on Journal Socket. Starting Apply Kernel Variables... [ OK ] Started Memstrack Anylazing Service. Starting Setup Virtual Console... Starting Create Volatile Files and Directories... [ OK ] Listening on Journal Socket (/dev/log). Starting Journal Service... [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Sockets. [ OK ] Reached target Swap. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Started Apply Kernel Variables. [ OK ] Started Setup Virtual Console. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Create list of required sta…vice nodes for the current kernel. 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.389276] device-mapper: uevent: version 1.0.3 [ 4.392372] 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.159699] virtio_net virtio0 ens2: renamed from eth0 [ 5.203795] random: fast init done [ 5.240699] scsi host0: ata_piix [ 5.285292] scsi host1: ata_piix [ 5.286896] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 5.289187] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 8.959902] dracut-initqueue[581]: RTNETLINK answers: File exists [ 10.035955] random: crng init done [ 10.036810] 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.471293] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped target Timers. [ OK ] Stopped target Remote File Systems. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Slices. [ OK ] Stopped target Sockets. [ OK ] Stopped target Paths. [ OK ] Stopped target System Initialization. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. Stopping udev Kernel Device Manager... [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped target Swap. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Closed udev Kernel Socket. [ OK ] Closed udev Control Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 11.604388] printk: systemd: 26 output lines suppressed due to ratelimiting [ 11.867700] SELinux: Disabled at runtime. [ 11.929168] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 11.938970] systemd[1]: Detected virtualization kvm. [ 11.940737] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 12.419202] systemd[1]: initrd-switch-root.service: Succeeded. [ 12.421372] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 12.424536] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 12.428301] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 12.433222] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 12.445909] systemd[1]: Starting Journal Service... Starting Journal Service... [ 12.454511] systemd[1]: Created slice system-getty.slice. [ OK ] Created slice system-getty.slice. [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Started Forward Password Requests to Wall Directory Watch. Starting Remount Root and Kernel File Systems... [ 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 ] Listening on RPCbind Server Activation Socket. Mounting Huge Pages File System... [ OK ] Created slice system-sshd\x2dkeygen.slice. Activating swap /dev/disk/by-label/SWAP... [ OK ] Listening on Process Core Dump Socket. [ 12.543742] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS Mounting Kernel Debug File System... Starting Create list of required st…ce nodes for the current kernel... [ OK ] Stopped target Switch Root. [ OK ] Listening on udev Control Socket. Starting Apply Kernel Variables... [ OK ] Reached target rpc_pipefs.target. [ OK ] Reached target RPC Port Mapper. [ OK ] Stopped target Initrd File Systems. Mounting POSIX Message Queue File System... [ OK ] Stopped target Initrd Root File System. [ OK ] Listening on udev Kernel Socket. Starting udev Coldplug all Devices... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Paths. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Created slice User and Session Slice. [ OK ] Reached target Slices. [ OK ] Started Journal Service. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Mounted Huge Pages File System. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Mounted Kernel Debug File System. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Apply Kernel Variables. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Reached target Swap. Starting Create Static Device Nodes in /dev... Starting Configure read-only root support... Starting Flush Journal to Persistent Storage... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. Starting udev Kernel Device Manager... [ OK ] Reached target Local File Systems (Pre). Mounting /mnt... Mounting /home/green/git/lustre-release... [ OK ] Mounted /mnt. [ 12.895264] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Coldplug all Devices. [ OK ] Started udev Kernel Device Manager. [ 13.218457] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 13.254720] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 13.472472] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 13.482952] EDAC sbridge: Ver: 1.1.2 [ 14.909142] Key type dns_resolver registered [ 15.225898] NFS: Registering the id_resolver key type [ 15.228112] Key type id_resolver registered [ 15.229950] 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 Update UTMP about System Boot/Shutdown... Starting RPC Bind... [ 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 dnf makecache --timer. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Reached target Timers. [ OK ] Reached target Basic System. [ OK ] Started D-Bus System Message Bus. Starting Restore /run/initramfs on shutdown... [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting Network Manager... Starting Login Service... [ OK ] Started irqbalance daemon. [ OK ] Reached target sshd-keygen.target. [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Login Service. [ OK ] Started Network Manager. Starting Network Manager Wait Online... [ OK ] Reached target Network. Starting OpenSSH server daemon... Starting GSSAPI Proxy Daemon... Starting Dynamic System Tuning Daemon... [ OK ] Started GSSAPI Proxy Daemon. Starting Hostname Service... [ 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 OpenSSH server daemon. [ OK ] Started Permit User Sessions. [ OK ] Started Command Scheduler. [ OK ] Started Serial Getty on ttyS1. [ OK ] Started Getty on tty1. [ OK ] Started Serial Getty on ttyS0. [ OK ] Reached target Login Prompts. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting System Logging Service... Starting Crash recovery kernel arming... Starting Notify NFS peers of a restart... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Starting Authorization Manager... [ 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 oleg224-server login: [ 62.789257] libcfs: loading out-of-tree module taints kernel. [ 62.820960] Key type ._llcrypt registered [ 62.822706] Key type .llcrypt registered [ 62.907819] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_hostid [ 83.147272] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing load_modules_local [ 85.304524] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 85.314967] alg: No test for adler32 (adler32-zlib) [ 86.948852] Lustre: Lustre: Build Version: 2.17.56_4_gb718cad [ 87.878921] LNet: Added LNI 192.168.202.124@tcp [8/256/0/180] [ 89.655691] Key type lgssc registered [ 91.865477] Lustre: Echo OBD driver; http://www.lustre.org/ [ 113.824300] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 146.926215] hrtimer: interrupt took 8062511 ns [ 162.029106] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing load_modules_local [ 175.584608] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 175.608179] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 176.778436] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 176.799798] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 176.857324] Lustre: lustre-MDT0000: new disk, initializing [ 176.943938] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 176.956372] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 183.753810] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 199.479871] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 199.691422] Lustre: 6506:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 199.727317] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 199.730821] Lustre: Skipped 1 previous similar message [ 199.814952] Lustre: lustre-MDT0001: new disk, initializing [ 199.884246] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 199.930674] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 199.939295] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 204.266021] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 209.565404] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 219.112358] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 219.401607] Lustre: lustre-OST0000: new disk, initializing [ 219.408423] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 219.416118] Lustre: 8444:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 219.489299] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 224.875960] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 224.884208] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 224.972761] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 226.106438] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 240.768610] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 240.902921] Lustre: lustre-OST0001: new disk, initializing [ 240.906918] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 240.912726] Lustre: 9517:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 240.973614] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 246.771231] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 247.888863] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 247.906386] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 248.033267] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 260.207608] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 270.211449] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 277.938751] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing check_logdir /tmp/testlogs/ [ 282.642212] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing yml_node [ 288.554851] Lustre: DEBUG MARKER: Client: 2.17.56.4 [ 291.794255] Lustre: DEBUG MARKER: MDS: 2.17.56.4 [ 295.477386] Lustre: DEBUG MARKER: OSS: 2.17.56.4 [ 296.894263] Lustre: DEBUG MARKER: -----============= acceptance-small: replay-single ============----- Wed Aug 19 00:55:41 EDT 2026 [ 317.621710] Lustre: DEBUG MARKER: excepting tests: 110f 131b 59 36 [ 319.628485] Lustre: DEBUG MARKER: === replay-single: start setup 00:56:03 (1787115363) === [ 325.532614] Lustre: DEBUG MARKER: oleg224-client.virtnet: executing check_config_client /mnt/lustre [ 345.993738] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 349.631089] Lustre: 13330:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 353.918736] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 360.681742] Lustre: DEBUG MARKER: === replay-single: finish setup 00:56:44 (1787115404) === [ 363.945738] Lustre: DEBUG MARKER: == replay-single test 100a: DNE: create striped dir, drop update rep from MDT1, fail MDT1 ========================================================== 00:56:48 (1787115408) [ 365.296902] Lustre: *** cfs_fail_loc=1701, val=2147483648*** [ 365.300543] LustreError: 6518:0:(ldlm_lib.c:3345:target_send_reply_msg()) @@@ dropping reply req@ffff8c3f87683800 x1873926038867200/t4294967300(0) o1000->lustre-MDT0000-mdtlov_UUID@0@lo:223/0 lens 264/4320 e 0 to 0 dl 1787115423 ref 1 fl Interpret:/200/0 rc 0/0 job:'osp_up1-0.0' uid:0 gid:0 projid:4294967295 [ 366.948836] Lustre: Failing over lustre-MDT0001 [ 367.121449] Lustre: server umount lustre-MDT0001 complete [ 371.167963] Lustre: lustre-MDT0001-osp-MDT0000: Connection to lustre-MDT0001 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 371.189328] Lustre: Skipped 2 previous similar messages [ 376.293162] LustreError: 10515:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0001: 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. [ 376.312449] LustreError: 10515:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 7 previous similar messages [ 377.085713] LustreError: 6513:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0001: not available for connect from 192.168.202.24@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 381.409052] Lustre: 7845:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787115412/real 1787115412] req@ffff8c3f87683b80 x1873926038867200/t0(0) o1000->lustre-MDT0001-osp-MDT0000@0@lo:24/4 lens 264/4320 e 0 to 1 dl 1787115428 ref 2 fl Rpc:XQr/200/ffffffff rc 0/-1 job:'osp_up1-0.0' uid:0 gid:0 projid:4294967295 [ 381.416662] LustreError: 6518:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0001: 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. [ 381.456893] LustreError: 6518:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 2 previous similar messages [ 386.543203] LustreError: 6514:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0001: 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. [ 386.570706] LustreError: 6514:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 3 previous similar messages [ 386.640254] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 386.963872] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 387.321347] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 391.976113] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 392.168775] Lustre: lustre-MDT0001-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 392.190122] Lustre: lustre-MDT0001: Recovery over after 0:05, of 2 clients 2 recovered and 0 were evicted. [ 402.046813] Lustre: DEBUG MARKER: oleg224-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 403.773968] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 413.789272] Lustre: DEBUG MARKER: == replay-single test 100b: DNE: create striped dir, fail MDT0 ========================================================== 00:57:38 (1787115458) [ 414.898888] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 414.903338] LustreError: 6514:0:(ldlm_lib.c:3345:target_send_reply_msg()) @@@ dropping reply req@ffff8c3f875d3480 x1873926016780928/t4294967361(0) o36->97066b6e-1c3d-4932-ad2b-003a266fbca9@192.168.202.24@tcp:311/0 lens 560/536 e 0 to 0 dl 1787115511 ref 1 fl Interpret:/200/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 416.704075] Lustre: Failing over lustre-MDT0000 [ 416.721237] LustreError: 9527:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787115463 with bad export cookie 983780846901466378 [ 416.732366] LustreError: 9527:0:(ldlm_lock.c:2770:ldlm_lock_dump_handle()) ### ### ns: mdt-lustre-MDT0001_UUID lock: ffff8c40afa92600/0xda71777cc651e41 lrc: 3/0,0 mode: PW/PW res: [0x240000401:0x5:0x0].0x0 bits 0x2/0x0 rrc: 2 type: IBT gid 0 flags: 0x40000000000000 nid: 0@lo remote: 0xda71777cc651e3a expref: 7 pid: 14321 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 [ 417.000749] Lustre: server umount lustre-MDT0000 complete [ 417.760302] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 417.768047] 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 [ 417.769111] LustreError: 6515: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. [ 417.810793] Lustre: Skipped 3 previous similar messages [ 428.001139] LustreError: 6518: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. [ 428.022706] LustreError: 6518:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 12 previous similar messages [ 433.119664] Lustre: 3638:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787115464/real 1787115464] req@ffff8c40bfcb7800 x1873926038906368/t0(0) o400->MGC192.168.202.124@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1787115480 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 433.159823] LustreError: MGC192.168.202.124@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 436.222673] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 443.361793] LustreError: 3637:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8c3f872a4a80 x1873926038914944/t0(0) o250->MGC192.168.202.124@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 [ 443.631489] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 445.287219] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 448.395742] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 448.997620] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 449.005312] Lustre: Skipped 2 previous similar messages [ 449.039099] Lustre: lustre-MDT0000: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 449.041831] Lustre: 6513:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff8c3f872a5180 x1873926016780928/t4294967361(0) o36->97066b6e-1c3d-4932-ad2b-003a266fbca9@192.168.202.24@tcp:346/0 lens 560/2880 e 0 to 0 dl 1787115546 ref 1 fl Interpret:/202/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 449.108829] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:6 to 0x2c0000401:33) [ 449.109672] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:6 to 0x280000401:33) [ 459.089632] Lustre: DEBUG MARKER: oleg224-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 460.846296] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 470.733475] Lustre: DEBUG MARKER: == replay-single test 100c: DNE: create striped dir, abort_recov_mdt mds2 ========================================================== 00:58:34 (1787115514) [ 480.039209] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 482.130151] Lustre: Failing over lustre-MDT0001 [ 482.711094] Lustre: server umount lustre-MDT0001 complete [ 484.837023] Lustre: lustre-MDT0001-lwp-OST0000: Connection to lustre-MDT0001 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 484.843905] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 484.847306] LustreError: 6514:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0001: 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. [ 484.847316] LustreError: 6514:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 15 previous similar messages [ 484.876487] Lustre: Skipped 2 previous similar messages [ 496.391759] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 496.394789] LDISKFS-fs (dm-1): recovery complete [ 496.407127] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 496.776937] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 496.805582] Lustre: lustre-MDT0001: Aborting MDT recovery [ 496.820656] LustreError: 17664:0:(lod_dev.c:511:lod_sub_recovery_thread()) lustre-MDT0000-osp-MDT0001: get update log duration 0, retries 0, failed: rc = -108 [ 498.144892] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 502.248906] Lustre: lustre-MDT0001-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 502.253181] Lustre: Skipped 3 previous similar messages [ 502.338217] Lustre: lustre-MDT0001-osd: cancel update llog [0x240000400:0x1:0x0] [ 502.358566] Lustre: lustre-MDT0000-osp-MDT0001: cancel update llog [0x200000401:0x1:0x0] [ 502.381292] Lustre: lustre-MDT0001: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 502.414431] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:46 to 0x280000400:65) [ 502.414469] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:46 to 0x2c0000400:65) [ 502.452856] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 519.906815] Lustre: Failing over lustre-MDT0001 [ 520.254946] Lustre: server umount lustre-MDT0001 complete [ 522.724594] Lustre: lustre-MDT0001-osp-MDT0000: Connection to lustre-MDT0001 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 522.726390] LustreError: 6513:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0001: 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. [ 522.737059] Lustre: Skipped 2 previous similar messages [ 522.764875] LustreError: 6513:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 13 previous similar messages [ 539.332120] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 539.656896] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 541.523083] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 544.316636] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 544.746267] Lustre: lustre-MDT0001-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 544.751567] Lustre: Skipped 2 previous similar messages [ 544.784381] Lustre: lustre-MDT0001: Recovery over after 0:03, of 2 clients 2 recovered and 0 were evicted. [ 544.809166] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:70 to 0x280000400:97) [ 544.809327] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:70 to 0x2c0000400:97) [ 554.793255] Lustre: DEBUG MARKER: oleg224-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 556.434731] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 567.573657] Lustre: DEBUG MARKER: == replay-single test 100d: DNE: cancel update logs upon recovery abort ========================================================== 01:00:11 (1787115611) [ 583.424690] Lustre: Failing over lustre-MDT0001 [ 585.193429] LustreError: lustre-MDT0001-osp-MDT0000: operation out_update to node 0@lo failed: rc = -107 [ 585.204566] Lustre: lustre-MDT0001-osp-MDT0000: Connection to lustre-MDT0001 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 585.221134] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 587.025827] Lustre: lustre-MDT0001: Not available for connect from 192.168.202.24@tcp (stopping) [ 587.030711] Lustre: Skipped 2 previous similar messages [ 589.024964] Lustre: server umount lustre-MDT0001 complete [ 590.821148] LustreError: 14321:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0001: 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. [ 590.836913] LustreError: 14321:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 16 previous similar messages [ 597.797668] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 598.227823] Lustre: lustre-MDT0001: Aborting client recovery [ 598.231320] LustreError: 20186:0:(ldlm_lib.c:3003:target_stop_recovery_thread()) lustre-MDT0001: Aborting recovery [ 598.240185] Lustre: 20210:0:(ldlm_lib.c:2403:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 598.256062] LustreError: 20208:0:(lod_dev.c:511:lod_sub_recovery_thread()) lustre-MDT0001-osd: get update log duration 0, retries 0, failed: rc = -108 [ 598.262829] Lustre: 20210:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0001: disconnect stale client 97066b6e-1c3d-4932-ad2b-003a266fbca9@ [ 598.275325] Lustre: lustre-MDT0001: disconnecting 2 stale clients [ 598.281391] Lustre: lustre-MDT0001-osd: cancel update llog [0x2400013a0:0x3:0x0] [ 598.290487] Lustre: lustre-MDT0000-osp-MDT0001: cancel update llog [0x200000bd1:0x3:0x0] [ 598.354455] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:70 to 0x2c0000400:129) [ 598.360789] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:70 to 0x280000400:129) [ 603.208424] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 603.617983] Lustre: lustre-MDT0001-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 603.629060] Lustre: Skipped 2 previous similar messages [ 603.635453] LustreError: lustre-MDT0001-osp-MDT0000: This client was evicted by lustre-MDT0001; in progress operations using this service will fail. [ 627.245042] Lustre: DEBUG MARKER: == replay-single test 100e: DNE: create striped dir on MDT0 and MDT1, fail MDT0, MDT1 ========================================================== 01:01:11 (1787115671) [ 635.691770] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 642.618203] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 644.995852] Lustre: Failing over lustre-MDT0000 [ 645.442485] Lustre: server umount lustre-MDT0000 complete [ 649.183651] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 649.196575] Lustre: lustre-MDT0000-osp-MDT0001: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 649.216249] Lustre: Skipped 2 previous similar messages [ 649.228427] LustreError: 6499:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787115696 with bad export cookie 983780846901468842 [ 649.252064] LustreError: MGC192.168.202.124@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 649.253249] Lustre: Failing over lustre-MDT0001 [ 649.254575] LustreError: 6499:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 3 previous similar messages [ 649.572844] Lustre: server umount lustre-MDT0001 complete [ 674.638563] LDISKFS-fs (dm-1): 5 truncates cleaned up [ 674.644248] LDISKFS-fs (dm-1): recovery complete [ 674.655061] LDISKFS-fs (dm-0): 3 truncates cleaned up [ 674.660182] LDISKFS-fs (dm-0): recovery complete [ 674.662297] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 674.679763] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 675.033304] LustreError: 23152:0:(llog.c:1655:llog_backup()) MGC192.168.202.124@tcp: failed to open log lustre-sptlrpc: rc = -108 [ 675.041684] Lustre: 23152:0:(mgc_request_server.c:770:mgc_llog_local_copy()) MGC192.168.202.124@tcp: failed to copy new config lustre-sptlrpc: rc = -108 [ 679.903980] Lustre: lustre-MDT0001-lwp-OST0001: Connection to lustre-MDT0001 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 679.927959] Lustre: Skipped 2 previous similar messages [ 694.523184] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 694.525414] Lustre: Skipped 1 previous similar message [ 694.551288] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 694.789647] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_connect to node 0@lo failed: rc = -114 [ 696.100970] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 700.393863] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 700.407814] Lustre: Skipped 2 previous similar messages [ 700.556479] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 700.674276] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 700.780899] Lustre: lustre-MDT0001: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 700.863750] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:70 to 0x280000400:161) [ 700.909872] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:70 to 0x2c0000400:161) [ 701.649794] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:44 to 0x280000401:65) [ 701.654293] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:44 to 0x2c0000401:65) [ 704.735191] Lustre: 3639:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787115696/real 1787115696] req@ffff8c3f875e0e00 x1873926039245184/t0(0) o400->lustre-MDT0001-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787115751 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 709.087187] Lustre: 3640:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787115701/real 1787115701] req@ffff8c3f865e3480 x1873926039245568/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787115756 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 709.116766] Lustre: 3640:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 5 previous similar messages [ 711.922839] Lustre: DEBUG MARKER: oleg224-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 713.616665] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 714.208216] Lustre: 3640:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787115706/real 1787115706] req@ffff8c3f865e0e00 x1873926039246208/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787115761 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 714.233884] Lustre: 3640:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 4 previous similar messages [ 715.176978] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 724.447265] Lustre: 3638:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787115716/real 1787115716] req@ffff8c3f876f5880 x1873926039247488/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787115771 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 724.482629] Lustre: 3638:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 6 previous similar messages [ 725.725671] Lustre: DEBUG MARKER: == replay-single test 101: Shouldn't reassign precreated objs to other files after recovery ========================================================== 01:02:49 (1787115769) [ 736.506362] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 766.075349] Lustre: Failing over lustre-MDT0000 [ 766.811639] Lustre: server umount lustre-MDT0000 complete [ 766.946807] 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 [ 766.954367] LustreError: 23729: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. [ 766.969198] Lustre: Skipped 3 previous similar messages [ 767.014459] LustreError: 23729:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 35 previous similar messages [ 782.096595] LDISKFS-fs (dm-0): 3 truncates cleaned up [ 782.102108] LDISKFS-fs (dm-0): recovery complete [ 782.139922] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 782.423167] LustreError: MGC192.168.202.124@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 782.896439] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 782.902225] Lustre: lustre-MDT0000: Aborting client recovery [ 782.903682] Lustre: Skipped 1 previous similar message [ 782.911566] LustreError: 25592:0:(ldlm_lib.c:3003:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 782.914887] Lustre: 25625:0:(ldlm_lib.c:2403:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 782.938545] Lustre: 25625:0:(ldlm_lib.c:2403:target_recovery_overseer()) Skipped 2 previous similar messages [ 782.944578] Lustre: 25625:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 97066b6e-1c3d-4932-ad2b-003a266fbca9@ [ 782.951608] Lustre: 25625:0:(genops.c:1622:class_disconnect_stale_exports()) Skipped 1 previous similar message [ 782.961527] Lustre: lustre-MDT0000: disconnecting 2 stale clients [ 782.975090] Lustre: lustre-MDT0000-osd: cancel update llog [0x200000400:0x1:0x0] [ 783.001366] Lustre: lustre-MDT0001-osp-MDT0000: cancel update llog [0x240000401:0x1:0x0] [ 783.066988] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:67 to 0x2c0000401:609) [ 783.090080] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:44 to 0x280000401:609) [ 787.943303] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 787.950077] Lustre: Skipped 5 previous similar messages [ 789.369174] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 895.408966] Lustre: DEBUG MARKER: == replay-single test 102a: check resend (request lost) with multiple modify RPCs in flight ========================================================== 01:05:39 (1787115939) [ 897.156803] Lustre: *** cfs_fail_loc=159, val=0*** [ 952.128664] Lustre: lustre-MDT0001: Client 97066b6e-1c3d-4932-ad2b-003a266fbca9 (at 192.168.202.24@tcp) reconnecting [ 960.512628] Lustre: DEBUG MARKER: == replay-single test 102b: check resend (reply lost) with multiple modify RPCs in flight ========================================================== 01:06:44 (1787116004) [ 962.510242] Lustre: *** cfs_fail_loc=15a, val=0*** [ 962.520255] Lustre: Skipped 1 previous similar message [ 1017.604615] Lustre: lustre-MDT0000: Client 97066b6e-1c3d-4932-ad2b-003a266fbca9 (at 192.168.202.24@tcp) reconnecting [ 1017.669194] Lustre: 23162:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff8c3f867d8700 x1873926019828992/t17179873232(0) o36->97066b6e-1c3d-4932-ad2b-003a266fbca9@192.168.202.24@tcp:159/0 lens 488/3152 e 0 to 0 dl 1787116114 ref 1 fl Interpret:/202/0 rc 0/0 job:'chmod.0' uid:0 gid:0 projid:4294967295 [ 1017.694105] Lustre: 23162:0:(mdt_recovery.c:102:mdt_req_from_lrd()) Skipped 6 previous similar messages [ 1026.404780] Lustre: DEBUG MARKER: == replay-single test 102c: check replay w/o reconstruction with multiple mod RPCs in flight ========================================================== 01:07:50 (1787116070) [ 1035.269418] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 1036.315156] Lustre: *** cfs_fail_loc=15a, val=0*** [ 1036.318303] Lustre: Skipped 5 previous similar messages [ 1039.861175] Lustre: Failing over lustre-MDT0001 [ 1040.110875] Lustre: server umount lustre-MDT0001 complete [ 1043.201404] LustreError: 23763:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0001: not available for connect from 192.168.202.24@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1043.245769] LustreError: 23763:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 15 previous similar messages [ 1043.936139] Lustre: lustre-MDT0001-lwp-OST0000: Connection to lustre-MDT0001 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 1043.937841] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 1043.952107] Lustre: Skipped 2 previous similar messages [ 1062.643459] LDISKFS-fs (dm-1): 7 truncates cleaned up [ 1062.647154] LDISKFS-fs (dm-1): recovery complete [ 1062.667961] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1062.950114] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 1062.954484] Lustre: Skipped 2 previous similar messages [ 1062.981190] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 1062.989372] Lustre: Skipped 2 previous similar messages [ 1063.686335] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 1063.698024] Lustre: Skipped 1 previous similar message [ 1067.681783] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1068.005499] Lustre: lustre-MDT0001-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 1068.018159] Lustre: Skipped 2 previous similar messages [ 1068.035658] Lustre: lustre-MDT0001: Recovery over after 0:05, of 2 clients 2 recovered and 0 were evicted. [ 1068.039913] Lustre: Skipped 1 previous similar message [ 1068.084249] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:169 to 0x280000400:193) [ 1068.085059] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:169 to 0x2c0000400:193) [ 1079.419053] Lustre: DEBUG MARKER: oleg224-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 1081.275106] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1093.048610] Lustre: DEBUG MARKER: == replay-single test 102d: check replay [ 1094.971656] Lustre: *** cfs_fail_loc=15a, val=0*** [ 1094.978390] Lustre: Skipped 5 previous similar messages [ 1100.346461] Lustre: Failing over lustre-MDT0000 [ 1100.813757] Lustre: server umount lustre-MDT0000 complete [ 1118.177799] Lustre: 3638:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787116148/real 1787116148] req@ffff8c3f88ce8a80 x1873926039913216/t0(0) o400->MGC192.168.202.124@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1787116164 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1118.216064] Lustre: 3638:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 5 previous similar messages [ 1118.226106] LustreError: MGC192.168.202.124@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1119.701626] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1128.422979] LustreError: 3637:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8c40b26ee680 x1873926039922816/t0(0) o250->MGC192.168.202.124@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 [ 1128.941565] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1129.979692] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 1132.728920] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1134.050852] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 1134.056147] Lustre: Skipped 2 previous similar messages [ 1134.093192] Lustre: lustre-MDT0000: Recovery over after 0:05, of 2 clients 2 recovered and 0 were evicted. [ 1134.153123] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1117 to 0x280000401:1153) [ 1134.154192] Lustre: 23163:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff8c40c12d8700 x1873926019891456/t17179873291(0) o36->97066b6e-1c3d-4932-ad2b-003a266fbca9@192.168.202.24@tcp:276/0 lens 488/3152 e 0 to 0 dl 1787116231 ref 1 fl Interpret:/202/0 rc 0/0 job:'chmod.0' uid:0 gid:0 projid:4294967295 [ 1134.163191] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1117 to 0x2c0000401:1153) [ 1134.211762] Lustre: 23163:0:(mdt_recovery.c:102:mdt_req_from_lrd()) Skipped 6 previous similar messages [ 1141.311306] Lustre: DEBUG MARKER: oleg224-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1143.311802] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1152.168942] Lustre: DEBUG MARKER: == replay-single test 103: Check otr_next_id overflow ==== 01:09:56 (1787116196) [ 1156.196819] Lustre: Failing over lustre-MDT0000 [ 1156.548346] Lustre: server umount lustre-MDT0000 complete [ 1159.648154] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1174.093144] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1174.202914] LustreError: MGC192.168.202.124@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1174.357898] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1176.378988] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 1178.987697] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1179.673309] Lustre: lustre-MDT0000: Recovery over after 0:03, of 2 clients 2 recovered and 0 were evicted. [ 1179.725791] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1117 to 0x280000401:1185) [ 1179.736740] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1117 to 0x2c0000401:1185) [ 1188.172868] Lustre: DEBUG MARKER: oleg224-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1189.717824] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1198.564647] Lustre: DEBUG MARKER: == replay-single test 110a: DNE: create striped dir, fail MDT1 ========================================================== 01:10:42 (1787116242) [ 1206.064450] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1208.202959] Lustre: Failing over lustre-MDT0000 [ 1208.478467] Lustre: server umount lustre-MDT0000 complete [ 1210.335756] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1210.339622] Lustre: lustre-MDT0000-lwp-MDT0001: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 1210.361575] Lustre: Skipped 11 previous similar messages [ 1226.193454] Lustre: 3641:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787116257/real 1787116257] req@ffff8c3f89961c00 x1873926039992704/t0(0) o400->MGC192.168.202.124@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1787116273 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1226.207725] LustreError: MGC192.168.202.124@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1231.896233] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1231.901143] LDISKFS-fs (dm-0): recovery complete [ 1231.908713] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1236.842965] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1241.817992] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1242.189630] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1117 to 0x2c0000401:1217) [ 1242.200525] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1117 to 0x280000401:1217) [ 1252.582896] Lustre: DEBUG MARKER: oleg224-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1253.957222] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1262.949726] Lustre: DEBUG MARKER: == replay-single test 110b: DNE: create striped dir, fail MDT1 and client ========================================================== 01:11:47 (1787116307) [ 1270.682696] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1273.343204] Lustre: Failing over lustre-MDT0000 [ 1273.674064] Lustre: server umount lustre-MDT0000 complete [ 1276.900382] LustreError: 6499:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787116323 with bad export cookie 983780846901695033 [ 1276.910140] LustreError: 6499:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 1293.279637] Lustre: 3638:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787116324/real 1787116324] req@ffff8c3f899f6d80 x1873926040036096/t0(0) o400->MGC192.168.202.124@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1787116340 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1293.316365] LustreError: MGC192.168.202.124@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1299.685525] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1299.688570] LDISKFS-fs (dm-0): recovery complete [ 1299.694675] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1303.521339] LustreError: 3637:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8c40b1c59f80 x1873926040044544/t0(0) o250->MGC192.168.202.124@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 [ 1303.944288] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1308.777615] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1309.156432] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 1309.162743] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 1309.163775] Lustre: Skipped 1 previous similar message [ 1309.184763] Lustre: Skipped 11 previous similar messages [ 1318.557710] Lustre: DEBUG MARKER: oleg224-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1321.033077] Lustre: lustre-MDT0000: Denying connection for new client 0e82656b-27b6-481d-a280-ffff1bd40db3 (at 192.168.202.24@tcp), waiting for 2 known clients (0 recovered, 1 in progress, and 0 evicted) to recover in 0:58 [ 1326.336948] Lustre: lustre-MDT0000: Denying connection for new client 0e82656b-27b6-481d-a280-ffff1bd40db3 (at 192.168.202.24@tcp), waiting for 2 known clients (0 recovered, 1 in progress, and 0 evicted) to recover in 0:53 [ 1331.453151] Lustre: lustre-MDT0000: Denying connection for new client 0e82656b-27b6-481d-a280-ffff1bd40db3 (at 192.168.202.24@tcp), waiting for 2 known clients (0 recovered, 1 in progress, and 0 evicted) to recover in 0:48 [ 1336.571255] Lustre: lustre-MDT0000: Denying connection for new client 0e82656b-27b6-481d-a280-ffff1bd40db3 (at 192.168.202.24@tcp), waiting for 2 known clients (0 recovered, 1 in progress, and 0 evicted) to recover in 0:42 [ 1341.692040] Lustre: lustre-MDT0000: Denying connection for new client 0e82656b-27b6-481d-a280-ffff1bd40db3 (at 192.168.202.24@tcp), waiting for 2 known clients (0 recovered, 1 in progress, and 0 evicted) to recover in 0:37 [ 1351.940942] Lustre: lustre-MDT0000: Denying connection for new client 0e82656b-27b6-481d-a280-ffff1bd40db3 (at 192.168.202.24@tcp), waiting for 2 known clients (0 recovered, 1 in progress, and 0 evicted) to recover in 0:27 [ 1351.958829] Lustre: Skipped 1 previous similar message [ 1372.417163] Lustre: lustre-MDT0000: Denying connection for new client 0e82656b-27b6-481d-a280-ffff1bd40db3 (at 192.168.202.24@tcp), waiting for 2 known clients (0 recovered, 1 in progress, and 0 evicted) to recover in 0:07 [ 1372.427474] Lustre: Skipped 3 previous similar messages [ 1379.500454] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 1379.510598] Lustre: 35011:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 97066b6e-1c3d-4932-ad2b-003a266fbca9@ [ 1379.527123] Lustre: 35011:0:(genops.c:1622:class_disconnect_stale_exports()) Skipped 1 previous similar message [ 1379.545937] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 1379.568626] Lustre: lustre-MDT0000: Recovery over after 1:10, of 2 clients 1 recovered and 1 was evicted. [ 1379.580470] Lustre: Skipped 1 previous similar message [ 1379.642324] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1117 to 0x2c0000401:1249) [ 1379.653686] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1117 to 0x280000401:1249) [ 1394.133822] Lustre: DEBUG MARKER: == replay-single test 110c: DNE: create striped dir, fail MDT2 ========================================================== 01:13:58 (1787116438) [ 1402.818796] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 1405.040056] Lustre: Failing over lustre-MDT0001 [ 1405.652296] Lustre: server umount lustre-MDT0001 complete [ 1406.431835] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 1428.665740] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 1428.667828] LDISKFS-fs (dm-1): recovery complete [ 1428.675699] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1428.932658] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 1428.935330] Lustre: Skipped 4 previous similar messages [ 1428.965848] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 1433.667637] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1434.189105] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:209 to 0x280000400:225) [ 1434.190427] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:209 to 0x2c0000400:225) [ 1443.741568] Lustre: DEBUG MARKER: oleg224-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 1445.432784] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1454.959955] Lustre: DEBUG MARKER: == replay-single test 110d: DNE: create striped dir, fail MDT2 and client ========================================================== 01:14:59 (1787116499) [ 1462.791085] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 1464.839856] Lustre: Failing over lustre-MDT0001 [ 1465.098977] Lustre: server umount lustre-MDT0001 complete [ 1469.920541] Lustre: lustre-MDT0001-lwp-OST0000: Connection to lustre-MDT0001 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 1469.947528] Lustre: Skipped 10 previous similar messages [ 1487.005068] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 1487.006664] LDISKFS-fs (dm-1): recovery complete [ 1487.019726] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1492.157107] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1492.451972] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 1492.462644] Lustre: Skipped 1 previous similar message [ 1503.618307] Lustre: DEBUG MARKER: oleg224-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 1506.038253] Lustre: lustre-MDT0001: Denying connection for new client 628cea46-db7e-426c-ace3-fab5ee8878b9 (at 192.168.202.24@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 0:56 [ 1506.055367] Lustre: Skipped 1 previous similar message [ 1562.502299] Lustre: lustre-MDT0001: recovery is timed out, evict stale exports [ 1562.505942] Lustre: 38841:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0001: disconnect stale client 0e82656b-27b6-481d-a280-ffff1bd40db3@ [ 1562.529447] Lustre: lustre-MDT0001: disconnecting 1 stale clients [ 1562.565758] Lustre: lustre-MDT0001: Recovery over after 1:10, of 2 clients 1 recovered and 1 was evicted. [ 1562.574709] Lustre: Skipped 1 previous similar message [ 1562.618313] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:209 to 0x2c0000400:257) [ 1562.618669] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:209 to 0x280000400:257) [ 1575.757394] Lustre: DEBUG MARKER: == replay-single test 110e: DNE: create striped dir, uncommit on MDT2, fail client/MDT1/MDT2 ========================================================== 01:17:00 (1787116620) [ 1583.354482] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 1591.956957] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1594.059782] Lustre: Failing over lustre-MDT0000 [ 1594.338920] Lustre: server umount lustre-MDT0000 complete [ 1594.849634] LustreError: 23763: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. [ 1594.850452] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1594.872201] LustreError: 23763:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 155 previous similar messages [ 1594.894907] LustreError: Skipped 1 previous similar message [ 1597.860661] LustreError: 26176:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787116644 with bad export cookie 983780846901696601 [ 1597.861855] Lustre: Failing over lustre-MDT0001 [ 1597.862679] LustreError: MGC192.168.202.124@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1597.870946] LustreError: 26176:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 1598.189076] Lustre: server umount lustre-MDT0001 complete [ 1622.202777] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1622.205261] LDISKFS-fs (dm-0): recovery complete [ 1622.225913] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1622.435705] LustreError: 3637:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8c40aaf89880 x1873926040207104/t0(0) o250->MGC192.168.202.124@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 [ 1622.452144] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 1622.455430] LDISKFS-fs (dm-1): recovery complete [ 1622.465609] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1622.828521] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 1622.833122] Lustre: Skipped 1 previous similar message [ 1623.051246] Lustre: lustre-MDT0001-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 1623.073478] Lustre: Skipped 9 previous similar messages [ 1627.762468] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1628.138740] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1629.483658] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1117 to 0x280000401:1281) [ 1629.488305] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1117 to 0x2c0000401:1281) [ 1638.218349] Lustre: DEBUG MARKER: oleg224-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 1640.662589] Lustre: lustre-MDT0001: Denying connection for new client 0d27a98a-12db-4c70-8253-c55254a4ab6e (at 192.168.202.24@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 0:57 [ 1640.675222] Lustre: Skipped 11 previous similar messages [ 1654.239272] Lustre: 3639:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787116646/real 1787116646] req@ffff8c40aaa90e00 x1873926040204800/t0(0) o400->lustre-MDT0001-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787116701 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1654.253823] Lustre: 3639:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 1698.500186] Lustre: lustre-MDT0001: recovery is timed out, evict stale exports [ 1698.515803] Lustre: 41857:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0001: disconnect stale client 628cea46-db7e-426c-ace3-fab5ee8878b9@ [ 1698.532273] Lustre: lustre-MDT0001: disconnecting 1 stale clients [ 1698.616802] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:209 to 0x280000400:289) [ 1698.624119] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:209 to 0x2c0000400:289) [ 1710.595673] Lustre: DEBUG MARKER: SKIP: replay-single test_110f skipping excluded test 110f [ 1711.990500] Lustre: DEBUG MARKER: == replay-single test 110g: DNE: create striped dir, uncommit on MDT1, fail client/MDT1/MDT2 ========================================================== 01:19:16 (1787116756) [ 1719.092410] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1727.012544] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 1729.265298] Lustre: Failing over lustre-MDT0000 [ 1729.703640] Lustre: server umount lustre-MDT0000 complete [ 1733.868762] LustreError: 6500:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787116780 with bad export cookie 983780846901700780 [ 1733.871515] LustreError: MGC192.168.202.124@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1733.876760] Lustre: Failing over lustre-MDT0001 [ 1733.884823] LustreError: 6500:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 1734.217540] Lustre: server umount lustre-MDT0001 complete [ 1758.631668] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1758.635090] LDISKFS-fs (dm-0): recovery complete [ 1758.642213] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 1758.642427] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1758.644145] LDISKFS-fs (dm-1): recovery complete [ 1758.650589] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1758.754331] Lustre: MGS: Not available for connect from 0@lo (not set up) [ 1759.029562] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 1759.033691] Lustre: Skipped 1 previous similar message [ 1762.814535] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1762.951078] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1763.427838] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 1763.434325] Lustre: Skipped 2 previous similar messages [ 1764.280923] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:209 to 0x280000400:321) [ 1764.286173] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:209 to 0x2c0000400:321) [ 1773.371030] Lustre: DEBUG MARKER: oleg224-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 1775.970266] Lustre: lustre-MDT0000: Denying connection for new client c27f5f04-de3a-4ab1-b040-1600bb527ab9 (at 192.168.202.24@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 0:57 [ 1775.994050] Lustre: Skipped 11 previous similar messages [ 1833.500202] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 1833.507312] Lustre: 45335:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 0d27a98a-12db-4c70-8253-c55254a4ab6e@ [ 1833.518239] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 1833.534415] Lustre: lustre-MDT0000: Recovery over after 1:10, of 2 clients 1 recovered and 1 was evicted. [ 1833.541146] Lustre: Skipped 3 previous similar messages [ 1833.603655] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1117 to 0x2c0000401:1313) [ 1833.604895] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1117 to 0x280000401:1313) [ 1849.263861] Lustre: DEBUG MARKER: == replay-single test 111a: DNE: unlink striped dir, fail MDT1 ========================================================== 01:21:33 (1787116893) [ 1859.039541] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1861.186282] Lustre: Failing over lustre-MDT0000 [ 1861.494283] Lustre: server umount lustre-MDT0000 complete [ 1864.672260] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1864.685233] LustreError: Skipped 3 previous similar messages [ 1881.039390] LustreError: MGC192.168.202.124@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1886.772119] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1886.775789] LDISKFS-fs (dm-0): recovery complete [ 1886.799260] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1897.103685] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1117 to 0x2c0000401:1345) [ 1897.104242] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1117 to 0x280000401:1345) [ 1897.552768] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1908.007780] Lustre: DEBUG MARKER: oleg224-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1909.918813] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1919.886926] Lustre: DEBUG MARKER: == replay-single test 111b: DNE: unlink striped dir, fail MDT2 ========================================================== 01:22:43 (1787116963) [ 1929.470408] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 1932.267546] Lustre: Failing over lustre-MDT0001 [ 1932.593449] Lustre: server umount lustre-MDT0001 complete [ 1957.540101] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 1957.544911] LDISKFS-fs (dm-1): recovery complete [ 1957.560897] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1957.960365] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 1957.971033] Lustre: Skipped 6 previous similar messages [ 1963.409754] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1975.703473] Lustre: DEBUG MARKER: oleg224-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 2032.500147] Lustre: lustre-MDT0001: recovery is timed out, evict stale exports [ 2032.505143] Lustre: 49519:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0001: disconnect stale client c27f5f04-de3a-4ab1-b040-1600bb527ab9@ [ 2032.515757] Lustre: lustre-MDT0001: disconnecting 1 stale clients [ 2032.593624] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:209 to 0x2c0000400:353) [ 2032.595032] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:209 to 0x280000400:353) [ 2043.230971] Lustre: DEBUG MARKER: == replay-single test 111c: DNE: unlink striped dir, uncommit on MDT1, fail client/MDT1/MDT2 ========================================================== 01:24:47 (1787117087) [ 2052.075567] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2059.370265] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 2061.631713] Lustre: Failing over lustre-MDT0000 [ 2061.860698] Lustre: server umount lustre-MDT0000 complete [ 2065.383628] 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 [ 2065.394129] Lustre: Skipped 22 previous similar messages [ 2065.477499] Lustre: Failing over lustre-MDT0001 [ 2065.484231] LustreError: 6500:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787117112 with bad export cookie 983780846901705582 [ 2065.495448] LustreError: 6500:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 3 previous similar messages [ 2066.019923] Lustre: server umount lustre-MDT0001 complete [ 2086.700462] Lustre: 3639:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787117117/real 1787117117] req@ffff8c40a523d500 x1873926040455680/t0(0) o400->lustre-MDT0001-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787117133 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2086.755222] Lustre: 3639:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 27 previous similar messages [ 2091.568743] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 2091.575489] LDISKFS-fs (dm-1): recovery complete [ 2091.615792] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2091.652778] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2091.658145] LDISKFS-fs (dm-0): recovery complete [ 2091.669794] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2091.882501] LustreError: 52473:0:(llog.c:1655:llog_backup()) MGC192.168.202.124@tcp: failed to open log lustre-sptlrpc: rc = -108 [ 2091.897411] Lustre: 52473:0:(mgc_request_server.c:770:mgc_llog_local_copy()) MGC192.168.202.124@tcp: failed to copy new config lustre-sptlrpc: rc = -108 [ 2110.432426] LustreError: 3637:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8c40b60e2a00 x1873926040459520/t0(0) o250->MGC192.168.202.124@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 [ 2110.797619] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 2110.800424] Lustre: Skipped 3 previous similar messages [ 2116.730309] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2117.205310] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:209 to 0x2c0000400:385) [ 2117.209830] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:209 to 0x280000400:385) [ 2117.310548] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2128.966729] Lustre: DEBUG MARKER: oleg224-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 2131.578670] Lustre: lustre-MDT0000: Denying connection for new client dfcdc1bb-4434-4713-ae02-cc5ffd1f1c98 (at 192.168.202.24@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 0:54 [ 2131.594776] Lustre: Skipped 22 previous similar messages [ 2186.502422] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 2186.511200] Lustre: 52568:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 9ed82c4f-b4cd-49c5-b67e-c6425f94faf6@ [ 2186.526891] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 2186.561960] Lustre: lustre-MDT0000-osp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 2186.578472] Lustre: Skipped 23 previous similar messages [ 2186.608487] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1117 to 0x2c0000401:1377) [ 2186.611992] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1117 to 0x280000401:1377) [ 2198.185432] Lustre: DEBUG MARKER: == replay-single test 111d: DNE: unlink striped dir, uncommit on MDT2, fail client/MDT1/MDT2 ========================================================== 01:27:22 (1787117242) [ 2206.614688] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 2215.367756] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2217.773132] Lustre: Failing over lustre-MDT0000 [ 2218.133664] Lustre: server umount lustre-MDT0000 complete [ 2220.001054] LustreError: 52486: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. [ 2220.032508] LustreError: 52486:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 80 previous similar messages [ 2222.993557] Lustre: Failing over lustre-MDT0001 [ 2222.996711] LustreError: 6498:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787117269 with bad export cookie 983780846901708473 [ 2223.011057] LustreError: MGC192.168.202.124@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2223.014762] LustreError: 6498:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 2223.057927] LustreError: Skipped 1 previous similar message [ 2223.359882] Lustre: server umount lustre-MDT0001 complete [ 2252.474082] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2252.478305] LDISKFS-fs (dm-0): recovery complete [ 2252.487103] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2252.608505] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 2252.615968] LDISKFS-fs (dm-1): recovery complete [ 2252.669519] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2268.129628] LustreError: 3637:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8c40a525a300 x1873926040530944/t0(0) o250->MGC192.168.202.124@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 [ 2272.248153] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1117 to 0x280000401:1409) [ 2272.253747] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1117 to 0x2c0000401:1409) [ 2273.912208] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2274.788748] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2285.704689] Lustre: DEBUG MARKER: oleg224-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 2342.500134] Lustre: lustre-MDT0001: recovery is timed out, evict stale exports [ 2342.502385] Lustre: 55924:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0001: disconnect stale client dfcdc1bb-4434-4713-ae02-cc5ffd1f1c98@ [ 2342.517213] Lustre: lustre-MDT0001: disconnecting 1 stale clients [ 2342.642416] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:209 to 0x2c0000400:417) [ 2342.642421] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:209 to 0x280000400:417) [ 2354.116545] Lustre: DEBUG MARKER: == replay-single test 111e: DNE: unlink striped dir, uncommit on MDT2, fail MDT1/MDT2 ========================================================== 01:29:58 (1787117398) [ 2362.015450] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 2370.726924] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2372.869916] Lustre: Failing over lustre-MDT0000 [ 2373.516140] Lustre: server umount lustre-MDT0000 complete [ 2378.365585] LustreError: 19640:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787117425 with bad export cookie 983780846901710657 [ 2378.377112] Lustre: Failing over lustre-MDT0001 [ 2378.389730] LustreError: 19640:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 2378.960607] Lustre: server umount lustre-MDT0001 complete [ 2405.130861] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2405.134105] LDISKFS-fs (dm-0): recovery complete [ 2405.157556] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2405.217926] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 2405.219586] LDISKFS-fs (dm-1): recovery complete [ 2405.238201] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2424.498056] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_connect to node 0@lo failed: rc = -114 [ 2424.509907] LustreError: Skipped 4 previous similar messages [ 2428.720579] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 2428.730988] Lustre: Skipped 8 previous similar messages [ 2429.522647] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2429.976832] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2440.523544] Lustre: lustre-MDT0000: Recovery over after 0:12, of 2 clients 2 recovered and 0 were evicted. [ 2440.534775] Lustre: Skipped 6 previous similar messages [ 2440.582991] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1117 to 0x280000401:1441) [ 2440.584562] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1117 to 0x2c0000401:1441) [ 2441.653753] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:209 to 0x280000400:449) [ 2441.655799] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:209 to 0x2c0000400:449) [ 2448.516524] Lustre: DEBUG MARKER: oleg224-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 2450.112360] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2452.169630] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2461.867156] Lustre: DEBUG MARKER: == replay-single test 111f: DNE: unlink striped dir, uncommit on MDT1, fail MDT1/MDT2 ========================================================== 01:31:45 (1787117505) [ 2471.511370] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2481.836726] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 2484.065288] Lustre: Failing over lustre-MDT0000 [ 2484.198823] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2484.449672] Lustre: server umount lustre-MDT0000 complete [ 2488.748602] Lustre: Failing over lustre-MDT0001 [ 2488.750624] LustreError: 6500:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787117535 with bad export cookie 983780846901712995 [ 2488.778600] LustreError: 6500:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 2489.314322] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 2489.320054] Lustre: Skipped 4 previous similar messages [ 2492.675866] Lustre: lustre-MDT0001: Not available for connect from 192.168.202.24@tcp (stopping) [ 2495.406620] Lustre: server umount lustre-MDT0001 complete [ 2518.072210] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2518.078607] LDISKFS-fs (dm-0): recovery complete [ 2518.089251] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2518.349498] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 2518.352894] LDISKFS-fs (dm-1): recovery complete [ 2518.376032] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2539.255248] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2540.161959] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2544.010853] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1117 to 0x2c0000401:1473) [ 2544.011705] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1117 to 0x280000401:1473) [ 2557.471338] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:209 to 0x280000400:481) [ 2557.471523] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:209 to 0x2c0000400:481) [ 2563.474268] Lustre: DEBUG MARKER: oleg224-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 2565.302537] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2566.690809] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2577.447637] Lustre: DEBUG MARKER: == replay-single test 111g: DNE: unlink striped dir, fail MDT1/MDT2 ========================================================== 01:33:40 (1787117620) [ 2587.976726] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2596.607288] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 2599.462301] Lustre: Failing over lustre-MDT0000 [ 2600.093461] Lustre: server umount lustre-MDT0000 complete [ 2605.089726] LustreError: 6500:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787117652 with bad export cookie 983780846901715319 [ 2605.092282] Lustre: Failing over lustre-MDT0001 [ 2605.097171] LustreError: 6500:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 2605.541243] Lustre: server umount lustre-MDT0001 complete [ 2626.271191] Lustre: 3641:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787117657/real 1787117657] req@ffff8c40bf5d7100 x1873926040715008/t0(0) o400->lustre-MDT0001-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787117673 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2626.287885] Lustre: 3641:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 19 previous similar messages [ 2632.582029] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2632.583964] LDISKFS-fs (dm-0): recovery complete [ 2632.596184] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2632.787303] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 2632.793946] LDISKFS-fs (dm-1): recovery complete [ 2632.805722] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2650.079754] LustreError: 3637:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8c40a5258000 x1873926040717312/t0(0) o250->MGC192.168.202.124@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 [ 2650.730082] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 2650.743029] Lustre: Skipped 8 previous similar messages [ 2650.805410] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 2650.818458] Lustre: Skipped 7 previous similar messages [ 2657.481666] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2657.570561] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2669.298831] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1117 to 0x2c0000401:1505) [ 2669.306902] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1117 to 0x280000401:1505) [ 2670.627410] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:209 to 0x280000400:513) [ 2670.628438] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:209 to 0x2c0000400:513) [ 2680.122180] Lustre: DEBUG MARKER: oleg224-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 2682.136665] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2683.996780] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2694.522545] Lustre: DEBUG MARKER: == replay-single test 112a: DNE: cross MDT rename, fail MDT1 ========================================================== 01:35:38 (1787117738) [ 2696.755679] Lustre: DEBUG MARKER: SKIP: replay-single test_112a needs >= 4 MDTs [ 2699.550835] Lustre: DEBUG MARKER: == replay-single test 112b: DNE: cross MDT rename, fail MDT2 ========================================================== 01:35:42 (1787117742) [ 2702.837624] Lustre: DEBUG MARKER: SKIP: replay-single test_112b needs >= 4 MDTs [ 2705.829979] Lustre: DEBUG MARKER: == replay-single test 112c: DNE: cross MDT rename, fail MDT3 ========================================================== 01:35:49 (1787117749) [ 2707.940757] Lustre: DEBUG MARKER: SKIP: replay-single test_112c needs >= 4 MDTs [ 2710.576448] Lustre: DEBUG MARKER: == replay-single test 112d: DNE: cross MDT rename, fail MDT4 ========================================================== 01:35:54 (1787117754) [ 2713.305388] Lustre: DEBUG MARKER: SKIP: replay-single test_112d needs >= 4 MDTs [ 2716.033981] Lustre: DEBUG MARKER: == replay-single test 112e: DNE: cross MDT rename, fail MDT1 and MDT2 ========================================================== 01:35:59 (1787117759) [ 2719.465561] Lustre: DEBUG MARKER: SKIP: replay-single test_112e needs >= 4 MDTs [ 2722.019726] Lustre: DEBUG MARKER: == replay-single test 112f: DNE: cross MDT rename, fail MDT1 and MDT3 ========================================================== 01:36:05 (1787117765) [ 2723.896976] Lustre: DEBUG MARKER: SKIP: replay-single test_112f needs >= 4 MDTs [ 2726.078292] Lustre: DEBUG MARKER: == replay-single test 112g: DNE: cross MDT rename, fail MDT1 and MDT4 ========================================================== 01:36:10 (1787117770) [ 2727.713893] Lustre: DEBUG MARKER: SKIP: replay-single test_112g needs >= 4 MDTs [ 2729.847593] Lustre: DEBUG MARKER: == replay-single test 112h: DNE: cross MDT rename, fail MDT2 and MDT3 ========================================================== 01:36:13 (1787117773) [ 2731.362656] Lustre: DEBUG MARKER: SKIP: replay-single test_112h needs >= 4 MDTs [ 2734.857064] Lustre: DEBUG MARKER: == replay-single test 112i: DNE: cross MDT rename, fail MDT2 and MDT4 ========================================================== 01:36:17 (1787117777) [ 2737.393492] Lustre: DEBUG MARKER: SKIP: replay-single test_112i needs >= 4 MDTs [ 2740.567609] Lustre: DEBUG MARKER: == replay-single test 112j: DNE: cross MDT rename, fail MDT3 and MDT4 ========================================================== 01:36:23 (1787117783) [ 2742.581376] Lustre: DEBUG MARKER: SKIP: replay-single test_112j needs >= 4 MDTs [ 2745.432924] Lustre: DEBUG MARKER: == replay-single test 112k: DNE: cross MDT rename, fail MDT1,MDT2,MDT3 ========================================================== 01:36:28 (1787117788) [ 2747.931573] Lustre: DEBUG MARKER: SKIP: replay-single test_112k needs >= 4 MDTs [ 2750.439829] Lustre: DEBUG MARKER: == replay-single test 112l: DNE: cross MDT rename, fail MDT1,MDT2,MDT4 ========================================================== 01:36:33 (1787117793) [ 2751.952993] Lustre: DEBUG MARKER: SKIP: replay-single test_112l needs >= 4 MDTs [ 2754.206975] Lustre: DEBUG MARKER: == replay-single test 112m: DNE: cross MDT rename, fail MDT1,MDT3,MDT4 ========================================================== 01:36:37 (1787117797) [ 2756.309418] Lustre: DEBUG MARKER: SKIP: replay-single test_112m needs >= 4 MDTs [ 2758.587222] Lustre: DEBUG MARKER: == replay-single test 112n: DNE: cross MDT rename, fail MDT2,MDT3,MDT4 ========================================================== 01:36:42 (1787117802) [ 2760.729364] Lustre: DEBUG MARKER: SKIP: replay-single test_112n needs >= 4 MDTs [ 2763.150547] Lustre: DEBUG MARKER: == replay-single test 115: failover for create/unlink striped directory ========================================================== 01:36:46 (1787117806) [ 2773.488475] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 2777.122463] Lustre: Failing over lustre-MDT0001 [ 2777.735251] Lustre: server umount lustre-MDT0001 complete [ 2778.080759] Lustre: lustre-MDT0001-osp-MDT0000: Connection to lustre-MDT0001 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 2778.089577] Lustre: Skipped 26 previous similar messages [ 2802.343791] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 2802.346039] LDISKFS-fs (dm-1): recovery complete [ 2802.359274] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2807.780853] Lustre: lustre-MDT0001-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 2807.803291] Lustre: Skipped 24 previous similar messages [ 2808.083399] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:209 to 0x280000400:545) [ 2808.099080] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:209 to 0x2c0000400:545) [ 2808.964684] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2822.030973] Lustre: DEBUG MARKER: oleg224-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 2823.843198] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2835.209069] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2839.773636] Lustre: Failing over lustre-MDT0000 [ 2840.490253] Lustre: server umount lustre-MDT0000 complete [ 2843.617719] LustreError: 67002: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. [ 2843.659069] LustreError: 67002:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 55 previous similar messages [ 2860.004062] LustreError: MGC192.168.202.124@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2860.020125] LustreError: Skipped 3 previous similar messages [ 2868.217350] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2868.219767] LDISKFS-fs (dm-0): recovery complete [ 2868.243860] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2870.251265] LustreError: 3637:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8c40a5293480 x1873926040866432/t0(0) o250->MGC192.168.202.124@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 [ 2876.101868] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1117 to 0x280000401:1537) [ 2876.105029] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1117 to 0x2c0000401:1537) [ 2876.287634] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2888.341614] Lustre: DEBUG MARKER: oleg224-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2890.686825] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2901.719598] Lustre: DEBUG MARKER: == replay-single test 116a: large update log master MDT recovery ========================================================== 01:39:05 (1787117945) [ 2911.074838] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2912.721986] Lustre: *** cfs_fail_loc=1702, val=0*** [ 2915.387053] Lustre: Failing over lustre-MDT0000 [ 2915.666392] Lustre: server umount lustre-MDT0000 complete [ 2940.607572] LDISKFS-fs (dm-0): 4 truncates cleaned up [ 2940.609541] LDISKFS-fs (dm-0): recovery complete [ 2940.645348] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2942.434620] LustreError: 3637:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8c40bf5d6a00 x1873926040923136/t0(0) o250->MGC192.168.202.124@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 [ 2948.306867] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1117 to 0x2c0000401:1569) [ 2948.309147] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1117 to 0x280000401:1569) [ 2948.836083] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2960.858561] Lustre: DEBUG MARKER: oleg224-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2962.487148] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2972.247173] Lustre: DEBUG MARKER: == replay-single test 116b: large update log slave MDT recovery ========================================================== 01:40:16 (1787118016) [ 2984.997625] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 2986.880553] Lustre: *** cfs_fail_loc=1702, val=0*** [ 2991.007224] Lustre: Failing over lustre-MDT0001 [ 2991.411856] Lustre: server umount lustre-MDT0001 complete [ 2993.138553] LustreError: 9527:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787118040 with bad export cookie 983780846901724839 [ 3016.593632] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 3016.599086] LDISKFS-fs (dm-1): recovery complete [ 3016.667105] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3022.410339] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:209 to 0x2c0000400:577) [ 3022.412897] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:209 to 0x280000400:577) [ 3022.794492] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3033.906843] Lustre: DEBUG MARKER: oleg224-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 3035.990877] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3046.637651] Lustre: DEBUG MARKER: == replay-single test 117: DNE: cross MDT unlink, fail MDT1 and MDT2 ========================================================== 01:41:29 (1787118089) [ 3048.702661] Lustre: DEBUG MARKER: SKIP: replay-single test_117 needs >= 4 MDTs [ 3050.909943] Lustre: DEBUG MARKER: == replay-single test 118: invalidate osp update will not cause update log corruption ========================================================== 01:41:34 (1787118094) [ 3053.046400] Lustre: *** cfs_fail_loc=1705, val=0*** [ 3064.509596] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3067.343786] Lustre: Failing over lustre-MDT0000 [ 3067.655750] Lustre: server umount lustre-MDT0000 complete [ 3068.391529] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3068.404731] LustreError: Skipped 3 previous similar messages [ 3092.016101] LDISKFS-fs (dm-0): 3 truncates cleaned up [ 3092.017424] LDISKFS-fs (dm-0): recovery complete [ 3092.021488] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3094.111166] LustreError: 77776:0:(import.c:339:ptlrpc_invalidate_import()) MGS: timeout waiting for callback (1 != 0) [ 3094.116881] LustreError: 77776:0:(import.c:363:ptlrpc_invalidate_import()) @@@ still on sending list req@ffff8c3f872a6d80 x1873926041021952/t0(0) o250->MGC192.168.202.124@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 1787118141 ref 1 fl Rpc:NQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3094.131495] LustreError: 77776:0:(import.c:373:ptlrpc_invalidate_import()) MGS: Unregistering RPCs found (0). Network is sluggish? Waiting for them to error out. [ 3095.010703] LustreError: 3637:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8c40bfd08e00 x1873926041025152/t0(0) o250->MGC192.168.202.124@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 [ 3096.322441] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 3096.326142] Lustre: Skipped 8 previous similar messages [ 3100.786099] Lustre: lustre-MDT0000: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 3100.795316] Lustre: Skipped 9 previous similar messages [ 3100.847330] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1117 to 0x2c0000401:1601) [ 3100.847623] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1117 to 0x280000401:1601) [ 3101.084480] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3113.233989] Lustre: DEBUG MARKER: oleg224-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3115.307200] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3127.043326] Lustre: DEBUG MARKER: == replay-single test 119: timeout of normal replay does not cause DNE replay fails ========================================================== 01:42:50 (1787118170) [ 3137.852454] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3142.046469] Lustre: Failing over lustre-MDT0000 [ 3142.117169] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3142.127135] Lustre: Skipped 2 previous similar messages [ 3142.530551] Lustre: server umount lustre-MDT0000 complete [ 3162.748755] LDISKFS-fs (dm-0): 3 truncates cleaned up [ 3162.751798] LDISKFS-fs (dm-0): recovery complete [ 3162.789878] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3173.407409] Lustre: 67002:0:(ldlm_lib.c:2084:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 60, extend: 0 [ 3177.954208] Lustre: 23729:0:(ldlm_lib.c:2084:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 60, extend: 0 [ 3177.977035] LustreError: 79918:0:(ldlm_lib.c:2689:replay_request_or_update()) cfs_fail_timeout id 714 sleeping for 65000ms [ 3179.127865] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3189.867870] Lustre: DEBUG MARKER: oleg224-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3243.049732] LustreError: 79918:0:(ldlm_lib.c:2689:replay_request_or_update()) cfs_fail_timeout id 714 awake [ 3243.055614] Lustre: 79918:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 86a3aa69-cd3d-464d-9cd9-8d6daa91edd2@192.168.202.24@tcp [ 3243.084083] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 3243.090643] Lustre: 79918:0:(ldlm_lib.c:1913:abort_req_replay_queue()) @@@ aborted: req@ffff8c408647c000 x1873926020315136/t0(81604378629) o36->86a3aa69-cd3d-464d-9cd9-8d6daa91edd2@192.168.202.24@tcp:83/0 lens 528/0 e 7 to 0 dl 1787118303 ref 1 fl Complete:/204/ffffffff rc 0/-1 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 3243.105802] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 3243.114708] Lustre: 79918:0:(ldlm_lib.c:2084:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 60, extend: 1 [ 3243.134612] Lustre: lustre-MDT0000: Denying connection for new client 86a3aa69-cd3d-464d-9cd9-8d6daa91edd2 (at 192.168.202.24@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 1 evicted) already passed deadline 0:09 [ 3243.159067] Lustre: Skipped 21 previous similar messages [ 3243.254288] Lustre: 79918:0:(ldlm_lib.c:2393:target_recovery_overseer()) lustre-MDT0000 recovery is aborted by hard timeout [ 3243.259786] Lustre: 79918:0:(ldlm_lib.c:2403:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 3243.270546] Lustre: 79918:0:(ldlm_lib.c:2403:target_recovery_overseer()) Skipped 2 previous similar messages [ 3243.283472] Lustre: lustre-MDT0000-osd: cancel update llog [0x200001b70:0x1:0x0] [ 3243.305708] Lustre: lustre-MDT0001-osp-MDT0000: cancel update llog [0x240002b11:0x1:0x0] [ 3243.359990] Lustre: 79918:0:(ldlm_lib.c:2950:target_recovery_thread()) too long recovery - read logs [ 3243.374076] LustreError: dumping log to /tmp/lustre-log.1787118290.79918 [ 3243.595555] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1117 to 0x2c0000401:1633) [ 3243.598756] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1117 to 0x280000401:1633) [ 3247.696516] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 51 sec [ 3261.282778] Lustre: DEBUG MARKER: == replay-single test 120: DNE fail abort should stop both normal and DNE replay ========================================================== 01:45:05 (1787118305) [ 3269.219981] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3278.320414] Lustre: Failing over lustre-MDT0000 [ 3278.736582] Lustre: server umount lustre-MDT0000 complete [ 3294.364427] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3294.366590] LDISKFS-fs (dm-0): recovery complete [ 3294.376664] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3294.917971] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3294.933037] Lustre: Skipped 7 previous similar messages [ 3294.987205] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 3294.989846] Lustre: Skipped 7 previous similar messages [ 3295.003734] Lustre: lustre-MDT0000: Aborting client recovery [ 3295.014170] LustreError: 81878:0:(ldlm_lib.c:3003:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 3295.024653] Lustre: 81912:0:(ldlm_lib.c:2403:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 3295.038882] Lustre: 81912:0:(ldlm_lib.c:2403:target_recovery_overseer()) Skipped 1 previous similar message [ 3295.052380] LustreError: 81911:0:(lod_dev.c:511:lod_sub_recovery_thread()) lustre-MDT0001-osp-MDT0000: get update log duration 1, retries 0, failed: rc = -108 [ 3295.072450] Lustre: 81912:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 86a3aa69-cd3d-464d-9cd9-8d6daa91edd2@ [ 3295.086744] Lustre: lustre-MDT0000: disconnecting 2 stale clients [ 3295.115989] Lustre: lustre-MDT0000-osd: cancel update llog [0x200009870:0x3:0x0] [ 3295.144555] Lustre: lustre-MDT0001-osp-MDT0000: cancel update llog [0x2400090a2:0x1:0x0] [ 3295.226751] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1117 to 0x2c0000401:1665) [ 3295.232972] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1117 to 0x280000401:1665) [ 3300.333112] LustreError: lustre-MDT0000-osp-MDT0001: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 3302.484591] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3330.210985] Lustre: DEBUG MARKER: == replay-single test 121: lock replay timed out and race ========================================================== 01:46:12 (1787118372) [ 3335.329949] Lustre: Failing over lustre-MDT0000 [ 3336.342815] Lustre: server umount lustre-MDT0000 complete [ 3345.376295] Lustre: *** cfs_fail_loc=721, val=0*** [ 3345.381567] Lustre: Skipped 6 previous similar messages [ 3346.400400] Lustre: *** cfs_fail_loc=721, val=0*** [ 3350.151270] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3350.346836] Lustre: *** cfs_fail_loc=721, val=0*** [ 3350.352791] Lustre: Skipped 10 previous similar messages [ 3353.530326] Lustre: *** cfs_fail_loc=721, val=1*** [ 3353.531667] Lustre: Skipped 83 previous similar messages [ 3356.173136] Lustre: *** cfs_fail_loc=721, val=1*** [ 3356.178575] Lustre: Skipped 6 previous similar messages [ 3357.070891] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3360.737337] Lustre: *** cfs_fail_loc=721, val=1*** [ 3360.741260] Lustre: Skipped 32 previous similar messages [ 3368.710041] Lustre: lustre-MDT0000: Client 86a3aa69-cd3d-464d-9cd9-8d6daa91edd2 (at 192.168.202.24@tcp) reconnected, waiting for 2 clients in recovery for 0:53 [ 3368.739203] Lustre: *** cfs_fail_loc=721, val=1*** [ 3368.743095] Lustre: Skipped 34 previous similar messages [ 3385.093142] Lustre: *** cfs_fail_loc=721, val=1*** [ 3385.100442] Lustre: Skipped 52 previous similar messages [ 3385.124290] Lustre: lustre-MDT0000: Client 86a3aa69-cd3d-464d-9cd9-8d6daa91edd2 (at 192.168.202.24@tcp) reconnected, waiting for 2 clients in recovery for 0:37 [ 3386.337182] Lustre: 3637:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787118403/real 1787118403] req@ffff8c3f8aa54700 x1873926041225600/t0(0) o400->lustre-MDT0000-osp-MDT0001@0@lo:24/4 lens 224/224 e 0 to 1 dl 1787118433 ref 1 fl Rpc:XQr/2c0/ffffffff rc 0/-1 job:'ldlm_lock_repla.0' uid:0 gid:0 projid:4294967295 [ 3386.365260] Lustre: 3637:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 12 previous similar messages [ 3386.377753] Lustre: lustre-MDT0000: Received new MDS connection from 0@lo, keep former export from same NID [ 3386.395955] Lustre: *** cfs_fail_loc=721, val=1*** [ 3386.401926] Lustre: 83330:0:(tgt_handler.c:581:tgt_handle_recovery()) @@@ obsoleted, rq_xid=1873926020462080, exp_last_xid=1873926020463871 req@ffff8c3f899c0e00 x1873926020462080/t0(0) o101->86a3aa69-cd3d-464d-9cd9-8d6daa91edd2@192.168.202.24@tcp:0/0 lens 328/0 e 0 to 0 dl 1787118410 ref 1 fl Complete:/240/ffffffff rc 0/-1 job:'ldlm_lock_repla.0' uid:0 gid:0 projid:4294967295 [ 3400.459892] Lustre: lustre-MDT0000: Client 86a3aa69-cd3d-464d-9cd9-8d6daa91edd2 (at 192.168.202.24@tcp) reconnected, waiting for 2 clients in recovery for 0:22 [ 3416.544906] Lustre: lustre-MDT0000: Received new MDS connection from 0@lo, keep former export from same NID [ 3416.576297] Lustre: *** cfs_fail_loc=721, val=1*** [ 3416.579250] Lustre: 83330:0:(tgt_handler.c:581:tgt_handle_recovery()) @@@ obsoleted, rq_xid=1873926020461952, exp_last_xid=1873926020463871 req@ffff8c3f899c1180 x1873926020461952/t0(0) o101->86a3aa69-cd3d-464d-9cd9-8d6daa91edd2@192.168.202.24@tcp:0/0 lens 328/0 e 0 to 0 dl 1787118410 ref 1 fl Complete:/240/ffffffff rc 0/-1 job:'ldlm_lock_repla.0' uid:0 gid:0 projid:4294967295 [ 3416.844812] Lustre: lustre-MDT0000: Client 86a3aa69-cd3d-464d-9cd9-8d6daa91edd2 (at 192.168.202.24@tcp) reconnected, waiting for 2 clients in recovery for 0:20 [ 3417.569040] Lustre: *** cfs_fail_loc=721, val=1*** [ 3417.576430] Lustre: Skipped 130 previous similar messages [ 3433.218054] Lustre: lustre-MDT0000: Client 86a3aa69-cd3d-464d-9cd9-8d6daa91edd2 (at 192.168.202.24@tcp) reconnected, waiting for 2 clients in recovery for 0:04 [ 3446.752224] Lustre: lustre-MDT0000: Received new MDS connection from 0@lo, keep former export from same NID [ 3446.776689] Lustre: *** cfs_fail_loc=721, val=1*** [ 3446.799519] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 3448.602373] Lustre: lustre-MDT0000: Client 86a3aa69-cd3d-464d-9cd9-8d6daa91edd2 (at 192.168.202.24@tcp) reconnected, waiting for 2 clients in recovery for 0:28 [ 3464.967063] Lustre: lustre-MDT0000: Client 86a3aa69-cd3d-464d-9cd9-8d6daa91edd2 (at 192.168.202.24@tcp) reconnected, waiting for 2 clients in recovery for 0:12 [ 3476.959702] Lustre: lustre-MDT0000: Received new MDS connection from 0@lo, keep former export from same NID [ 3476.978683] Lustre: *** cfs_fail_loc=721, val=1*** [ 3482.080660] Lustre: *** cfs_fail_loc=721, val=1*** [ 3482.091978] Lustre: Skipped 254 previous similar messages [ 3496.701378] Lustre: lustre-MDT0000: Recovery already passed deadline 0:00. If you do not want to wait more, you may force taget eviction via 'lctl --device lustre-MDT0000 abort_recovery. [ 3507.168445] Lustre: lustre-MDT0000: Received new MDS connection from 0@lo, keep former export from same NID [ 3507.177552] Lustre: *** cfs_fail_loc=721, val=1*** [ 3507.180169] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 3507.188757] Lustre: 83330:0:(ldlm_lib.c:2084:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3507.200825] Lustre: 83330:0:(ldlm_lib.c:2084:extend_recovery_timer()) Skipped 20 previous similar messages [ 3513.120753] Lustre: lustre-MDT0000: Client 86a3aa69-cd3d-464d-9cd9-8d6daa91edd2 (at 192.168.202.24@tcp) reconnected, waiting for 2 clients in recovery for 0:19 [ 3513.139732] Lustre: Skipped 1 previous similar message [ 3537.377402] Lustre: lustre-MDT0000: Received new MDS connection from 0@lo, keep former export from same NID [ 3537.391134] Lustre: 83330:0:(ldlm_lib.c:2084:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3537.443503] Lustre: 83330:0:(ldlm_lib.c:2393:target_recovery_overseer()) lustre-MDT0000 recovery is aborted by hard timeout [ 3537.465700] Lustre: 83330:0:(ldlm_lib.c:2393:target_recovery_overseer()) Skipped 1 previous similar message [ 3537.474348] Lustre: 83330:0:(ldlm_lib.c:2403:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 3537.484269] Lustre: 83330:0:(ldlm_lib.c:2403:target_recovery_overseer()) Skipped 2 previous similar messages [ 3537.491516] Lustre: 83330:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 86a3aa69-cd3d-464d-9cd9-8d6daa91edd2@192.168.202.24@tcp [ 3537.498857] Lustre: 83330:0:(genops.c:1622:class_disconnect_stale_exports()) Skipped 1 previous similar message [ 3537.505604] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 3537.511786] LustreError: 83330:0:(ldlm_lib.c:1933:abort_lock_replay_queue()) @@@ aborted: req@ffff8c40b2684000 x1873926020468864/t0(0) o101->86a3aa69-cd3d-464d-9cd9-8d6daa91edd2@192.168.202.24@tcp:0/0 lens 328/0 e 0 to 0 dl 1787118458 ref 1 fl Complete:/240/ffffffff rc 0/-1 job:'ldlm_lock_repla.0' uid:0 gid:0 projid:4294967295 [ 3537.547061] Lustre: lustre-MDT0000-osd: cancel update llog [0x20000a040:0x1:0x0] [ 3537.576447] Lustre: lustre-MDT0001-osp-MDT0000: cancel update llog [0x2400090a3:0x1:0x0] [ 3537.605673] Lustre: 83330:0:(tgt_handler.c:581:tgt_handle_recovery()) @@@ obsoleted, rq_xid=1873926041280640, exp_last_xid=1873926041292415 req@ffff8c3f867d9f80 x1873926041280640/t0(0) o400->lustre-MDT0001-mdtlov_UUID@0@lo:0/0 lens 224/0 e 0 to 0 dl 1787118564 ref 1 fl Complete:/2c0/ffffffff rc 0/-1 job:'ptlrpcd_rcv.0' uid:0 gid:0 projid:4294967295 [ 3537.627940] Lustre: 83330:0:(ldlm_lib.c:2950:target_recovery_thread()) too long recovery - read logs [ 3537.634943] LustreError: dumping log to /tmp/lustre-log.1787118584.83330 [ 3537.735736] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1117 to 0x2c0000401:1697) [ 3537.741137] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1667 to 0x280000401:1697) [ 3538.401392] Lustre: lustre-MDT0000-osp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 3538.411937] Lustre: Skipped 28 previous similar messages [ 3557.506344] Lustre: DEBUG MARKER: == replay-single test 130a: DoM file create (setstripe) replay ========================================================== 01:50:01 (1787118601) [ 3568.071488] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3570.979696] Lustre: Failing over lustre-MDT0000 [ 3571.505445] Lustre: server umount lustre-MDT0000 complete [ 3573.221827] 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 [ 3573.228869] LustreError: 67002: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. [ 3573.245729] Lustre: Skipped 31 previous similar messages [ 3573.305177] LustreError: 67002:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 180 previous similar messages [ 3589.670939] LustreError: MGC192.168.202.124@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3589.691559] LustreError: Skipped 5 previous similar messages [ 3600.675713] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3600.683467] LDISKFS-fs (dm-0): recovery complete [ 3600.703394] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3614.178162] LustreError: 3637:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8c40b6ce7100 x1873926041325184/t0(0) o250->MGC192.168.202.124@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 [ 3620.063172] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1117 to 0x2c0000401:1729) [ 3620.072063] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1667 to 0x280000401:1729) [ 3620.360837] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3632.391965] Lustre: DEBUG MARKER: oleg224-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3634.582489] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3645.428464] Lustre: DEBUG MARKER: == replay-single test 130b: DoM file create (inherited) replay ========================================================== 01:51:29 (1787118689) [ 3655.710642] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3657.896366] Lustre: Failing over lustre-MDT0000 [ 3658.373615] Lustre: server umount lustre-MDT0000 complete [ 3685.969627] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3685.973860] LDISKFS-fs (dm-0): recovery complete [ 3685.998120] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3686.655259] Lustre: lustre-MDT0000: Not available for connect from 192.168.202.24@tcp (not set up) [ 3692.243645] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1117 to 0x2c0000401:1761) [ 3692.242143] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1667 to 0x280000401:1761) [ 3692.942610] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3704.686162] Lustre: DEBUG MARKER: oleg224-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3706.583647] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3717.035370] Lustre: DEBUG MARKER: == replay-single test 131a: DoM file write lock replay === 01:52:40 (1787118760) [ 3725.661449] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3727.615156] Lustre: Failing over lustre-MDT0000 [ 3727.835780] Lustre: server umount lustre-MDT0000 complete [ 3728.352294] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3728.364558] LustreError: Skipped 2 previous similar messages [ 3751.391779] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3751.396505] LDISKFS-fs (dm-0): recovery complete [ 3751.407228] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3756.526500] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xda71777cc6958af [ 3758.770932] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 3758.785291] Lustre: Skipped 4 previous similar messages [ 3762.284303] Lustre: lustre-MDT0000: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 3762.302247] Lustre: Skipped 4 previous similar messages [ 3762.355922] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1667 to 0x280000401:1793) [ 3762.357221] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1117 to 0x2c0000401:1793) [ 3762.901579] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3775.126229] Lustre: DEBUG MARKER: oleg224-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3777.443141] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3787.466981] Lustre: DEBUG MARKER: SKIP: replay-single test_131b skipping excluded test 131b [ 3789.527442] Lustre: DEBUG MARKER: == replay-single test 132a: PFL new component instantiate replay ========================================================== 01:53:53 (1787118833) [ 3799.091383] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3802.215848] Lustre: Failing over lustre-MDT0000 [ 3802.588581] Lustre: server umount lustre-MDT0000 complete [ 3825.815566] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3825.816801] LDISKFS-fs (dm-0): recovery complete [ 3825.824718] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3829.735365] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xda71777cc695eba [ 3835.484285] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1796 to 0x280000401:1825) [ 3835.484305] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1795 to 0x2c0000401:1825) [ 3835.575849] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3846.919476] Lustre: DEBUG MARKER: oleg224-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3848.937887] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3857.457452] Lustre: DEBUG MARKER: == replay-single test 133: check resend of ongoing requests for lwp during failover ========================================================== 01:55:01 (1787118901) [ 3862.497914] Lustre: *** cfs_fail_loc=123, val=2147483648*** [ 3862.503477] Lustre: Skipped 270 previous similar messages [ 3865.560463] Lustre: Failing over lustre-MDT0000 [ 3865.836745] Lustre: server umount lustre-MDT0000 complete [ 3878.666895] Lustre: lustre-MDT0001: Client f53a6088-2482-4f76-a0a7-54a347b1b769 (at 192.168.202.24@tcp) reconnecting [ 3885.480276] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3898.203619] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3898.398456] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000300000400-0x0000000340000400]:1:mdt [ 3898.420425] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000300000400-0x0000000340000400]:1:mdt] [ 3898.475564] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1796 to 0x280000401:1857) [ 3898.476113] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1795 to 0x2c0000401:1857) [ 3907.164193] Lustre: DEBUG MARKER: == replay-single test 134: replay creation of a file created in a pool ========================================================== 01:55:51 (1787118951) [ 3924.322459] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3926.649330] Lustre: Failing over lustre-MDT0000 [ 3927.046850] Lustre: server umount lustre-MDT0000 complete [ 3950.529283] LDISKFS-fs (dm-0): 4 truncates cleaned up [ 3950.531498] LDISKFS-fs (dm-0): recovery complete [ 3950.546968] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3956.703824] LustreError: 94369:0:(import.c:339:ptlrpc_invalidate_import()) MGS: timeout waiting for callback (1 != 0) [ 3956.710338] LustreError: 3637:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8c40b2686680 x1873926041539328/t0(0) o250->MGC192.168.202.124@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 [ 3956.770361] LustreError: 3637:0:(client.c:1391:ptlrpc_import_delay_req()) Skipped 7 previous similar messages [ 3956.807854] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xda71777cc696da8 [ 3957.095462] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3957.099135] Lustre: Skipped 6 previous similar messages [ 3957.143672] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 3957.146391] Lustre: Skipped 8 previous similar messages [ 3962.180469] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3962.455282] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1795 to 0x2c0000401:1889) [ 3962.468288] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1796 to 0x280000401:1889) [ 3972.225257] Lustre: DEBUG MARKER: oleg224-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3973.747512] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3991.152853] Lustre: DEBUG MARKER: == replay-single test 135: Server failure in lock replay phase ========================================================== 01:57:15 (1787119035) [ 4001.292243] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 4003.501620] Lustre: Failing over lustre-OST0000 [ 4003.729900] Lustre: server umount lustre-OST0000 complete [ 4010.683206] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing load_module ../libcfs/libcfs/libcfs [ 4022.233532] LDISKFS-fs (dm-2): 3 truncates cleaned up [ 4022.239636] LDISKFS-fs (dm-2): recovery complete [ 4022.260868] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4024.363011] Lustre: *** cfs_fail_loc=32d, val=20*** [ 4024.367862] Lustre: Skipped 1 previous similar message [ 4028.246803] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4035.380750] Lustre: DEBUG MARKER: oleg224-client.virtnet: executing wait_import_state_mount REPLAY_LOCKS osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 4037.000954] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in REPLAY_LOCKS state after 0 sec [ 4038.836652] Lustre: Failing over lustre-OST0000 [ 4038.841559] LustreError: 97737:0:(ldlm_lib.c:3003:target_stop_recovery_thread()) lustre-OST0000: Aborting recovery [ 4038.846577] Lustre: 96959:0:(ldlm_lib.c:2403:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 4038.851254] LustreError: 96959:0:(ofd_obd.c:1324:ofd_iocontrol()) lustre-OST0000: iocontrol from 'tgt_recover_0' cmd=c00866c1 _IOWR('f', 193, 8) unrecognized: rc = -25 [ 4039.022444] Lustre: server umount lustre-OST0000 complete [ 4057.348411] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing load_module ../libcfs/libcfs/libcfs [ 4060.639385] Lustre: 3637:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787119071/real 1787119071] req@ffff8c40a5259180 x1873926041601664/t0(0) o400->lustre-OST0000-osc-MDT0001@0@lo:28/4 lens 224/224 e 1 to 1 dl 1787119107 ref 1 fl Rpc:XQr/2c0/ffffffff rc 0/-1 job:'ldlm_lock_repla.0' uid:0 gid:0 projid:4294967295 [ 4060.677891] Lustre: 3637:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 11 previous similar messages [ 4066.363326] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4074.240061] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4079.078889] Lustre: lustre-OST0000: Not available for connect from 0@lo (stopping) [ 4079.100440] Lustre: Skipped 1 previous similar message [ 4081.942385] Lustre: lustre-OST0000: Not available for connect from 192.168.202.24@tcp (stopping) [ 4085.046494] Lustre: server umount lustre-OST0000 complete [ 4090.848682] Lustre: lustre-OST0001: Not available for connect from 0@lo (stopping) [ 4090.856649] Lustre: Skipped 2 previous similar messages [ 4094.900368] Lustre: server umount lustre-OST0001 complete [ 4103.915655] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4111.659806] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4121.314058] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4122.531792] LustreError: lustre-OST0000-osc-MDT0001: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 4122.549389] LustreError: lustre-OST0001-osc-MDT0001: This client was evicted by lustre-OST0001; in progress operations using this service will fail. [ 4122.577850] LustreError: lustre-OST0000-osc-MDT0000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 4122.595830] LustreError: lustre-OST0001-osc-MDT0000: This client was evicted by lustre-OST0001; in progress operations using this service will fail. [ 4128.955411] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4141.793350] Lustre: DEBUG MARKER: == replay-single test 136: MDS to disconnect all OSPs first, then cleanup ldlm ========================================================== 01:59:45 (1787119185) [ 4143.506939] Lustre: DEBUG MARKER: SKIP: replay-single test_136 needs > 2 MDTs [ 4145.292410] Lustre: DEBUG MARKER: == replay-single test 137a: DNE: create under striped dir, fail MDT1 ========================================================== 01:59:49 (1787119189) [ 4153.475785] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4155.684758] Lustre: Failing over lustre-MDT0000 [ 4156.029255] Lustre: server umount lustre-MDT0000 complete [ 4173.795648] LustreError: 100194: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. [ 4173.809189] LustreError: 100194:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 266 previous similar messages [ 4179.651707] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 4179.655801] LDISKFS-fs (dm-0): recovery complete [ 4179.673875] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4184.039025] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xda71777cc698820 [ 4184.066632] Lustre: MGC192.168.202.124@tcp: Connection restored to 0@lo (at 0@lo) [ 4184.074358] Lustre: Skipped 33 previous similar messages [ 4189.883589] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1795 to 0x2c0000401:1921) [ 4189.885301] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1911 to 0x280000401:1953) [ 4190.396048] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4200.364693] Lustre: DEBUG MARKER: oleg224-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4202.255812] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4211.973888] Lustre: DEBUG MARKER: == replay-single test 137b: DNE: create under striped dir, fail MDT2 ========================================================== 02:00:56 (1787119256) [ 4219.996853] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 4222.088160] Lustre: Failing over lustre-MDT0001 [ 4222.220985] Lustre: lustre-MDT0001: Not available for connect from 192.168.202.24@tcp (stopping) [ 4222.226336] Lustre: Skipped 3 previous similar messages [ 4222.416963] Lustre: server umount lustre-MDT0001 complete [ 4225.509114] Lustre: lustre-MDT0001-lwp-OST0001: Connection to lustre-MDT0001 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 4225.533311] Lustre: Skipped 33 previous similar messages [ 4246.439069] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 4246.443306] LDISKFS-fs (dm-1): recovery complete [ 4246.475097] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4252.335480] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:209 to 0x280000400:609) [ 4252.342522] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:581 to 0x2c0000400:609) [ 4253.231337] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4264.248915] Lustre: DEBUG MARKER: oleg224-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 4266.120842] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4276.825634] Lustre: DEBUG MARKER: == replay-single test 137c: DNE: create under striped dir, fail MDT1/MDT2 ========================================================== 02:02:01 (1787119321) [ 4285.169893] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4293.781133] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 4296.601545] Lustre: Failing over lustre-MDT0001 [ 4296.899608] Lustre: server umount lustre-MDT0001 complete [ 4300.843532] Lustre: Failing over lustre-MDT0000 [ 4301.390682] Lustre: server umount lustre-MDT0000 complete [ 4319.521536] LustreError: MGC192.168.202.124@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4319.553843] LustreError: Skipped 6 previous similar messages [ 4328.250724] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 4328.252221] LDISKFS-fs (dm-0): recovery complete [ 4328.263446] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4328.284261] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 4328.287786] LDISKFS-fs (dm-1): recovery complete [ 4328.328696] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4329.439128] LustreError: 107277:0:(import.c:339:ptlrpc_invalidate_import()) MGS: timeout waiting for callback (1 != 0) [ 4329.456475] LustreError: 107277:0:(import.c:363:ptlrpc_invalidate_import()) @@@ still on sending list req@ffff8c3f8a0a0a80 x1873926041773056/t0(0) o250->MGC192.168.202.124@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 1787119376 ref 1 fl Rpc:NQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4329.472299] LustreError: 107277:0:(import.c:373:ptlrpc_invalidate_import()) MGS: Unregistering RPCs found (0). Network is sluggish? Waiting for them to error out. [ 4329.894932] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xda71777cc69973f [ 4330.664176] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_connect to node 0@lo failed: rc = -114 [ 4330.669786] LustreError: Skipped 9 previous similar messages [ 4335.248975] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4335.774221] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4339.152606] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:581 to 0x2c0000400:641) [ 4339.153168] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:209 to 0x280000400:641) [ 4345.356110] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1911 to 0x280000401:1985) [ 4345.356632] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1795 to 0x2c0000401:1953) [ 4351.574126] Lustre: DEBUG MARKER: oleg224-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 4353.250074] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4355.034914] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4365.842945] Lustre: DEBUG MARKER: == replay-single test 200: Dropping one OBD_PING should not cause disconnect ========================================================== 02:03:29 (1787119409) [ 4367.471963] Lustre: DEBUG MARKER: SKIP: replay-single test_200 Need remote client [ 4369.107888] Lustre: DEBUG MARKER: == replay-single test 201: MDT umount cascading disconnects timeouts ========================================================== 02:03:33 (1787119413) [ 4373.207287] LustreError: 107298:0:(tgt_handler.c:1143:tgt_disconnect()) cfs_fail_timeout id 245 sleeping for 8000ms [ 4376.313841] LustreError: 101045:0:(tgt_handler.c:1143:tgt_disconnect()) cfs_fail_timeout id 245 sleeping for 8000ms [ 4376.319335] LustreError: 101045:0:(tgt_handler.c:1143:tgt_disconnect()) Skipped 1 previous similar message [ 4381.239468] LustreError: 107298:0:(tgt_handler.c:1143:tgt_disconnect()) cfs_fail_timeout id 245 awake [ 4381.247907] Lustre: Failing over lustre-MDT0001 [ 4381.261115] LustreError: 100772:0:(tgt_handler.c:1143:tgt_disconnect()) cfs_fail_timeout id 245 sleeping for 8000ms [ 4381.268014] LustreError: 100772:0:(tgt_handler.c:1143:tgt_disconnect()) Skipped 2 previous similar messages [ 4381.467893] Lustre: lustre-MDT0001: Not available for connect from 192.168.202.24@tcp (stopping) [ 4384.343146] LustreError: 99662:0:(tgt_handler.c:1143:tgt_disconnect()) cfs_fail_timeout id 245 awake [ 4389.279182] LustreError: 108509:0:(tgt_handler.c:1143:tgt_disconnect()) cfs_fail_timeout id 245 awake [ 4389.283204] LustreError: 108509:0:(tgt_handler.c:1143:tgt_disconnect()) Skipped 1 previous similar message [ 4389.363812] Lustre: server umount lustre-MDT0001 complete [ 4397.552844] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4399.886996] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4399.895287] Lustre: Skipped 9 previous similar messages [ 4401.968419] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4403.177912] Lustre: lustre-MDT0001: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 4403.184422] Lustre: Skipped 9 previous similar messages [ 4403.228121] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:209 to 0x280000400:673) [ 4403.228266] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:581 to 0x2c0000400:673) [ 4411.212328] Lustre: DEBUG MARKER: == replay-single test 202: pfl replay should recovery layout generation ========================================================== 02:04:15 (1787119455) [ 4420.791738] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4422.806062] Lustre: Failing over lustre-MDT0000 [ 4422.982437] Lustre: server umount lustre-MDT0000 complete [ 4445.847128] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 4445.849329] LDISKFS-fs (dm-0): recovery complete [ 4445.856686] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4455.015513] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4456.134335] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1955 to 0x2c0000401:1985) [ 4456.137961] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1911 to 0x280000401:2017) [ 4464.205607] Lustre: DEBUG MARKER: oleg224-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4466.233586] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4476.242662] Lustre: DEBUG MARKER: == replay-single test 203: resend can hit original request ========================================================== 02:05:20 (1787119520) [ 4477.944164] LustreError: 107297:0:(mdt_handler.c:2126:mdt_getattr_name_lock()) cfs_fail_timeout id 2403 sleeping for 2000ms [ 4480.039205] LustreError: 107297:0:(mdt_handler.c:2126:mdt_getattr_name_lock()) cfs_fail_timeout id 2403 awake [ 4480.046079] LustreError: 107297:0:(mdt_handler.c:2126:mdt_getattr_name_lock()) Skipped 1 previous similar message [ 4480.060222] Lustre: 107297:0:(service.c:2628:ptlrpc_server_handle_request()) @@@ pause req after reply req@ffff8c3f89ac6d80 x1873926020781824/t0(0) o101->f53a6088-2482-4f76-a0a7-54a347b1b769@192.168.202.24@tcp:599/0 lens 592/1888 e 0 to 0 dl 1787119574 ref 1 fl Complete:/600/0 rc 0/0 job:'stat.0' uid:0 gid:0 projid:0 [ 4483.104247] Lustre: 107297:0:(service.c:2630:ptlrpc_server_handle_request()) @@@ continue req@ffff8c3f89ac6d80 x1873926020781824/t0(0) o101->f53a6088-2482-4f76-a0a7-54a347b1b769@192.168.202.24@tcp:599/0 lens 592/1888 e 0 to 0 dl 1787119574 ref 1 fl Complete:/600/0 rc 0/0 job:'stat.0' uid:0 gid:0 projid:0 [ 4491.868477] Lustre: DEBUG MARKER: == replay-single test complete, duration 4193 sec ======== 02:05:36 (1787119536) [ 4493.373980] Lustre: DEBUG MARKER: === replay-single: start cleanup 02:05:37 (1787119537) === [ 4501.795229] Lustre: DEBUG MARKER: === replay-single: finish cleanup 02:05:45 (1787119545) === [ 4507.107640] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4507.112828] Lustre: Skipped 4 previous similar messages [ 4508.634942] Lustre: server umount lustre-MDT0000 complete [ 4515.811133] LustreError: 9527:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787119562 with bad export cookie 983780846901765271 [ 4515.826808] LustreError: 9527:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 4516.162152] Lustre: server umount lustre-MDT0001 complete [ 4533.224586] Lustre: server umount lustre-OST0000 complete [ 4552.269241] Lustre: server umount lustre-OST0001 complete [ 4571.422137] Lustre: DEBUG MARKER: oleg224-server.virtnet: executing unload_modules_local [ 4574.465356] Key type lgssc unregistered [ 4574.858661] LNet: 114583:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 4574.864852] LNetError: 114583:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 4574.880620] LNet: Removed LNI 192.168.202.124@tcp [ 4575.866244] Key type .llcrypt unregistered [ 4575.869715] Key type ._llcrypt unregistered