[ 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 626154550 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.001012] APIC: Switch to symmetric I/O mode setup [ 0.002319] x2apic enabled [ 0.003008] Switched APIC routing to physical x2apic. [ 0.004014] kvm-guest: setup PV IPIs [ 0.006785] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.007000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.007033] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.008016] pid_max: default: 32768 minimum: 301 [ 0.009151] LSM: Security Framework initializing [ 0.010052] Yama: becoming mindful. [ 0.011031] SELinux: Initializing. [ 0.012082] *** VALIDATE selinux *** [ 0.021902] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.027331] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.028185] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.030072] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.031204] *** VALIDATE tmpfs *** [ 0.033359] *** VALIDATE proc *** [ 0.035112] *** VALIDATE cgroup *** [ 0.036008] *** VALIDATE cgroup2 *** [ 0.037394] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.038182] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.039009] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.040044] Spectre V2 : User space: Vulnerable [ 0.041008] Speculative Store Bypass: Vulnerable [ 0.044439] debug: unmapping init [mem 0xffffffff9c859000-0xffffffff9c860fff] [ 0.046255] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.047815] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.048021] ... version: 2 [ 0.049017] ... bit width: 48 [ 0.050007] ... generic registers: 4 [ 0.051011] ... value mask: 0000ffffffffffff [ 0.052010] ... max period: 00007fffffffffff [ 0.053013] ... fixed-purpose events: 3 [ 0.054008] ... event mask: 000000070000000f [ 0.055365] rcu: Hierarchical SRCU implementation. [ 0.057540] smp: Bringing up secondary CPUs ... [ 0.058717] x86: Booting SMP configuration: [ 0.059026] .... node #0, CPUs: #1 #2 #3 [ 0.065111] smp: Brought up 1 node, 4 CPUs [ 0.067023] smpboot: Max logical packages: 1 [ 0.068011] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.137472] node 0 deferred pages initialised in 66ms [ 0.146031] devtmpfs: initialized [ 0.147149] x86/mm: Memory block size: 128MB [ 0.159432] gcov: version magic: 0x41383552 [ 0.165415] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.175124] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.179401] pinctrl core: initialized pinctrl subsystem [ 0.182384] [ 0.182940] ************************************************************* [ 0.186011] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.190010] ** ** [ 0.192011] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.195011] ** ** [ 0.198016] ** This means that this kernel is built to expose internal ** [ 0.205014] ** IOMMU data structures, which may compromise security on ** [ 0.208026] ** your system. ** [ 0.213024] ** ** [ 0.216018] ** If you see this message and you are not debugging the ** [ 0.218021] ** kernel, report this immediately to your vendor! ** [ 0.221017] ** ** [ 0.326028] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.327023] ************************************************************* [ 0.329000] NET: Registered protocol family 16 [ 0.332711] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.336144] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.339073] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.342707] cpuidle: using governor menu [ 0.345296] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.347474] PCI: Using configuration type 1 for base access [ 0.349163] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.356120] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.357024] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.360587] cryptd: max_cpu_qlen set to 1000 [ 0.362241] ACPI: Added _OSI(Module Device) [ 0.363073] ACPI: Added _OSI(Processor Device) [ 0.364000] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.365033] ACPI: Added _OSI(Processor Aggregator Device) [ 0.371243] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.379174] ACPI: Interpreter enabled [ 0.381067] ACPI: PM: (supports S0 S3 S4 S5) [ 0.382017] ACPI: Using IOAPIC for interrupt routing [ 0.384220] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.388599] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.407043] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.411047] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.414023] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.418363] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.432221] acpiphp: Slot [2] registered [ 0.440026] acpiphp: Slot [5] registered [ 0.445098] acpiphp: Slot [6] registered [ 0.446229] acpiphp: Slot [7] registered [ 0.448085] acpiphp: Slot [8] registered [ 0.449000] acpiphp: Slot [9] registered [ 0.449000] acpiphp: Slot [10] registered [ 0.451090] acpiphp: Slot [3] registered [ 0.452071] acpiphp: Slot [4] registered [ 0.454222] acpiphp: Slot [11] registered [ 0.455188] acpiphp: Slot [12] registered [ 0.457081] acpiphp: Slot [13] registered [ 0.458088] acpiphp: Slot [14] registered [ 0.460111] acpiphp: Slot [15] registered [ 0.461086] acpiphp: Slot [16] registered [ 0.462081] acpiphp: Slot [17] registered [ 0.464075] acpiphp: Slot [18] registered [ 0.465089] acpiphp: Slot [19] registered [ 0.467084] acpiphp: Slot [20] registered [ 0.469113] acpiphp: Slot [21] registered [ 0.470103] acpiphp: Slot [22] registered [ 0.472106] acpiphp: Slot [23] registered [ 0.473095] acpiphp: Slot [24] registered [ 0.475244] acpiphp: Slot [25] registered [ 0.477089] acpiphp: Slot [26] registered [ 0.478126] acpiphp: Slot [27] registered [ 0.479150] acpiphp: Slot [28] registered [ 0.481124] acpiphp: Slot [29] registered [ 0.482135] acpiphp: Slot [30] registered [ 0.484169] acpiphp: Slot [31] registered [ 0.485147] PCI host bridge to bus 0000:00 [ 0.487024] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.489028] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.492035] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.495027] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.497032] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.500035] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.502187] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.505236] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.509694] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.522907] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.529734] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.532019] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.535020] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.538019] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.541773] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.544934] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.547040] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.550975] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.556014] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.571027] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.576020] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.583000] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.604022] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.616028] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.643022] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.645000] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.712027] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.718024] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.732007] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.743376] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.750033] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.757022] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.771019] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.785677] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.790014] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.795015] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.813017] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.825083] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.831017] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.837021] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.847022] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 0.860400] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.873021] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.888062] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.924026] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 0.946435] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.950989] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.955720] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.959174] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.964351] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.971094] iommu: Default domain type: Passthrough [ 0.980155] SCSI subsystem initialized [ 0.983277] ACPI: bus type USB registered [ 0.989126] usbcore: registered new interface driver usbfs [ 0.993146] usbcore: registered new interface driver hub [ 0.996093] usbcore: registered new device driver usb [ 0.999194] pps_core: LinuxPPS API ver. 1 registered [ 1.001010] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 1.006061] PTP clock support registered [ 1.009223] EDAC MC: Ver: 3.0.0 [ 1.038271] PCI: Using ACPI for IRQ routing [ 1.041240] NetLabel: Initializing [ 1.043013] NetLabel: domain hash size = 128 [ 1.045011] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 1.048077] NetLabel: unlabeled traffic allowed by default [ 1.051470] vgaarb: loaded [ 1.053714] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 1.055025] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 1.063764] clocksource: Switched to clocksource kvm-clock [ 1.266861] VFS: Disk quotas dquot_6.6.0 [ 1.268309] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 1.271027] *** VALIDATE ramfs *** [ 1.272145] *** VALIDATE hugetlbfs *** [ 1.273625] pnp: PnP ACPI init [ 1.276055] pnp: PnP ACPI: found 6 devices [ 1.303817] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 1.311061] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 1.316053] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 1.320259] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 1.322327] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 1.325257] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 1.328347] NET: Registered protocol family 2 [ 1.331151] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 1.336617] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 1.340044] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 1.345478] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 1.349843] TCP: Hash tables configured (established 65536 bind 65536) [ 1.353542] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 1.358455] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 1.361843] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 1.365326] NET: Registered protocol family 1 [ 1.368955] RPC: Registered named UNIX socket transport module. [ 1.370136] RPC: Registered udp transport module. [ 1.371116] RPC: Registered tcp transport module. [ 1.373101] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 1.375303] NET: Registered protocol family 44 [ 1.377137] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 1.378892] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 1.380969] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 1.382903] PCI: CLS 0 bytes, default 64 [ 1.384829] Unpacking initramfs... [ 3.096704] debug: unmapping init [mem 0xffff9104fcc54000-0xffff9104fffbffff] [ 3.151928] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 3.153657] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 3.156971] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 3.796667] Initialise system trusted keyrings [ 3.798902] Key type blacklist registered [ 3.801558] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 3.814994] zbud: loaded [ 3.817635] *** VALIDATE nfs *** [ 3.818708] *** VALIDATE nfs4 *** [ 3.820104] pstore: using deflate compression [ 3.823847] Platform Keyring initialized [ 3.959152] NET: Registered protocol family 38 [ 4.011333] Key type asymmetric registered [ 4.015317] Asymmetric key parser 'x509' registered [ 4.018487] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 4.022868] io scheduler mq-deadline registered [ 4.025387] io scheduler kyber registered [ 4.027941] io scheduler bfq registered [ 4.030834] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 4.034820] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 4.038466] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 4.042186] ACPI: Power Button [PWRF] [ 4.047752] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 4.055103] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 4.074794] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 4.086207] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 4.103887] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 4.134811] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 4.166601] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 4.172362] Non-volatile memory driver v1.3 [ 4.174271] Linux agpgart interface v0.103 [ 4.208259] virtio_blk virtio1: [vda] 146744 512-byte logical blocks (75.1 MB/71.7 MiB) [ 4.211865] vda: detected capacity change from 0 to 75132928 [ 4.226916] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 4.229803] vdb: detected capacity change from 0 to 1073741824 [ 4.244322] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 4.248853] vdc: detected capacity change from 0 to 2621440000 [ 4.291569] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 4.293923] vdd: detected capacity change from 0 to 2621440000 [ 4.321810] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 4.324112] vde: detected capacity change from 0 to 4294967296 [ 4.337337] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 4.340336] vdf: detected capacity change from 0 to 4294967296 [ 4.347613] libphy: Fixed MDIO Bus: probed [ 4.354282] usbcore: registered new interface driver usbserial_generic [ 4.357440] usbserial: USB Serial support registered for generic [ 4.359987] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 4.365529] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 4.367809] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 4.370836] mousedev: PS/2 mouse device common for all mice [ 4.375354] rtc_cmos 00:05: RTC can wake from S4 [ 4.378698] rtc_cmos 00:05: registered as rtc0 [ 4.381374] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 4.385468] intel_pstate: CPU model not supported [ 4.389877] hid: raw HID events driver (C) Jiri Kosina [ 4.391782] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 4.394201] usbcore: registered new interface driver usbhid [ 4.406464] usbhid: USB HID core driver [ 4.411272] drop_monitor: Initializing network drop monitor service [ 4.411545] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 4.418906] Initializing XFRM netlink socket [ 4.423279] NET: Registered protocol family 10 [ 4.426922] Segment Routing with IPv6 [ 4.428395] NET: Registered protocol family 17 [ 4.431176] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 4.432801] mpls_gso: MPLS GSO support [ 4.442169] RAS: Correctable Errors collector initialized. [ 4.444819] AVX version of gcm_enc/dec engaged. [ 4.446443] AES CTR mode by8 optimization enabled [ 4.543830] sched_clock: Marking stable (4543756484, 0)->(5830176432, -1286419948) [ 4.549185] registered taskstats version 1 [ 4.551370] Loading compiled-in X.509 certificates [ 4.553751] zswap: loaded using pool lzo/zbud [ 4.591612] Key type big_key registered [ 4.605827] Key type encrypted registered [ 4.608174] ima: No TPM chip found, activating TPM-bypass! [ 4.613867] ima: Allocated hash algorithm: sha1 [ 4.616189] ima: No architecture policies found [ 4.619280] evm: Initialising EVM extended attributes: [ 4.621435] evm: security.selinux [ 4.622516] evm: security.ima [ 4.623409] evm: security.capability [ 4.624881] evm: HMAC attrs: 0x1 [ 4.627552] rtc_cmos 00:05: setting system clock to 2026-09-08 23:02:54 UTC (1788908574) [ 4.637804] debug: unmapping init [mem 0xffffffff9d803000-0xffffffff9d9fffff] [ 4.641702] debug: unmapping init [mem 0xffffffff9c582000-0xffffffff9c858fff] [ 4.651099] Write protecting the kernel read-only data: 28672k [ 4.654402] debug: unmapping init [mem 0xffffffff9ac03000-0xffffffff9adfffff] [ 4.657135] debug: unmapping init [mem 0xffffffff9b514000-0xffffffff9b5fffff] [ 4.699802] 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) [ 4.707288] systemd[1]: Detected virtualization kvm. [ 4.708894] systemd[1]: Detected architecture x86-64. [ 4.710779] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 4.746935] systemd[1]: No hostname configured. [ 4.748725] systemd[1]: Set hostname to . [ 4.750729] random: systemd: uninitialized urandom read (16 bytes read) [ 4.752990] systemd[1]: Initializing machine ID from random generator. [ 4.877476] random: ln: uninitialized urandom read (6 bytes read) [ 5.005983] random: systemd: uninitialized urandom read (16 bytes read) [ 5.009755] systemd[1]: Listening on Journal Socket (/dev/log). [ OK ] Listening on Journal Socket (/dev/log). [ 5.023145] systemd[1]: Reached target Slices. [ OK ] Reached target Slices. [ 5.033770] systemd[1]: Reached target Timers. [ OK ] Reached target Timers. [ OK ] Reached target Swap. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. [ OK ] Reached target Initrd Root Device. [ OK ] Listening on udev Kernel Socket. [ OK ] Listening on Journal Socket. Starting Journal Service... Starting Setup Virtual Console... [ OK ] Started Memstrack Anylazing Service. [ OK ] Listening on udev Control Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Local File Systems. Starting Create Volatile Files and Directories... Starting Apply Kernel Variables... Starting Create list of required st…ce nodes for the current kernel... [ OK ] Started Setup Virtual Console. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Apply Kernel Variables. [ 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... [ 6.522711] device-mapper: uevent: version 1.0.3 [ 6.525307] device-mapper: ioctl: 4.46.0-ioctl (2022-02-22) initialised: dm-devel@redhat.com [ OK ] Started dracut pre-udev hook. Starting udev Kernel Device Manager... [ OK ] Started udev Kernel Device Manager. Starting dracut pre-trigger hook... [ OK ] Started dracut pre-trigger hook. Starting udev Coldplug all Devices... Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. Starting dracut initqueue hook... [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ 8.049358] random: fast init done [ 8.386602] virtio_net virtio0 ens2: renamed from eth0 [ 8.405152] scsi host0: ata_piix [ 8.512195] scsi host1: ata_piix [ 8.514366] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 8.517800] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 13.155334] random: crng init done [ 13.158511] random: 7 urandom warning(s) missed due to ratelimiting [ 17.222571] dracut-initqueue[584]: RTNETLINK answers: File exists Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Mounting /sysroot... [ 19.955384] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped target Timers. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Sockets. [ OK ] Stopped target System Initialization. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. [ OK ] Stopped target Swap. [ 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 Apply Kernel Variables. [ OK ] Stopped target Paths. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped target Slices. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Closed udev Kernel Socket. [ OK ] Closed udev Control Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 23.069779] printk: systemd: 26 output lines suppressed due to ratelimiting [ 23.741970] SELinux: Disabled at runtime. [ 23.840857] 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) [ 23.860616] systemd[1]: Detected virtualization kvm. [ 23.864376] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 26.980104] systemd[1]: initrd-switch-root.service: Succeeded. [ 26.992506] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 27.025215] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 27.031321] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 27.035655] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 27.075808] systemd[1]: Starting Journal Service... Starting Journal Service... [ 27.099626] systemd[1]: Created slice system-serial\x2dgetty.slice. [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Listening on Process Core Dump Socket. Mounting Kernel Debug File System... [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd Root File System. [ OK ] Stopped target Initrd File Systems. Mounting Huge Pages File System... [ OK ] Created slice system-getty.slice. [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Listening on udev Kernel Socket. Starting Remount Root and Kernel File Systems... Mounting POSIX Message Queue File System... [ OK ] Started Forward Password Requests to Wall Directory Watch. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Listening on udev Control Socket. [ OK ] Reached target rpc_pipefs.target. Starting udev Coldplug all Devices... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Reached target RPC Port Mapper. Starting Apply Kernel Variables... Activating swap /dev/disk/by-label/SWAP... [ OK ] Created slice User and Session Slice. [ OK ] Reached target Slices. [ 27.757208] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS [ OK ] Started Journal Service. [ OK ] Mounted Kernel Debug File System. [ OK ] Mounted Huge Pages File System. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Apply Kernel Variables. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Reached target Swap. Starting Configure read-only root support... Starting Create Static Device Nodes in /dev... Starting Flush Journal to Persistent Storage... [ OK ] Started udev Coldplug all Devices. [ 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. [ 28.683136] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 29.646427] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 29.858814] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 30.577487] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 30.745761] EDAC sbridge: Ver: 1.1.2 [* ] A start job is running for Configur…-only root support (7s / no limit) [** ] A start job is running for Configur…-only root support (8s / no limit) [*** ] A start job is running for Configur…-only root support (8s / no limit) [ *** ] A start job is running for Configur…-only root support (9s / no limit) [ *** ] A start job is running for Configur…-only root support (9s / no limit) [ ***] A start job is running for Configur…only root support (10s / no limit)[ 37.258759] Key type dns_resolver registered [ **] A start job is running for Configur…only root support (10s / no limit) [ *] A start job is running for Configur…only root support (11s / no limit)[ 38.525413] NFS: Registering the id_resolver key type [ 38.532592] Key type id_resolver registered [ 38.539387] Key type id_legacy registered [ **] A start job is running for Configur…only root support (11s / no limit) [ ***] A start job is running for Configur…only root support (12s / no limit) [ OK ] Started Configure read-only root support. [ OK ] Reached target Local File Systems. Starting Rebuild Dynamic Linker Cache... Starting Mark the need to relabel after reboot... Starting Load/Save Random Seed... Starting Create Volatile Files and Directories... [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Load/Save Random Seed. [ 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 ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Reached target Timers. Starting Restore /run/initramfs on shutdown... [ OK ] Started D-Bus System Message Bus. Starting Network Manager... [ OK ] Started irqbalance daemon. Starting Login Service... [ OK ] Reached target sshd-keygen.target. [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Network Manager. [ OK ] Reached target Network. Starting Dynamic System Tuning Daemon... Starting OpenSSH server daemon... Starting GSSAPI Proxy Daemon... Starting Network Manager Wait Online... [ OK ] Started Login Service. Starting Hostname Service... [ OK ] Started OpenSSH server daemon. [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... [ OK ] Started Permit User Sessions. [ OK ] Started Getty on tty1. [ OK ] Started Command Scheduler. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Serial Getty on ttyS1. [ OK ] Reached target Login Prompts. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting 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. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg213-server login: [ 74.851568] hrtimer: interrupt took 12846860 ns [ 99.007466] libcfs: loading out-of-tree module taints kernel. [ 99.041295] Key type ._llcrypt registered [ 99.043382] Key type .llcrypt registered [ 99.119187] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_hostid [ 111.729824] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing load_modules_local [ 112.761369] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 112.770021] alg: No test for adler32 (adler32-zlib) [ 113.937425] Lustre: Lustre: Build Version: 2.17.57_86_g8205644 [ 114.478428] LNet: Added LNI 192.168.202.113@tcp [8/256/0/180] [ 116.152670] Key type lgssc registered [ 117.336380] Lustre: Echo OBD driver; http://www.lustre.org/ [ 128.950328] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 156.755315] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing load_modules_local [ 165.494840] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 165.516211] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 166.737818] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 166.768236] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 166.828347] Lustre: lustre-MDT0000: new disk, initializing [ 166.888791] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 166.899468] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 169.832873] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 179.017865] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 179.109972] Lustre: 6510: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 [ 179.131363] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 179.133502] Lustre: Skipped 1 previous similar message [ 179.188902] Lustre: lustre-MDT0001: new disk, initializing [ 179.234626] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 179.266064] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 179.282672] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 182.134211] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 185.633938] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 191.492419] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 191.653484] Lustre: lustre-OST0000: new disk, initializing [ 191.656200] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 191.660322] Lustre: 8446:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 191.704129] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 191.791212] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 191.799323] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 191.888142] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 195.660300] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 205.445935] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 205.548853] Lustre: lustre-OST0001: new disk, initializing [ 205.551762] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 205.555860] Lustre: 9517:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 205.599609] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 209.717672] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 214.022216] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 214.030665] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 214.048801] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 218.321605] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 224.424814] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 228.248234] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing check_logdir /tmp/testlogs/ [ 230.743848] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing yml_node [ 234.035982] Lustre: DEBUG MARKER: Client: 2.17.57.86 [ 235.917785] Lustre: DEBUG MARKER: MDS: 2.17.57.86 [ 237.647449] Lustre: DEBUG MARKER: OSS: 2.17.57.86 [ 238.697361] Lustre: DEBUG MARKER: -----============= acceptance-small: replay-single ============----- Tue Sep 8 19:06:47 EDT 2026 [ 250.221153] Lustre: DEBUG MARKER: excepting tests: 110f 131b 59 36 [ 251.629489] Lustre: DEBUG MARKER: === replay-single: start setup 19:06:59 (1788908819) === [ 255.500794] Lustre: DEBUG MARKER: oleg213-client.virtnet: executing check_config_client /mnt/lustre [ 268.488280] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 270.604267] Lustre: 13323:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 272.847408] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 276.336638] Lustre: DEBUG MARKER: === replay-single: finish setup 19:07:24 (1788908844) === [ 278.555963] Lustre: DEBUG MARKER: == replay-single test 100a: DNE: create striped dir, drop update rep from MDT1, fail MDT1 ========================================================== 19:07:26 (1788908846) [ 279.685635] Lustre: *** cfs_fail_loc=1701, val=2147483648*** [ 279.687456] LustreError: 13293:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff910447ab0a80 x1875806712326272/t4294967300(0) o1000->lustre-MDT0000-mdtlov_UUID@0@lo:535/0 lens 264/4320 e 0 to 0 dl 1788908860 ref 1 fl Interpret:/200/0 rc 0/0 job:'osp_up1-0.0' uid:0 gid:0 projid:4294967295 [ 281.239165] Lustre: Failing over lustre-MDT0001 [ 281.521870] Lustre: server umount lustre-MDT0001 complete [ 282.596538] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 282.608694] 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 [ 285.664993] 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 [ 286.885765] LustreError: 10088:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 192.168.202.13@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 286.902358] LustreError: 10088:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 6 previous similar messages [ 290.786283] LustreError: 6546:0:(ldlm_lib.c:1190: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. [ 290.793767] LustreError: 6546:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 1 previous similar message [ 292.004661] LustreError: 6517:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 192.168.202.13@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 295.908407] Lustre: 7526:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788908849/real 1788908849] req@ffff910447ab2d80 x1875806712326272/t0(0) o1000->lustre-MDT0001-osp-MDT0000@0@lo:24/4 lens 264/4320 e 0 to 1 dl 1788908865 ref 2 fl Rpc:XQr/200/ffffffff rc 0/-1 job:'osp_up1-0.0' uid:0 gid:0 projid:4294967295 [ 295.909331] LustreError: 13293:0:(ldlm_lib.c:1190: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. [ 295.945978] LustreError: 13293:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 2 previous similar messages [ 297.546110] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 297.758436] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 299.319119] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 301.252655] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 303.076496] Lustre: lustre-MDT0001-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 303.089840] Lustre: lustre-MDT0001: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 308.618957] Lustre: DEBUG MARKER: oleg213-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 309.773763] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 317.507497] Lustre: DEBUG MARKER: == replay-single test 100b: DNE: create striped dir, fail MDT0 ========================================================== 19:08:05 (1788908885) [ 318.456183] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 318.460190] LustreError: 6517:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff910447837480 x1875806698649472/t4294967361(0) o36->7050fccd-e219-4780-8276-fa4dda26bc33@192.168.202.13@tcp:614/0 lens 560/536 e 0 to 0 dl 1788908939 ref 1 fl Interpret:/200/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 319.747228] Lustre: Failing over lustre-MDT0000 [ 319.995539] Lustre: server umount lustre-MDT0000 complete [ 323.555167] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 323.556425] 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 [ 323.561550] LustreError: 6523:0:(ldlm_lib.c:1190: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. [ 323.561561] LustreError: 6523:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 1 previous similar message [ 323.605627] Lustre: Skipped 3 previous similar messages [ 333.794084] LustreError: 6546:0:(ldlm_lib.c:1190: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. [ 333.805567] LustreError: 6546:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 12 previous similar messages [ 335.881364] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 335.957834] LustreError: MGC192.168.202.113@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 336.131764] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 339.138308] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 340.132347] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 341.482695] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 341.485804] Lustre: Skipped 2 previous similar messages [ 341.523811] Lustre: lustre-MDT0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 341.525171] Lustre: 6518:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff910574829500 x1875806698649472/t4294967361(0) o36->7050fccd-e219-4780-8276-fa4dda26bc33@192.168.202.13@tcp:637/0 lens 560/2880 e 0 to 0 dl 1788908962 ref 1 fl Interpret:/202/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 341.562291] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:6 to 0x2c0000401:33) [ 341.562338] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:6 to 0x280000401:33) [ 345.408420] Lustre: DEBUG MARKER: oleg213-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 346.482244] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 354.343855] Lustre: DEBUG MARKER: == replay-single test 100c: DNE: create striped dir, abort_recov_mdt mds2 ========================================================== 19:08:42 (1788908922) [ 360.321270] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 361.679282] Lustre: Failing over lustre-MDT0001 [ 361.954801] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 361.960846] 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 [ 361.964473] LustreError: 6518:0:(ldlm_lib.c:1190: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. [ 361.968972] Lustre: Skipped 2 previous similar messages [ 361.981912] LustreError: 6518:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 3 previous similar messages [ 362.010513] Lustre: server umount lustre-MDT0001 complete [ 370.885784] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 370.887623] LDISKFS-fs (dm-1): recovery complete [ 370.900961] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 371.103925] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 371.137496] Lustre: lustre-MDT0001: Aborting MDT recovery [ 372.652426] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 375.102815] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 376.301689] Lustre: lustre-MDT0001-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 376.309663] Lustre: Skipped 3 previous similar messages [ 376.363750] Lustre: lustre-MDT0001-osd: cancel update llog [0x240000400:0x1:0x0] [ 376.368540] Lustre: lustre-MDT0000-osp-MDT0001: cancel update llog [0x200000401:0x1:0x0] [ 376.377936] Lustre: lustre-MDT0001: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 376.415815] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:46 to 0x2c0000400:65) [ 376.416694] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:46 to 0x280000400:65) [ 388.891863] Lustre: Failing over lustre-MDT0001 [ 389.051638] Lustre: server umount lustre-MDT0001 complete [ 391.653492] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 391.653631] 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 [ 391.685160] Lustre: Skipped 3 previous similar messages [ 396.458821] LustreError: 13981:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 192.168.202.13@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 396.476583] LustreError: 13981:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 9 previous similar messages [ 405.317864] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 405.533616] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 406.690140] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 408.794201] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 410.598243] Lustre: lustre-MDT0001-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 410.605531] Lustre: Skipped 2 previous similar messages [ 410.621913] Lustre: lustre-MDT0001: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 410.664537] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:70 to 0x2c0000400:97) [ 410.667904] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:70 to 0x280000400:97) [ 416.498915] Lustre: DEBUG MARKER: oleg213-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 417.439476] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 424.318153] Lustre: DEBUG MARKER: == replay-single test 100d: DNE: cancel update logs upon recovery abort ========================================================== 19:09:52 (1788908992) [ 436.904757] Lustre: Failing over lustre-MDT0001 [ 437.118914] Lustre: server umount lustre-MDT0001 complete [ 439.789897] LustreError: lustre-MDT0001-osp-MDT0000: operation out_update to node 0@lo failed: rc = -107 [ 439.798343] 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 [ 443.263272] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 443.501343] Lustre: lustre-MDT0001: Aborting client recovery [ 443.503493] LustreError: 20174:0:(ldlm_lib.c:3029:target_stop_recovery_thread()) lustre-MDT0001: Aborting recovery [ 443.510710] LustreError: 20196:0:(lod_dev.c:511:lod_sub_recovery_thread()) lustre-MDT0001-osd: get update log duration 0, retries 0, failed: rc = -108 [ 443.513174] Lustre: 20198:0:(ldlm_lib.c:2429:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 443.519979] Lustre: 20198:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0001: disconnect stale client 7050fccd-e219-4780-8276-fa4dda26bc33@ [ 443.528514] Lustre: lustre-MDT0001: disconnecting 2 stale clients [ 443.535087] Lustre: lustre-MDT0001-osd: cancel update llog [0x2400013a0:0x3:0x0] [ 443.542146] Lustre: lustre-MDT0000-osp-MDT0001: cancel update llog [0x200000bd1:0x3:0x0] [ 443.573947] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:70 to 0x280000400:129) [ 443.616018] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:70 to 0x2c0000400:129) [ 446.763255] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 448.484980] Lustre: lustre-MDT0001-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 448.494275] Lustre: Skipped 2 previous similar messages [ 448.500766] LustreError: lustre-MDT0001-osp-MDT0000: This client was evicted by lustre-MDT0001; in progress operations using this service will fail. [ 464.771129] Lustre: DEBUG MARKER: == replay-single test 100e: DNE: create striped dir on MDT0 and MDT1, fail MDT0, MDT1 ========================================================== 19:10:32 (1788909032) [ 470.505329] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 476.321370] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 477.795904] Lustre: Failing over lustre-MDT0000 [ 477.974976] Lustre: server umount lustre-MDT0000 complete [ 478.389786] LustreError: 19633:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.202.13@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 478.402570] LustreError: 19633:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 13 previous similar messages [ 479.204189] 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 [ 479.206390] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 479.213072] Lustre: Skipped 5 previous similar messages [ 480.675825] LustreError: 6502:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788909050 with bad export cookie 10752212430049765065 [ 480.680040] LustreError: 6502:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 480.680719] LustreError: MGC192.168.202.113@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 480.681356] Lustre: Failing over lustre-MDT0001 [ 480.893193] Lustre: server umount lustre-MDT0001 complete [ 501.384323] LDISKFS-fs (dm-1): 5 truncates cleaned up [ 501.385728] LDISKFS-fs (dm-1): recovery complete [ 501.394992] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 501.486255] LDISKFS-fs (dm-0): 3 truncates cleaned up [ 501.488673] LDISKFS-fs (dm-0): recovery complete [ 501.503038] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 501.565519] LustreError: 23125:0:(llog.c:1655:llog_backup()) MGC192.168.202.113@tcp: failed to open log lustre-sptlrpc: rc = -108 [ 501.569386] Lustre: 23125:0:(mgc_request_server.c:770:mgc_llog_local_copy()) MGC192.168.202.113@tcp: failed to copy new config lustre-sptlrpc: rc = -108 [ 505.828619] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x9537883ccaa842a2 [ 505.836562] Lustre: MGC192.168.202.113@tcp: Connection restored to 0@lo (at 0@lo) [ 505.846111] Lustre: Skipped 2 previous similar messages [ 506.006720] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 506.009383] Lustre: Skipped 1 previous similar message [ 506.190281] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_connect to node 0@lo failed: rc = -114 [ 507.658285] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 510.047769] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 510.381160] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 512.180290] Lustre: lustre-MDT0001: Recovery over after 0:05, of 2 clients 2 recovered and 0 were evicted. [ 512.215168] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:70 to 0x2c0000400:161) [ 512.215579] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:70 to 0x280000400:161) [ 518.199732] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:44 to 0x280000401:65) [ 518.203842] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:44 to 0x2c0000401:65) [ 522.980936] Lustre: DEBUG MARKER: oleg213-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 [ 524.237922] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 525.544959] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 532.738359] Lustre: DEBUG MARKER: == replay-single test 101: Shouldn't reassign precreated objs to other files after recovery ========================================================== 19:11:40 (1788909100) [ 538.708356] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 540.625229] Lustre: 3649:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788909054/real 1788909054] req@ffff910581d8bb80 x1875806712687360/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788909110 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 545.248873] Lustre: 3647:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788909059/real 1788909059] req@ffff910448d6d180 x1875806712687744/t0(0) o400->lustre-MDT0001-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788909115 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 545.279738] Lustre: 3647:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 551.392176] Lustre: 3647:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788909065/real 1788909065] req@ffff910576917480 x1875806712688384/t0(0) o400->lustre-MDT0001-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788909121 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 551.438316] Lustre: 3647:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 4 previous similar messages [ 555.489199] Lustre: 3647:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788909069/real 1788909069] req@ffff910581d8b800 x1875806712689024/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788909125 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 557.118112] Lustre: Failing over lustre-MDT0000 [ 557.496341] Lustre: server umount lustre-MDT0000 complete [ 559.074186] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 559.079693] 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 [ 559.086123] Lustre: Skipped 2 previous similar messages [ 566.716806] LDISKFS-fs (dm-0): 3 truncates cleaned up [ 566.718939] LDISKFS-fs (dm-0): recovery complete [ 566.727954] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 566.785829] LustreError: MGC192.168.202.113@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 566.969817] Lustre: lustre-MDT0000: Aborting client recovery [ 566.975251] LustreError: 25563:0:(ldlm_lib.c:3029:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 566.980302] Lustre: 25597:0:(ldlm_lib.c:2429:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 566.982278] LustreError: 25596:0:(lod_dev.c:511:lod_sub_recovery_thread()) lustre-MDT0001-osp-MDT0000: get update log duration 0, retries 0, failed: rc = -108 [ 566.987756] Lustre: 25597:0:(ldlm_lib.c:2429:target_recovery_overseer()) Skipped 2 previous similar messages [ 566.997700] Lustre: 25597:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 7050fccd-e219-4780-8276-fa4dda26bc33@ [ 567.004744] Lustre: 25597:0:(genops.c:1601:class_disconnect_stale_exports()) Skipped 1 previous similar message [ 567.009231] Lustre: lustre-MDT0000: disconnecting 2 stale clients [ 567.013945] Lustre: lustre-MDT0000-osd: cancel update llog [0x200000400:0x1:0x0] [ 567.020725] Lustre: lustre-MDT0001-osp-MDT0000: cancel update llog [0x240000401:0x1:0x0] [ 567.059351] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:44 to 0x2c0000401:609) [ 567.067094] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:67 to 0x280000401:609) [ 570.684297] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 572.387582] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 572.398147] Lustre: Skipped 6 previous similar messages [ 638.438181] Lustre: DEBUG MARKER: == replay-single test 102a: check resend (request lost) with multiple modify RPCs in flight ========================================================== 19:13:26 (1788909206) [ 639.629642] Lustre: *** cfs_fail_loc=159, val=0*** [ 693.952368] Lustre: lustre-MDT0001: Client 7050fccd-e219-4780-8276-fa4dda26bc33 (at 192.168.202.13@tcp) reconnecting [ 699.216947] Lustre: DEBUG MARKER: == replay-single test 102b: check resend (reply lost) with multiple modify RPCs in flight ========================================================== 19:14:27 (1788909267) [ 700.419130] Lustre: *** cfs_fail_loc=15a, val=0*** [ 755.370221] Lustre: lustre-MDT0000: Client 7050fccd-e219-4780-8276-fa4dda26bc33 (at 192.168.202.13@tcp) reconnecting [ 755.396615] Lustre: 23136:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff91044afb7800 x1875806701636864/t17179873231(0) o36->7050fccd-e219-4780-8276-fa4dda26bc33@192.168.202.13@tcp:295/0 lens 488/3152 e 0 to 0 dl 1788909375 ref 1 fl Interpret:/202/0 rc 0/0 job:'chmod.0' uid:0 gid:0 projid:4294967295 [ 755.422087] Lustre: 23136:0:(mdt_recovery.c:102:mdt_req_from_lrd()) Skipped 6 previous similar messages [ 760.157253] Lustre: DEBUG MARKER: == replay-single test 102c: check replay w/o reconstruction with multiple mod RPCs in flight ========================================================== 19:15:28 (1788909328) [ 765.990742] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 766.741332] Lustre: *** cfs_fail_loc=15a, val=0*** [ 766.749553] Lustre: Skipped 6 previous similar messages [ 769.479610] Lustre: Failing over lustre-MDT0001 [ 769.615991] Lustre: server umount lustre-MDT0001 complete [ 770.726033] LustreError: 23919:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 192.168.202.13@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 770.735565] LustreError: 23919:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 23 previous similar messages [ 772.069948] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 772.071116] 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 [ 772.092011] Lustre: Skipped 5 previous similar messages [ 787.652548] LDISKFS-fs (dm-1): 7 truncates cleaned up [ 787.655144] LDISKFS-fs (dm-1): recovery complete [ 787.666641] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 787.898788] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 787.904491] Lustre: Skipped 2 previous similar messages [ 787.923497] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 789.569801] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 789.575680] Lustre: Skipped 1 previous similar message [ 790.821339] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 793.061312] Lustre: lustre-MDT0001-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 793.065897] Lustre: Skipped 2 previous similar messages [ 793.070901] Lustre: lustre-MDT0001: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 793.070911] Lustre: Skipped 1 previous similar message [ 793.112064] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:169 to 0x2c0000400:193) [ 793.112423] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:169 to 0x280000400:193) [ 797.709080] Lustre: DEBUG MARKER: oleg213-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 798.834629] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 805.027588] Lustre: DEBUG MARKER: == replay-single test 102d: check replay [ 805.922581] Lustre: *** cfs_fail_loc=15a, val=0*** [ 805.926704] Lustre: Skipped 4 previous similar messages [ 809.089804] Lustre: Failing over lustre-MDT0000 [ 809.301298] Lustre: server umount lustre-MDT0000 complete [ 824.819675] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 824.883268] LustreError: MGC192.168.202.113@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 825.031561] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 826.243184] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 827.954264] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 830.454979] Lustre: lustre-MDT0000: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 830.476316] Lustre: 23135:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff91044a167100 x1875806701698816/t17179873292(0) o36->7050fccd-e219-4780-8276-fa4dda26bc33@192.168.202.13@tcp:370/0 lens 488/3152 e 0 to 0 dl 1788909450 ref 1 fl Interpret:/202/0 rc 0/0 job:'chmod.0' uid:0 gid:0 projid:4294967295 [ 830.484915] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1117 to 0x280000401:1153) [ 830.485309] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1117 to 0x2c0000401:1153) [ 830.509869] Lustre: 23135:0:(mdt_recovery.c:102:mdt_req_from_lrd()) Skipped 6 previous similar messages [ 834.938481] Lustre: DEBUG MARKER: oleg213-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 836.103936] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 842.256620] Lustre: DEBUG MARKER: == replay-single test 103: Check otr_next_id overflow ==== 19:16:50 (1788909410) [ 845.055780] Lustre: Failing over lustre-MDT0000 [ 845.189138] Lustre: server umount lustre-MDT0000 complete [ 860.465857] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 860.538208] LustreError: MGC192.168.202.113@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 860.663539] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 861.876623] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 863.478926] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 865.767798] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 865.773773] Lustre: Skipped 6 previous similar messages [ 865.800344] Lustre: lustre-MDT0000: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 865.842143] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1117 to 0x2c0000401:1185) [ 865.843319] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1117 to 0x280000401:1185) [ 869.748785] Lustre: DEBUG MARKER: oleg213-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 870.683669] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 876.498584] Lustre: DEBUG MARKER: == replay-single test 110a: DNE: create striped dir, fail MDT1 ========================================================== 19:17:24 (1788909444) [ 881.551761] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 882.733219] Lustre: Failing over lustre-MDT0000 [ 882.961889] Lustre: server umount lustre-MDT0000 complete [ 900.667494] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 900.669467] LDISKFS-fs (dm-0): recovery complete [ 900.677120] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 900.739870] LustreError: MGC192.168.202.113@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 900.890629] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 903.689644] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 906.276299] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1117 to 0x2c0000401:1217) [ 906.279191] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1117 to 0x280000401:1217) [ 910.048352] Lustre: DEBUG MARKER: oleg213-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 911.083540] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 916.660621] Lustre: DEBUG MARKER: == replay-single test 110b: DNE: create striped dir, fail MDT1 and client ========================================================== 19:18:05 (1788909485) [ 921.731972] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 923.380086] Lustre: Failing over lustre-MDT0000 [ 925.567869] Lustre: server umount lustre-MDT0000 complete [ 926.691192] 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 [ 926.693801] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 926.702448] Lustre: Skipped 12 previous similar messages [ 926.721791] LustreError: Skipped 3 previous similar messages [ 942.880391] Lustre: 3650:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788909496/real 1788909496] req@ffff91054988d500 x1875806713401984/t0(0) o400->MGC192.168.202.113@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1788909512 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 942.896075] Lustre: 3650:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 942.904073] LustreError: MGC192.168.202.113@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 944.094689] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 944.097657] LDISKFS-fs (dm-0): recovery complete [ 944.106199] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 952.418561] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 954.866235] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 957.411805] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 957.421685] Lustre: Skipped 1 previous similar message [ 960.651374] Lustre: DEBUG MARKER: oleg213-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 962.663955] Lustre: lustre-MDT0000: Denying connection for new client b7a45711-e520-4192-bc70-b50493684a39 (at 192.168.202.13@tcp), waiting for 2 known clients (0 recovered, 1 in progress, and 0 evicted) to recover in 1:04 [ 967.847787] Lustre: lustre-MDT0000: Denying connection for new client b7a45711-e520-4192-bc70-b50493684a39 (at 192.168.202.13@tcp), waiting for 2 known clients (0 recovered, 1 in progress, and 0 evicted) to recover in 0:59 [ 972.963795] Lustre: lustre-MDT0000: Denying connection for new client b7a45711-e520-4192-bc70-b50493684a39 (at 192.168.202.13@tcp), waiting for 2 known clients (0 recovered, 1 in progress, and 0 evicted) to recover in 0:54 [ 978.084750] Lustre: lustre-MDT0000: Denying connection for new client b7a45711-e520-4192-bc70-b50493684a39 (at 192.168.202.13@tcp), waiting for 2 known clients (0 recovered, 1 in progress, and 0 evicted) to recover in 0:49 [ 983.207633] Lustre: lustre-MDT0000: Denying connection for new client b7a45711-e520-4192-bc70-b50493684a39 (at 192.168.202.13@tcp), waiting for 2 known clients (0 recovered, 1 in progress, and 0 evicted) to recover in 0:44 [ 993.445831] Lustre: lustre-MDT0000: Denying connection for new client b7a45711-e520-4192-bc70-b50493684a39 (at 192.168.202.13@tcp), waiting for 2 known clients (0 recovered, 1 in progress, and 0 evicted) to recover in 0:34 [ 993.456435] Lustre: Skipped 1 previous similar message [ 1013.923766] Lustre: lustre-MDT0000: Denying connection for new client b7a45711-e520-4192-bc70-b50493684a39 (at 192.168.202.13@tcp), waiting for 2 known clients (0 recovered, 1 in progress, and 0 evicted) to recover in 0:13 [ 1013.930685] Lustre: Skipped 3 previous similar messages [ 1027.500201] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 1027.505198] Lustre: 34951:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 7050fccd-e219-4780-8276-fa4dda26bc33@ [ 1027.510182] Lustre: 34951:0:(genops.c:1601:class_disconnect_stale_exports()) Skipped 1 previous similar message [ 1027.513507] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 1027.524358] Lustre: lustre-MDT0000: Recovery over after 1:10, of 2 clients 1 recovered and 1 was evicted. [ 1027.525109] Lustre: lustre-MDT0000-osp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1027.529702] Lustre: Skipped 1 previous similar message [ 1027.542326] Lustre: Skipped 10 previous similar messages [ 1027.555916] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1117 to 0x2c0000401:1249) [ 1027.555940] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1117 to 0x280000401:1249) [ 1035.661570] Lustre: DEBUG MARKER: == replay-single test 110c: DNE: create striped dir, fail MDT2 ========================================================== 19:20:04 (1788909604) [ 1040.355338] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 1041.571781] Lustre: Failing over lustre-MDT0001 [ 1041.727413] Lustre: server umount lustre-MDT0001 complete [ 1044.450307] LustreError: 23136:0:(ldlm_lib.c:1190: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. [ 1044.456618] LustreError: 23136:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 86 previous similar messages [ 1059.518368] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 1059.520394] LDISKFS-fs (dm-1): recovery complete [ 1059.529187] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1059.697127] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 1059.701093] Lustre: Skipped 4 previous similar messages [ 1059.719303] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 1062.193775] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1064.995957] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:209 to 0x280000400:225) [ 1064.997619] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:209 to 0x2c0000400:225) [ 1068.552179] Lustre: DEBUG MARKER: oleg213-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 1069.477206] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1075.322436] Lustre: DEBUG MARKER: == replay-single test 110d: DNE: create striped dir, fail MDT2 and client ========================================================== 19:20:43 (1788909643) [ 1080.865751] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 1082.537505] Lustre: Failing over lustre-MDT0001 [ 1082.746462] Lustre: server umount lustre-MDT0001 complete [ 1100.321751] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 1100.323968] LDISKFS-fs (dm-1): recovery complete [ 1100.338642] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1100.551484] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 1102.877212] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1105.891979] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 1105.898333] Lustre: Skipped 1 previous similar message [ 1108.941322] Lustre: DEBUG MARKER: oleg213-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 1110.802682] Lustre: lustre-MDT0001: Denying connection for new client 9cc94bbc-b66d-49dc-8b57-d2791f015700 (at 192.168.202.13@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 1:04 [ 1110.822861] Lustre: Skipped 2 previous similar messages [ 1175.501737] Lustre: lustre-MDT0001: recovery is timed out, evict stale exports [ 1175.505288] Lustre: 38777:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0001: disconnect stale client b7a45711-e520-4192-bc70-b50493684a39@ [ 1175.516246] Lustre: lustre-MDT0001: disconnecting 1 stale clients [ 1175.547369] Lustre: lustre-MDT0001: Recovery over after 1:10, of 2 clients 1 recovered and 1 was evicted. [ 1175.550057] Lustre: Skipped 1 previous similar message [ 1175.569735] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:209 to 0x2c0000400:257) [ 1175.570286] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:209 to 0x280000400:257) [ 1182.321962] Lustre: DEBUG MARKER: == replay-single test 110e: DNE: create striped dir, uncommit on MDT2, fail client/MDT1/MDT2 ========================================================== 19:22:30 (1788909750) [ 1187.095597] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 1192.116705] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1193.422150] Lustre: Failing over lustre-MDT0000 [ 1193.575708] Lustre: server umount lustre-MDT0000 complete [ 1195.948082] Lustre: Failing over lustre-MDT0001 [ 1195.949475] LustreError: 19634:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788909765 with bad export cookie 10752212430049992978 [ 1195.950157] LustreError: MGC192.168.202.113@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1195.961401] LustreError: 19634:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 3 previous similar messages [ 1196.121021] Lustre: server umount lustre-MDT0001 complete [ 1214.456807] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1214.459104] LDISKFS-fs (dm-0): recovery complete [ 1214.466820] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1214.474167] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 1214.479304] LDISKFS-fs (dm-1): recovery complete [ 1214.492883] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1220.576461] LustreError: 3646:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff91057572ed80 x1875806713553792/t0(0) o250->MGC192.168.202.113@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 [ 1220.866459] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 1221.009157] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_connect to node 0@lo failed: rc = -114 [ 1221.010309] 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 [ 1221.012723] LustreError: Skipped 2 previous similar messages [ 1221.037724] Lustre: Skipped 11 previous similar messages [ 1223.669539] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1223.800646] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1227.260151] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1117 to 0x2c0000401:1281) [ 1227.260723] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1117 to 0x280000401:1281) [ 1230.639647] Lustre: DEBUG MARKER: oleg213-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 [ 1232.528489] Lustre: lustre-MDT0001: Denying connection for new client fe3a344e-e8a4-406e-8636-4f20bc62022c (at 192.168.202.13@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 1:03 [ 1232.542507] Lustre: Skipped 12 previous similar messages [ 1252.832159] Lustre: 3650:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788909767/real 1788909767] req@ffff91057572c380 x1875806713551488/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788909822 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1252.860172] Lustre: 3650:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 1296.500129] Lustre: lustre-MDT0001: recovery is timed out, evict stale exports [ 1296.504200] Lustre: 41781:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0001: disconnect stale client 9cc94bbc-b66d-49dc-8b57-d2791f015700@ [ 1296.509702] Lustre: lustre-MDT0001: disconnecting 1 stale clients [ 1296.543819] Lustre: lustre-MDT0001-osp-MDT0000: Connection restored to 0@lo (at 0@lo) [ 1296.547271] Lustre: Skipped 11 previous similar messages [ 1296.563980] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:209 to 0x2c0000400:289) [ 1296.564923] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:209 to 0x280000400:289) [ 1303.952727] Lustre: DEBUG MARKER: SKIP: replay-single test_110f skipping excluded test 110f [ 1305.205434] Lustre: DEBUG MARKER: == replay-single test 110g: DNE: create striped dir, uncommit on MDT1, fail client/MDT1/MDT2 ========================================================== 19:24:33 (1788909873) [ 1309.937646] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1314.532766] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 1315.653395] Lustre: Failing over lustre-MDT0000 [ 1315.768515] Lustre: server umount lustre-MDT0000 complete [ 1318.027815] LustreError: 6502:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788909887 with bad export cookie 10752212430049997171 [ 1318.032805] LustreError: MGC192.168.202.113@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1318.037674] Lustre: Failing over lustre-MDT0001 [ 1319.394955] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 1319.399060] Lustre: Skipped 1 previous similar message [ 1323.424797] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 1324.196853] Lustre: server umount lustre-MDT0001 complete [ 1342.136447] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1342.140238] LDISKFS-fs (dm-0): recovery complete [ 1342.144632] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1342.159454] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 1342.161289] LDISKFS-fs (dm-1): recovery complete [ 1342.168933] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1343.139258] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1343.146323] Lustre: Skipped 1 previous similar message [ 1345.697973] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1345.952620] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1348.565480] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:209 to 0x2c0000400:321) [ 1348.567391] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:209 to 0x280000400:321) [ 1351.867637] Lustre: DEBUG MARKER: oleg213-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 [ 1363.619676] Lustre: lustre-MDT0000: Denying connection for new client 530b22c6-0686-4c5a-8a21-ddd5220467cc (at 192.168.202.13@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 0:53 [ 1363.629039] Lustre: Skipped 14 previous similar messages [ 1417.500429] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 1417.502125] Lustre: 45215:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client fe3a344e-e8a4-406e-8636-4f20bc62022c@ [ 1417.508134] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 1417.537251] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1117 to 0x280000401:1313) [ 1417.538625] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1117 to 0x2c0000401:1313) [ 1425.330253] Lustre: DEBUG MARKER: == replay-single test 111a: DNE: unlink striped dir, fail MDT1 ========================================================== 19:26:33 (1788909993) [ 1429.189662] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1430.296450] Lustre: Failing over lustre-MDT0000 [ 1430.488164] Lustre: server umount lustre-MDT0000 complete [ 1446.825356] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1446.826903] LDISKFS-fs (dm-0): recovery complete [ 1446.832691] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1446.922274] LustreError: MGC192.168.202.113@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1449.118699] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1450.662817] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 1450.666297] Lustre: Skipped 4 previous similar messages [ 1452.540697] Lustre: lustre-MDT0000: Recovery over after 0:02, of 2 clients 2 recovered and 0 were evicted. [ 1452.549430] Lustre: Skipped 4 previous similar messages [ 1452.566935] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1117 to 0x2c0000401:1345) [ 1452.566940] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1117 to 0x280000401:1345) [ 1455.240363] Lustre: DEBUG MARKER: oleg213-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1456.008301] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1460.648031] Lustre: DEBUG MARKER: == replay-single test 111b: DNE: unlink striped dir, fail MDT2 ========================================================== 19:27:09 (1788910029) [ 1464.833878] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 1466.130376] Lustre: Failing over lustre-MDT0001 [ 1466.234973] Lustre: server umount lustre-MDT0001 complete [ 1482.831836] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 1482.835281] LDISKFS-fs (dm-1): recovery complete [ 1482.847985] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1482.990214] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 1482.999347] Lustre: Skipped 2 previous similar messages [ 1485.255211] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1490.872737] Lustre: DEBUG MARKER: oleg213-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 1558.501065] Lustre: lustre-MDT0001: recovery is timed out, evict stale exports [ 1558.503480] Lustre: 49434:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0001: disconnect stale client 530b22c6-0686-4c5a-8a21-ddd5220467cc@ [ 1558.512102] Lustre: lustre-MDT0001: disconnecting 1 stale clients [ 1558.536904] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:209 to 0x2c0000400:353) [ 1558.539600] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:209 to 0x280000400:353) [ 1563.841052] Lustre: DEBUG MARKER: == replay-single test 111c: DNE: unlink striped dir, uncommit on MDT1, fail client/MDT1/MDT2 ========================================================== 19:28:52 (1788910132) [ 1568.247696] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1572.126437] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 1573.071448] Lustre: Failing over lustre-MDT0000 [ 1573.179094] Lustre: server umount lustre-MDT0000 complete [ 1574.812395] LustreError: 6502:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788910144 with bad export cookie 10752212430050001931 [ 1574.813056] Lustre: Failing over lustre-MDT0001 [ 1574.824744] LustreError: 6502:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 3 previous similar messages [ 1575.393153] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 1575.393204] LustreError: 45178:0:(ldlm_lib.c:1190: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. [ 1575.395805] Lustre: Skipped 2 previous similar messages [ 1575.402969] LustreError: 45178:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 54 previous similar messages [ 1579.424875] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 1581.179892] Lustre: server umount lustre-MDT0001 complete [ 1598.082661] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1598.084387] LDISKFS-fs (dm-0): recovery complete [ 1598.087957] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1598.110868] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 1598.112700] LDISKFS-fs (dm-1): recovery complete [ 1598.120657] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1599.203674] LustreError: 52385:0:(import.c:339:ptlrpc_invalidate_import()) MGS: timeout waiting for callback (1 != 0) [ 1599.210188] LustreError: 52385:0:(import.c:363:ptlrpc_invalidate_import()) @@@ still on sending list req@ffff910581b18700 x1875806713778816/t0(0) o250->MGC192.168.202.113@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 1788910169 ref 1 fl Rpc:NQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1599.224022] LustreError: 52385:0:(import.c:373:ptlrpc_invalidate_import()) MGS: Unregistering RPCs found (0). Network is sluggish? Waiting for them to error out. [ 1599.972114] LustreError: 3646:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff910546e31f80 x1875806713779456/t0(0) o250->MGC192.168.202.113@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 [ 1600.181390] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 1600.184033] Lustre: Skipped 7 previous similar messages [ 1602.492279] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1602.494654] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1605.409991] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:209 to 0x280000400:385) [ 1605.410028] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:209 to 0x2c0000400:385) [ 1607.246463] Lustre: DEBUG MARKER: oleg213-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 [ 1624.228274] Lustre: lustre-MDT0000: Denying connection for new client b865e6fc-db1c-4eda-8bbf-ef98cc48a3a1 (at 192.168.202.13@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 0:50 [ 1624.242189] Lustre: Skipped 26 previous similar messages [ 1674.500415] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 1674.503132] Lustre: 52476:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 6bb9d899-4472-44a6-a4e8-5650f9f429f7@ [ 1674.508706] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 1674.547623] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1117 to 0x2c0000401:1377) [ 1674.552559] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1117 to 0x280000401:1377) [ 1681.569871] Lustre: DEBUG MARKER: == replay-single test 111d: DNE: unlink striped dir, uncommit on MDT2, fail client/MDT1/MDT2 ========================================================== 19:30:50 (1788910250) [ 1685.897148] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 1689.889791] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1690.937538] Lustre: Failing over lustre-MDT0000 [ 1691.044025] Lustre: server umount lustre-MDT0000 complete [ 1692.867288] LustreError: 10390:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788910262 with bad export cookie 10752212430050004836 [ 1692.869584] Lustre: Failing over lustre-MDT0001 [ 1692.876214] LustreError: 10390:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 1693.020043] Lustre: server umount lustre-MDT0001 complete [ 1709.933301] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 1709.934589] LDISKFS-fs (dm-1): recovery complete [ 1709.945343] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1710.002067] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1710.004203] LDISKFS-fs (dm-0): recovery complete [ 1710.008415] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1710.062986] LustreError: 55750:0:(llog.c:1655:llog_backup()) MGC192.168.202.113@tcp: failed to open log lustre-sptlrpc: rc = -108 [ 1710.071022] Lustre: 55750:0:(mgc_request_server.c:770:mgc_llog_local_copy()) MGC192.168.202.113@tcp: failed to copy new config lustre-sptlrpc: rc = -108 [ 1714.080120] Lustre: 3650:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788910267/real 1788910267] req@ffff91054809f800 x1875806713840384/t0(0) o400->lustre-MDT0001-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788910283 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1714.094259] Lustre: 3650:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 19 previous similar messages [ 1717.217041] LustreError: 3646:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff910547175500 x1875806713842560/t0(0) o250->MGC192.168.202.113@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 [ 1719.272388] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1719.498578] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1723.635892] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1117 to 0x2c0000401:1409) [ 1723.635919] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1117 to 0x280000401:1409) [ 1724.216921] Lustre: DEBUG MARKER: oleg213-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 [ 1792.500470] Lustre: lustre-MDT0001: recovery is timed out, evict stale exports [ 1792.503455] Lustre: 55826:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0001: disconnect stale client b865e6fc-db1c-4eda-8bbf-ef98cc48a3a1@ [ 1792.512711] Lustre: lustre-MDT0001: disconnecting 1 stale clients [ 1792.543624] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:209 to 0x280000400:417) [ 1792.543643] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:209 to 0x2c0000400:417) [ 1796.265962] Lustre: DEBUG MARKER: == replay-single test 111e: DNE: unlink striped dir, uncommit on MDT2, fail MDT1/MDT2 ========================================================== 19:32:44 (1788910364) [ 1800.254279] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 1803.417664] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1804.167253] Lustre: Failing over lustre-MDT0000 [ 1804.385867] Lustre: server umount lustre-MDT0000 complete [ 1805.794128] 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 [ 1805.794623] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1805.801219] Lustre: Skipped 23 previous similar messages [ 1805.808529] LustreError: Skipped 4 previous similar messages [ 1805.984887] LustreError: 19634:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788910375 with bad export cookie 10752212430050007055 [ 1805.985336] LustreError: MGC192.168.202.113@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1805.989372] LustreError: 19634:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 3 previous similar messages [ 1806.006558] LustreError: Skipped 2 previous similar messages [ 1806.010811] Lustre: Failing over lustre-MDT0001 [ 1806.134720] Lustre: server umount lustre-MDT0001 complete [ 1822.261876] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1822.264062] LDISKFS-fs (dm-0): recovery complete [ 1822.269666] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1822.274554] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 1822.276961] LDISKFS-fs (dm-1): recovery complete [ 1822.290395] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1822.428128] LustreError: 59160:0:(llog.c:1655:llog_backup()) MGC192.168.202.113@tcp: failed to open log lustre-sptlrpc: rc = -108 [ 1822.432938] Lustre: 59160:0:(mgc_request_server.c:770:mgc_llog_local_copy()) MGC192.168.202.113@tcp: failed to copy new config lustre-sptlrpc: rc = -108 [ 1826.272202] Lustre: 3647:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788910380/real 1788910380] req@ffff910575c6dc00 x1875806713901056/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788910396 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1826.285118] Lustre: 3647:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 6 previous similar messages [ 1830.368670] LustreError: 3646:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff910449ff2d80 x1875806713903488/t0(0) o250->MGC192.168.202.113@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 [ 1830.470053] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 1830.477471] Lustre: Skipped 4 previous similar messages [ 1832.252641] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1832.348304] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1836.002546] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 1836.005534] Lustre: Skipped 25 previous similar messages [ 1836.672130] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:209 to 0x2c0000400:449) [ 1836.672309] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:209 to 0x280000400:449) [ 1836.695594] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1117 to 0x2c0000401:1441) [ 1836.695799] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1117 to 0x280000401:1441) [ 1839.028490] Lustre: DEBUG MARKER: oleg213-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 [ 1839.715781] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1840.366393] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1844.540395] Lustre: DEBUG MARKER: == replay-single test 111f: DNE: unlink striped dir, uncommit on MDT1, fail MDT1/MDT2 ========================================================== 19:33:33 (1788910413) [ 1847.505681] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1850.589719] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 1851.313048] Lustre: Failing over lustre-MDT0000 [ 1851.490789] Lustre: server umount lustre-MDT0000 complete [ 1852.888720] LustreError: 26135:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788910422 with bad export cookie 10752212430050009386 [ 1852.890643] Lustre: Failing over lustre-MDT0001 [ 1852.893367] LustreError: 26135:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 1853.118538] Lustre: server umount lustre-MDT0001 complete [ 1868.672716] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1868.675945] LDISKFS-fs (dm-0): recovery complete [ 1868.682217] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1868.809494] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 1868.812474] LDISKFS-fs (dm-1): recovery complete [ 1868.822243] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1878.945638] LustreError: 3646:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff910545aa7100 x1875806713940224/t0(0) o250->MGC192.168.202.113@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 [ 1881.180560] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1881.321644] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1881.797822] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:209 to 0x280000400:481) [ 1881.799167] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:209 to 0x2c0000400:481) [ 1881.824304] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1117 to 0x280000401:1473) [ 1881.825616] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1117 to 0x2c0000401:1473) [ 1886.000629] Lustre: DEBUG MARKER: oleg213-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 [ 1886.603125] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1887.212490] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1891.410822] Lustre: DEBUG MARKER: == replay-single test 111g: DNE: unlink striped dir, fail MDT1/MDT2 ========================================================== 19:34:20 (1788910460) [ 1894.709574] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1897.737294] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 1898.486049] Lustre: Failing over lustre-MDT0000 [ 1898.749170] Lustre: server umount lustre-MDT0000 complete [ 1900.156257] LustreError: 26135:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788910470 with bad export cookie 10752212430050011661 [ 1900.157895] Lustre: Failing over lustre-MDT0001 [ 1900.160417] LustreError: 26135:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 1900.380467] Lustre: server umount lustre-MDT0001 complete [ 1916.008407] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1916.009871] LDISKFS-fs (dm-0): recovery complete [ 1916.018214] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1916.029268] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 1916.032100] LDISKFS-fs (dm-1): recovery complete [ 1916.036994] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1926.114764] LustreError: 3646:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff910581d5d500 x1875806713977472/t0(0) o250->MGC192.168.202.113@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 [ 1927.906180] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:209 to 0x2c0000400:513) [ 1927.906180] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:209 to 0x280000400:513) [ 1927.963963] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1117 to 0x280000401:1505) [ 1927.964168] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1117 to 0x2c0000401:1505) [ 1928.426268] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1928.509115] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1933.160596] Lustre: DEBUG MARKER: oleg213-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 [ 1933.888116] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1934.509909] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1938.601239] Lustre: DEBUG MARKER: == replay-single test 112a: DNE: cross MDT rename, fail MDT1 ========================================================== 19:35:07 (1788910507) [ 1939.256593] Lustre: DEBUG MARKER: SKIP: replay-single test_112a needs >= 4 MDTs [ 1940.057483] Lustre: DEBUG MARKER: == replay-single test 112b: DNE: cross MDT rename, fail MDT2 ========================================================== 19:35:08 (1788910508) [ 1940.758312] Lustre: DEBUG MARKER: SKIP: replay-single test_112b needs >= 4 MDTs [ 1941.571444] Lustre: DEBUG MARKER: == replay-single test 112c: DNE: cross MDT rename, fail MDT3 ========================================================== 19:35:10 (1788910510) [ 1942.316283] Lustre: DEBUG MARKER: SKIP: replay-single test_112c needs >= 4 MDTs [ 1943.066644] Lustre: DEBUG MARKER: == replay-single test 112d: DNE: cross MDT rename, fail MDT4 ========================================================== 19:35:11 (1788910511) [ 1943.768117] Lustre: DEBUG MARKER: SKIP: replay-single test_112d needs >= 4 MDTs [ 1944.521243] Lustre: DEBUG MARKER: == replay-single test 112e: DNE: cross MDT rename, fail MDT1 and MDT2 ========================================================== 19:35:13 (1788910513) [ 1945.165284] Lustre: DEBUG MARKER: SKIP: replay-single test_112e needs >= 4 MDTs [ 1945.811356] Lustre: DEBUG MARKER: == replay-single test 112f: DNE: cross MDT rename, fail MDT1 and MDT3 ========================================================== 19:35:14 (1788910514) [ 1946.402971] Lustre: DEBUG MARKER: SKIP: replay-single test_112f needs >= 4 MDTs [ 1947.057418] Lustre: DEBUG MARKER: == replay-single test 112g: DNE: cross MDT rename, fail MDT1 and MDT4 ========================================================== 19:35:15 (1788910515) [ 1947.669620] Lustre: DEBUG MARKER: SKIP: replay-single test_112g needs >= 4 MDTs [ 1948.314538] Lustre: DEBUG MARKER: == replay-single test 112h: DNE: cross MDT rename, fail MDT2 and MDT3 ========================================================== 19:35:17 (1788910517) [ 1948.938783] Lustre: DEBUG MARKER: SKIP: replay-single test_112h needs >= 4 MDTs [ 1949.646221] Lustre: DEBUG MARKER: == replay-single test 112i: DNE: cross MDT rename, fail MDT2 and MDT4 ========================================================== 19:35:18 (1788910518) [ 1950.283269] Lustre: DEBUG MARKER: SKIP: replay-single test_112i needs >= 4 MDTs [ 1951.024442] Lustre: DEBUG MARKER: == replay-single test 112j: DNE: cross MDT rename, fail MDT3 and MDT4 ========================================================== 19:35:19 (1788910519) [ 1951.679403] Lustre: DEBUG MARKER: SKIP: replay-single test_112j needs >= 4 MDTs [ 1952.414426] Lustre: DEBUG MARKER: == replay-single test 112k: DNE: cross MDT rename, fail MDT1,MDT2,MDT3 ========================================================== 19:35:21 (1788910521) [ 1953.111319] Lustre: DEBUG MARKER: SKIP: replay-single test_112k needs >= 4 MDTs [ 1953.952123] Lustre: DEBUG MARKER: == replay-single test 112l: DNE: cross MDT rename, fail MDT1,MDT2,MDT4 ========================================================== 19:35:22 (1788910522) [ 1954.677178] Lustre: DEBUG MARKER: SKIP: replay-single test_112l needs >= 4 MDTs [ 1955.664228] Lustre: DEBUG MARKER: == replay-single test 112m: DNE: cross MDT rename, fail MDT1,MDT3,MDT4 ========================================================== 19:35:24 (1788910524) [ 1956.493312] Lustre: DEBUG MARKER: SKIP: replay-single test_112m needs >= 4 MDTs [ 1957.311273] Lustre: DEBUG MARKER: == replay-single test 112n: DNE: cross MDT rename, fail MDT2,MDT3,MDT4 ========================================================== 19:35:25 (1788910525) [ 1958.014384] Lustre: DEBUG MARKER: SKIP: replay-single test_112n needs >= 4 MDTs [ 1958.849274] Lustre: DEBUG MARKER: == replay-single test 115: failover for create/unlink striped directory ========================================================== 19:35:27 (1788910527) [ 1962.521747] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 1963.823901] Lustre: Failing over lustre-MDT0001 [ 1963.828340] LustreError: 69172:0:(ldlm_resource.c:1207:ldlm_resource_complain()) lustre-MDT0000-osp-MDT0001: namespace resource [0x2000061c1:0x9:0x0].0x3a7a9df7 (ffff910568aff700) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 1963.953931] Lustre: server umount lustre-MDT0001 complete [ 1980.047957] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 1980.049974] LDISKFS-fs (dm-1): recovery complete [ 1980.061620] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1981.828606] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1982.062435] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 1982.065748] Lustre: Skipped 11 previous similar messages [ 1985.529777] Lustre: lustre-MDT0001: Recovery over after 0:03, of 2 clients 2 recovered and 0 were evicted. [ 1985.533336] Lustre: Skipped 11 previous similar messages [ 1985.557060] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:209 to 0x280000400:545) [ 1985.557083] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:209 to 0x2c0000400:545) [ 1987.888762] Lustre: DEBUG MARKER: oleg213-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 1988.561195] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1993.910127] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1994.958333] Lustre: Failing over lustre-MDT0000 [ 1995.098651] Lustre: server umount lustre-MDT0000 complete [ 2010.894639] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2010.896590] LDISKFS-fs (dm-0): recovery complete [ 2010.902720] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2013.228127] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2016.283683] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1117 to 0x280000401:1537) [ 2016.283890] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1117 to 0x2c0000401:1537) [ 2018.562711] Lustre: DEBUG MARKER: oleg213-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2019.438254] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2024.638028] Lustre: DEBUG MARKER: == replay-single test 116a: large update log master MDT recovery ========================================================== 19:36:33 (1788910593) [ 2028.398850] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2028.940740] Lustre: *** cfs_fail_loc=1702, val=0*** [ 2030.044419] Lustre: Failing over lustre-MDT0000 [ 2030.252475] Lustre: server umount lustre-MDT0000 complete [ 2046.616165] LDISKFS-fs (dm-0): 4 truncates cleaned up [ 2046.622589] LDISKFS-fs (dm-0): recovery complete [ 2046.626855] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2048.894350] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2052.141136] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1117 to 0x2c0000401:1569) [ 2052.141266] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1117 to 0x280000401:1569) [ 2054.766516] Lustre: DEBUG MARKER: oleg213-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2055.663324] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2060.655299] Lustre: DEBUG MARKER: == replay-single test 116b: large update log slave MDT recovery ========================================================== 19:37:09 (1788910629) [ 2064.521680] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 2064.993894] Lustre: *** cfs_fail_loc=1702, val=0*** [ 2066.146896] Lustre: Failing over lustre-MDT0001 [ 2066.359775] Lustre: server umount lustre-MDT0001 complete [ 2066.918117] LustreError: 19634:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788910636 with bad export cookie 10752212430050021104 [ 2066.925444] LustreError: 19634:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 2082.312399] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 2082.314166] LDISKFS-fs (dm-1): recovery complete [ 2082.318798] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2084.371114] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2087.941756] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:209 to 0x280000400:577) [ 2087.945207] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:209 to 0x2c0000400:577) [ 2090.398169] Lustre: DEBUG MARKER: oleg213-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 2091.050559] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2095.687926] Lustre: DEBUG MARKER: == replay-single test 117: DNE: cross MDT unlink, fail MDT1 and MDT2 ========================================================== 19:37:44 (1788910664) [ 2096.471682] Lustre: DEBUG MARKER: SKIP: replay-single test_117 needs >= 4 MDTs [ 2097.365584] Lustre: DEBUG MARKER: == replay-single test 118: invalidate osp update will not cause update log corruption ========================================================== 19:37:46 (1788910666) [ 2098.058243] Lustre: *** cfs_fail_loc=1705, val=0*** [ 2102.225783] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2103.269903] Lustre: Failing over lustre-MDT0000 [ 2105.000203] Lustre: lustre-MDT0000: Not available for connect from 192.168.202.13@tcp (stopping) [ 2105.003058] Lustre: Skipped 1 previous similar message [ 2105.471455] Lustre: server umount lustre-MDT0000 complete [ 2121.063870] LDISKFS-fs (dm-0): 3 truncates cleaned up [ 2121.065256] LDISKFS-fs (dm-0): recovery complete [ 2121.069889] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2123.228615] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2126.412124] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1117 to 0x2c0000401:1601) [ 2126.417097] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1117 to 0x280000401:1601) [ 2128.981222] Lustre: DEBUG MARKER: oleg213-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2129.742640] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2134.271467] Lustre: DEBUG MARKER: == replay-single test 119: timeout of normal replay does not cause DNE replay fails ========================================================== 19:38:22 (1788910702) [ 2138.339405] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2139.782075] Lustre: Failing over lustre-MDT0000 [ 2139.937992] Lustre: server umount lustre-MDT0000 complete [ 2146.970070] LDISKFS-fs (dm-0): 3 truncates cleaned up [ 2146.974392] LDISKFS-fs (dm-0): recovery complete [ 2146.984277] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2149.664356] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2151.080263] Lustre: 67603:0:(ldlm_lib.c:2110:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 60, extend: 0 [ 2152.419418] Lustre: 8440:0:(ldlm_lib.c:2110:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 60, extend: 0 [ 2152.425341] LustreError: 79723:0:(ldlm_lib.c:2715:replay_request_or_update()) cfs_fail_timeout id 714 sleeping for 65000ms [ 2155.676292] Lustre: DEBUG MARKER: oleg213-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2217.512202] LustreError: 79723:0:(ldlm_lib.c:2715:replay_request_or_update()) cfs_fail_timeout id 714 awake [ 2217.517641] Lustre: 79723:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 68f8910f-c94c-4643-9680-0ad2348165dc@192.168.202.13@tcp [ 2217.524799] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 2217.527180] Lustre: 79723:0:(ldlm_lib.c:1939:abort_req_replay_queue()) @@@ aborted: req@ffff91044ff64a80 x1875806702067840/t0(81604378628) o36->68f8910f-c94c-4643-9680-0ad2348165dc@192.168.202.13@tcp:202/0 lens 528/0 e 6 to 0 dl 1788910792 ref 1 fl Complete:/204/ffffffff rc 0/-1 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 2217.548212] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 2217.551421] Lustre: 79723:0:(ldlm_lib.c:2110:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 60, extend: 1 [ 2217.561174] Lustre: lustre-MDT0000: Denying connection for new client 68f8910f-c94c-4643-9680-0ad2348165dc (at 192.168.202.13@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 1 evicted) already passed deadline 0:06 [ 2217.570985] Lustre: Skipped 22 previous similar messages [ 2217.608133] Lustre: 79723:0:(ldlm_lib.c:2419:target_recovery_overseer()) lustre-MDT0000 recovery is aborted by hard timeout [ 2217.611893] Lustre: 79723:0:(ldlm_lib.c:2429:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 2217.615217] Lustre: 79723:0:(ldlm_lib.c:2429:target_recovery_overseer()) Skipped 2 previous similar messages [ 2217.622117] Lustre: lustre-MDT0000-osd: cancel update llog [0x200001b70:0x1:0x0] [ 2217.630205] Lustre: lustre-MDT0001-osp-MDT0000: cancel update llog [0x240002b11:0x1:0x0] [ 2217.649025] Lustre: 79723:0:(ldlm_lib.c:2976:target_recovery_thread()) too long recovery - read logs [ 2217.654519] LustreError: dumping log to /tmp/lustre-log.1788910787.79723 [ 2217.723121] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1117 to 0x280000401:1633) [ 2217.723440] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1117 to 0x2c0000401:1633) [ 2225.018910] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 62 sec [ 2233.372538] Lustre: DEBUG MARKER: == replay-single test 120: DNE fail abort should stop both normal and DNE replay ========================================================== 19:40:01 (1788910801) [ 2237.909395] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2242.123043] Lustre: Failing over lustre-MDT0000 [ 2243.239455] Lustre: lustre-MDT0000: Not available for connect from 192.168.202.13@tcp (stopping) [ 2248.358787] LustreError: 66083:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.202.13@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 2248.369950] LustreError: 66083:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 121 previous similar messages [ 2248.391822] Lustre: server umount lustre-MDT0000 complete [ 2257.145869] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2257.148222] LDISKFS-fs (dm-0): recovery complete [ 2257.153558] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2257.359810] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 2257.362902] Lustre: Skipped 15 previous similar messages [ 2257.387660] Lustre: lustre-MDT0000: Aborting client recovery [ 2257.390854] LustreError: 81691:0:(ldlm_lib.c:3029:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 2257.396146] LustreError: 81723:0:(lod_dev.c:511:lod_sub_recovery_thread()) lustre-MDT0001-osp-MDT0000: get update log duration 0, retries 0, failed: rc = -108 [ 2257.398124] Lustre: 81724:0:(ldlm_lib.c:2429:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 2257.406363] Lustre: 81724:0:(ldlm_lib.c:2429:target_recovery_overseer()) Skipped 1 previous similar message [ 2257.414645] Lustre: lustre-MDT0000-osd: cancel update llog [0x200009870:0x3:0x0] [ 2257.423484] Lustre: lustre-MDT0001-osp-MDT0000: cancel update llog [0x2400090a1:0x1:0x0] [ 2257.456295] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1117 to 0x2c0000401:1665) [ 2257.456372] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1117 to 0x280000401:1665) [ 2260.147248] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2262.509069] LustreError: lustre-MDT0000-osp-MDT0001: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 2277.491400] Lustre: DEBUG MARKER: == replay-single test 121: lock replay timed out and race ========================================================== 19:40:45 (1788910845) [ 2279.806915] Lustre: Failing over lustre-MDT0000 [ 2280.172456] Lustre: server umount lustre-MDT0000 complete [ 2284.203624] Lustre: *** cfs_fail_loc=721, val=0*** [ 2284.205760] Lustre: Skipped 9 previous similar messages [ 2287.586604] Lustre: *** cfs_fail_loc=721, val=0*** [ 2287.588294] Lustre: Skipped 1 previous similar message [ 2288.508534] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2288.596981] Lustre: *** cfs_fail_loc=721, val=0*** [ 2288.598646] Lustre: Skipped 9 previous similar messages [ 2290.598581] Lustre: *** cfs_fail_loc=721, val=1*** [ 2290.601833] Lustre: Skipped 74 previous similar messages [ 2292.179275] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2293.758632] Lustre: *** cfs_fail_loc=721, val=1*** [ 2293.763159] Lustre: Skipped 5 previous similar messages [ 2297.824471] Lustre: *** cfs_fail_loc=721, val=1*** [ 2297.829938] Lustre: Skipped 33 previous similar messages [ 2304.705731] Lustre: lustre-MDT0000: Client 68f8910f-c94c-4643-9680-0ad2348165dc (at 192.168.202.13@tcp) reconnected, waiting for 2 clients in recovery for 0:54 [ 2308.064648] Lustre: *** cfs_fail_loc=721, val=1*** [ 2308.066549] Lustre: Skipped 36 previous similar messages [ 2321.069466] Lustre: lustre-MDT0000: Client 68f8910f-c94c-4643-9680-0ad2348165dc (at 192.168.202.13@tcp) reconnected, waiting for 2 clients in recovery for 0:38 [ 2323.939119] Lustre: 3646:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788910863/real 1788910863] req@ffff9105480d2680 x1875806714335104/t0(0) o400->lustre-MDT0000-osp-MDT0001@0@lo:24/4 lens 224/224 e 0 to 1 dl 1788910893 ref 1 fl Rpc:XQr/2c0/ffffffff rc 0/-1 job:'ldlm_lock_repla.0' uid:0 gid:0 projid:4294967295 [ 2323.963446] Lustre: 3646:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 42 previous similar messages [ 2323.969149] Lustre: lustre-MDT0000: Received new MDS connection from 0@lo, keep former export from same NID [ 2323.975806] Lustre: *** cfs_fail_loc=721, val=1*** [ 2323.979316] Lustre: 83141:0:(tgt_handler.c:581:tgt_handle_recovery()) @@@ obsoleted, rq_xid=1875806702208128, exp_last_xid=1875806702209919 req@ffff91054477e300 x1875806702208128/t0(0) o101->68f8910f-c94c-4643-9680-0ad2348165dc@192.168.202.13@tcp:0/0 lens 328/0 e 0 to 0 dl 1788910870 ref 1 fl Complete:/240/ffffffff rc 0/-1 job:'ldlm_lock_repla.0' uid:0 gid:0 projid:4294967295 [ 2324.448771] Lustre: *** cfs_fail_loc=721, val=1*** [ 2324.453439] Lustre: Skipped 71 previous similar messages [ 2337.450039] Lustre: lustre-MDT0000: Client 68f8910f-c94c-4643-9680-0ad2348165dc (at 192.168.202.13@tcp) reconnected, waiting for 2 clients in recovery for 0:22 [ 2352.809337] Lustre: lustre-MDT0000: Client 68f8910f-c94c-4643-9680-0ad2348165dc (at 192.168.202.13@tcp) reconnected, waiting for 2 clients in recovery for 0:06 [ 2354.144876] Lustre: lustre-MDT0000: Received new MDS connection from 0@lo, keep former export from same NID [ 2354.154049] Lustre: *** cfs_fail_loc=721, val=1*** [ 2354.171113] Lustre: 83141:0:(tgt_handler.c:581:tgt_handle_recovery()) @@@ obsoleted, rq_xid=1875806702208000, exp_last_xid=1875806702209919 req@ffff910581b38e00 x1875806702208000/t0(0) o101->68f8910f-c94c-4643-9680-0ad2348165dc@192.168.202.13@tcp:0/0 lens 328/0 e 0 to 0 dl 1788910870 ref 1 fl Complete:/240/ffffffff rc 0/-1 job:'ldlm_lock_repla.0' uid:0 gid:0 projid:4294967295 [ 2357.922624] Lustre: *** cfs_fail_loc=721, val=1*** [ 2357.927017] Lustre: Skipped 120 previous similar messages [ 2369.194292] Lustre: lustre-MDT0000: Client 68f8910f-c94c-4643-9680-0ad2348165dc (at 192.168.202.13@tcp) reconnected, waiting for 2 clients in recovery for 0:05 [ 2384.353589] Lustre: lustre-MDT0000: Received new MDS connection from 0@lo, keep former export from same NID [ 2384.363883] Lustre: *** cfs_fail_loc=721, val=1*** [ 2384.366608] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 2385.586643] Lustre: lustre-MDT0000: Client 68f8910f-c94c-4643-9680-0ad2348165dc (at 192.168.202.13@tcp) reconnected, waiting for 2 clients in recovery for 0:28 [ 2414.563880] Lustre: lustre-MDT0000: Received new MDS connection from 0@lo, keep former export from same NID [ 2414.578432] Lustre: *** cfs_fail_loc=721, val=1*** [ 2417.324341] Lustre: lustre-MDT0000: Client 68f8910f-c94c-4643-9680-0ad2348165dc (at 192.168.202.13@tcp) reconnected, waiting for 2 clients in recovery for 0:28 [ 2417.333819] Lustre: Skipped 1 previous similar message [ 2422.436089] Lustre: *** cfs_fail_loc=721, val=1*** [ 2422.437549] Lustre: Skipped 242 previous similar messages [ 2444.768990] Lustre: lustre-MDT0000: Received new MDS connection from 0@lo, keep former export from same NID [ 2444.780451] Lustre: *** cfs_fail_loc=721, val=1*** [ 2465.448668] 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. [ 2474.976590] Lustre: lustre-MDT0000: Received new MDS connection from 0@lo, keep former export from same NID [ 2474.984324] Lustre: 83141:0:(ldlm_lib.c:2110:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 2474.989256] Lustre: 83141:0:(ldlm_lib.c:2110:extend_recovery_timer()) Skipped 25 previous similar messages [ 2474.992356] Lustre: 83141:0:(ldlm_lib.c:2419:target_recovery_overseer()) lustre-MDT0000 recovery is aborted by hard timeout [ 2474.995125] Lustre: 83141:0:(ldlm_lib.c:2419:target_recovery_overseer()) Skipped 1 previous similar message [ 2474.998210] Lustre: 83141:0:(ldlm_lib.c:2429:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 2475.001066] Lustre: 83141:0:(ldlm_lib.c:2429:target_recovery_overseer()) Skipped 2 previous similar messages [ 2475.003820] Lustre: 83141:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 68f8910f-c94c-4643-9680-0ad2348165dc@192.168.202.13@tcp [ 2475.009052] Lustre: 83141:0:(genops.c:1601:class_disconnect_stale_exports()) Skipped 2 previous similar messages [ 2475.012125] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 2475.013879] Lustre: Skipped 1 previous similar message [ 2475.016461] LustreError: 83141:0:(ldlm_lib.c:1959:abort_lock_replay_queue()) @@@ aborted: req@ffff9105498b5c00 x1875806702214528/t0(0) o101->68f8910f-c94c-4643-9680-0ad2348165dc@192.168.202.13@tcp:0/0 lens 328/0 e 0 to 0 dl 1788910918 ref 1 fl Complete:/240/ffffffff rc 0/-1 job:'ldlm_lock_repla.0' uid:0 gid:0 projid:4294967295 [ 2475.033232] Lustre: lustre-MDT0000-osd: cancel update llog [0x20000a040:0x1:0x0] [ 2475.048910] Lustre: lustre-MDT0001-osp-MDT0000: cancel update llog [0x2400090a2:0x1:0x0] [ 2475.074593] Lustre: 83141:0:(ldlm_lib.c:2976:target_recovery_thread()) too long recovery - read logs [ 2475.079803] LustreError: dumping log to /tmp/lustre-log.1788911044.83141 [ 2475.138594] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1117 to 0x2c0000401:1697) [ 2475.138743] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1667 to 0x280000401:1697) [ 2476.000354] Lustre: lustre-MDT0000-osp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 2476.003607] Lustre: Skipped 46 previous similar messages [ 2487.118106] Lustre: DEBUG MARKER: == replay-single test 130a: DoM file create (setstripe) replay ========================================================== 19:44:15 (1788911055) [ 2491.349834] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2492.503684] Lustre: Failing over lustre-MDT0000 [ 2492.654440] Lustre: server umount lustre-MDT0000 complete [ 2495.458446] 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 [ 2495.464120] Lustre: Skipped 45 previous similar messages [ 2510.109550] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2510.111359] LDISKFS-fs (dm-0): recovery complete [ 2510.121722] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2510.180651] LustreError: MGC192.168.202.113@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2510.185179] LustreError: Skipped 8 previous similar messages [ 2510.345277] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 2510.354780] Lustre: Skipped 15 previous similar messages [ 2512.625718] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2515.530443] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1667 to 0x280000401:1729) [ 2515.530935] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1117 to 0x2c0000401:1729) [ 2518.870846] Lustre: DEBUG MARKER: oleg213-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2519.738670] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2525.102293] Lustre: DEBUG MARKER: == replay-single test 130b: DoM file create (inherited) replay ========================================================== 19:44:53 (1788911093) [ 2529.464473] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2530.581677] Lustre: Failing over lustre-MDT0000 [ 2530.726166] Lustre: server umount lustre-MDT0000 complete [ 2530.784404] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 2530.788484] LustreError: Skipped 11 previous similar messages [ 2547.718553] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2547.720148] LDISKFS-fs (dm-0): recovery complete [ 2547.725848] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2549.838344] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2553.397191] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1117 to 0x2c0000401:1761) [ 2553.398201] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1667 to 0x280000401:1761) [ 2556.106073] Lustre: DEBUG MARKER: oleg213-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2556.807408] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2561.678153] Lustre: DEBUG MARKER: == replay-single test 131a: DoM file write lock replay === 19:45:30 (1788911130) [ 2565.923781] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2567.124303] Lustre: Failing over lustre-MDT0000 [ 2567.277669] Lustre: server umount lustre-MDT0000 complete [ 2583.421714] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2583.425173] LDISKFS-fs (dm-0): recovery complete [ 2583.429960] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2584.238275] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 2584.244301] Lustre: Skipped 8 previous similar messages [ 2585.354483] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2588.680456] Lustre: lustre-MDT0000: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 2588.684529] Lustre: Skipped 8 previous similar messages [ 2588.698626] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1667 to 0x280000401:1793) [ 2588.698629] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1117 to 0x2c0000401:1793) [ 2591.222375] Lustre: DEBUG MARKER: oleg213-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2592.023940] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2596.610995] Lustre: DEBUG MARKER: SKIP: replay-single test_131b skipping excluded test 131b [ 2597.472920] Lustre: DEBUG MARKER: == replay-single test 132a: PFL new component instantiate replay ========================================================== 19:46:06 (1788911166) [ 2600.908106] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2601.981805] Lustre: Failing over lustre-MDT0000 [ 2602.167103] Lustre: server umount lustre-MDT0000 complete [ 2618.177420] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2618.179546] LDISKFS-fs (dm-0): recovery complete [ 2618.183937] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2620.310026] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2623.510279] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1795 to 0x2c0000401:1825) [ 2623.510558] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1796 to 0x280000401:1825) [ 2625.891450] Lustre: DEBUG MARKER: oleg213-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2626.640956] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2631.578396] Lustre: DEBUG MARKER: == replay-single test 133: check resend of ongoing requests for lwp during failover ========================================================== 19:46:40 (1788911200) [ 2634.321204] Lustre: *** cfs_fail_loc=123, val=2147483648*** [ 2634.323198] Lustre: Skipped 264 previous similar messages [ 2636.206713] Lustre: Failing over lustre-MDT0000 [ 2636.343687] Lustre: server umount lustre-MDT0000 complete [ 2649.762641] Lustre: lustre-MDT0001: Client 4ec02880-225d-4406-ba42-7d08ca4ec3d5 (at 192.168.202.13@tcp) reconnecting [ 2650.555915] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2652.751611] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2656.234737] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000300000400-0x0000000340000400]:1:mdt [ 2656.242157] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000300000400-0x0000000340000400]:1:mdt] [ 2656.272469] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1796 to 0x280000401:1857) [ 2656.274790] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1795 to 0x2c0000401:1857) [ 2659.485740] Lustre: DEBUG MARKER: == replay-single test 134: replay creation of a file created in a pool ========================================================== 19:47:08 (1788911228) [ 2668.921486] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2669.904579] Lustre: Failing over lustre-MDT0000 [ 2670.126642] Lustre: server umount lustre-MDT0000 complete [ 2685.919531] LDISKFS-fs (dm-0): 4 truncates cleaned up [ 2685.922058] LDISKFS-fs (dm-0): recovery complete [ 2685.932948] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2687.877224] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2691.586931] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1795 to 0x2c0000401:1889) [ 2691.586939] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1796 to 0x280000401:1889) [ 2693.728724] Lustre: DEBUG MARKER: oleg213-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2694.357309] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2705.185891] Lustre: DEBUG MARKER: == replay-single test 135: Server failure in lock replay phase ========================================================== 19:47:53 (1788911273) [ 2709.722384] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 2710.658475] Lustre: Failing over lustre-OST0000 [ 2710.718835] Lustre: server umount lustre-OST0000 complete [ 2713.236267] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing load_module ../libcfs/libcfs/libcfs [ 2717.919588] LDISKFS-fs (dm-2): 3 truncates cleaned up [ 2717.921604] LDISKFS-fs (dm-2): recovery complete [ 2717.926809] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2719.760856] Lustre: *** cfs_fail_loc=32d, val=20*** [ 2719.763236] Lustre: Skipped 1 previous similar message [ 2720.384473] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2723.356680] Lustre: DEBUG MARKER: oleg213-client.virtnet: executing wait_import_state_mount REPLAY_LOCKS osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 2724.006391] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in REPLAY_LOCKS state after 0 sec [ 2724.874113] Lustre: Failing over lustre-OST0000 [ 2724.883789] LustreError: 97518:0:(ldlm_lib.c:3029:target_stop_recovery_thread()) lustre-OST0000: Aborting recovery [ 2724.887786] Lustre: 96737:0:(ldlm_lib.c:2429:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 2724.891951] LustreError: 96737:0:(ofd_obd.c:1325:ofd_iocontrol()) lustre-OST0000: iocontrol from 'tgt_recover_0' cmd=c00866c1 _IOWR('f', 193, 8) unrecognized: rc = -25 [ 2724.959491] Lustre: server umount lustre-OST0000 complete [ 2736.096068] Lustre: 3646:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788911289/real 1788911289] req@ffff910565999180 x1875806714610432/t0(0) o400->lustre-OST0000-osc-MDT0001@0@lo:28/4 lens 224/224 e 0 to 1 dl 1788911305 ref 1 fl Rpc:XQr/2c0/ffffffff rc 0/-1 job:'ldlm_lock_repla.0' uid:0 gid:0 projid:4294967295 [ 2736.106407] Lustre: 3646:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 5 previous similar messages [ 2738.091939] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing load_module ../libcfs/libcfs/libcfs [ 2740.799469] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2743.552703] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2746.339573] Lustre: lustre-OST0000: Not available for connect from 0@lo (stopping) [ 2746.342704] Lustre: Skipped 6 previous similar messages [ 2751.378533] Lustre: server umount lustre-OST0000 complete [ 2767.328501] Lustre: lustre-OST0001 is waiting for obd_unlinked_exports more than 8 seconds. The obd refcount = 3. Is it stuck? [ 2767.402684] Lustre: server umount lustre-OST0001 complete [ 2770.585532] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2771.875371] LustreError: lustre-OST0000-osc-MDT0000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 2771.882362] LustreError: lustre-OST0000-osc-MDT0001: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 2772.927643] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2776.098175] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2778.018252] LustreError: lustre-OST0001-osc-MDT0000: This client was evicted by lustre-OST0001; in progress operations using this service will fail. [ 2778.023475] LustreError: lustre-OST0001-osc-MDT0001: This client was evicted by lustre-OST0001; in progress operations using this service will fail. [ 2778.872877] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2784.320124] Lustre: DEBUG MARKER: == replay-single test 136: MDS to disconnect all OSPs first, then cleanup ldlm ========================================================== 19:49:13 (1788911353) [ 2784.990671] Lustre: DEBUG MARKER: SKIP: replay-single test_136 needs > 2 MDTs [ 2785.806514] Lustre: DEBUG MARKER: == replay-single test 137a: DNE: create under striped dir, fail MDT1 ========================================================== 19:49:14 (1788911354) [ 2789.565932] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2790.557040] Lustre: Failing over lustre-MDT0000 [ 2790.778465] Lustre: server umount lustre-MDT0000 complete [ 2806.937336] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2806.938487] LDISKFS-fs (dm-0): recovery complete [ 2806.943606] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2808.994613] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2812.431197] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1911 to 0x280000401:1953) [ 2812.431618] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1795 to 0x2c0000401:1921) [ 2814.714918] Lustre: DEBUG MARKER: oleg213-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2815.311292] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2819.940905] Lustre: DEBUG MARKER: == replay-single test 137b: DNE: create under striped dir, fail MDT2 ========================================================== 19:49:48 (1788911388) [ 2823.361944] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 2824.246496] Lustre: Failing over lustre-MDT0001 [ 2824.400217] Lustre: server umount lustre-MDT0001 complete [ 2839.395884] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 2839.397598] LDISKFS-fs (dm-1): recovery complete [ 2839.402085] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2841.161875] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2844.670622] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:580 to 0x2c0000400:609) [ 2844.670650] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:579 to 0x280000400:609) [ 2846.691785] Lustre: DEBUG MARKER: oleg213-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 2847.242602] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2850.888264] Lustre: DEBUG MARKER: == replay-single test 137c: DNE: create under striped dir, fail MDT1/MDT2 ========================================================== 19:50:19 (1788911419) [ 2853.821528] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2856.878658] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 2857.663815] Lustre: Failing over lustre-MDT0001 [ 2857.885066] Lustre: server umount lustre-MDT0001 complete [ 2859.486213] Lustre: Failing over lustre-MDT0000 [ 2859.711910] Lustre: server umount lustre-MDT0000 complete [ 2875.967596] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 2875.969206] LDISKFS-fs (dm-1): recovery complete [ 2875.983094] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2875.992487] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2875.994699] LDISKFS-fs (dm-0): recovery complete [ 2876.000325] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2876.169614] LustreError: 99455:0:(ldlm_lib.c:1190: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. [ 2876.186305] LustreError: 99455:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 168 previous similar messages [ 2876.222326] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 2876.225285] Lustre: Skipped 13 previous similar messages [ 2878.332856] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2878.368306] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2880.521873] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1911 to 0x280000401:1985) [ 2880.522984] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1795 to 0x2c0000401:1953) [ 2880.558798] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:580 to 0x2c0000400:641) [ 2880.558862] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:579 to 0x280000400:641) [ 2883.212632] Lustre: DEBUG MARKER: oleg213-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 [ 2883.978615] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2884.541948] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2888.797419] Lustre: DEBUG MARKER: == replay-single test 160: mdt.recovery_reconnect_histogram testing ========================================================== 19:50:57 (1788911457) [ 2891.826572] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2892.593022] Lustre: Failing over lustre-MDT0000 [ 2892.702912] Lustre: server umount lustre-MDT0000 complete [ 2908.031967] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2908.034187] LDISKFS-fs (dm-0): recovery complete [ 2908.038445] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2910.103444] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2913.286417] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1911 to 0x280000401:2017) [ 2913.286682] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1795 to 0x2c0000401:1985) [ 2915.552589] Lustre: DEBUG MARKER: oleg213-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2916.223162] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2922.289150] Lustre: DEBUG MARKER: == replay-single test 200: Dropping one OBD_PING should not cause disconnect ========================================================== 19:51:31 (1788911491) [ 2922.958129] Lustre: DEBUG MARKER: SKIP: replay-single test_200 Need remote client [ 2923.754975] Lustre: DEBUG MARKER: == replay-single test 201: MDT umount cascading disconnects timeouts ========================================================== 19:51:32 (1788911492) [ 2925.611826] LustreError: 107054:0:(tgt_handler.c:1143:tgt_disconnect()) cfs_fail_timeout id 245 sleeping for 8000ms [ 2933.624131] LustreError: 107054:0:(tgt_handler.c:1143:tgt_disconnect()) cfs_fail_timeout id 245 awake [ 2933.631210] Lustre: Failing over lustre-MDT0001 [ 2933.634595] LustreError: 99456:0:(tgt_handler.c:1143:tgt_disconnect()) cfs_fail_timeout id 245 sleeping for 8000ms [ 2933.638093] LustreError: 99456:0:(tgt_handler.c:1143:tgt_disconnect()) Skipped 2 previous similar messages [ 2933.729504] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 2933.732128] Lustre: Skipped 13 previous similar messages [ 2938.018480] LustreError: 99446:0:(tgt_handler.c:1143:tgt_disconnect()) cfs_fail_timeout id 245 sleeping for 8000ms [ 2938.022518] LustreError: 99446:0:(tgt_handler.c:1143:tgt_disconnect()) Skipped 1 previous similar message [ 2941.640119] LustreError: 99444:0:(tgt_handler.c:1143:tgt_disconnect()) cfs_fail_timeout id 245 awake [ 2941.677517] Lustre: server umount lustre-MDT0001 complete [ 2945.373813] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2946.032139] LustreError: 99627:0:(tgt_handler.c:1143:tgt_disconnect()) cfs_fail_timeout id 245 awake [ 2946.032139] LustreError: 99446:0:(tgt_handler.c:1143:tgt_disconnect()) cfs_fail_timeout id 245 awake [ 2946.032151] LustreError: 99446:0:(tgt_handler.c:1143:tgt_disconnect()) Skipped 2 previous similar messages [ 2946.036468] LustreError: 99627:0:(tgt_handler.c:1143:tgt_disconnect()) Skipped 2 previous similar messages [ 2947.358073] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2950.657855] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:580 to 0x2c0000400:673) [ 2950.658250] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:579 to 0x280000400:673) [ 2951.549865] Lustre: DEBUG MARKER: == replay-single test 202: pfl replay should recovery layout generation ========================================================== 19:52:00 (1788911520) [ 2955.570643] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2956.399536] Lustre: Failing over lustre-MDT0000 [ 2956.581373] Lustre: server umount lustre-MDT0000 complete [ 2971.379685] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2971.381150] LDISKFS-fs (dm-0): recovery complete [ 2971.385900] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2973.162472] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2976.790383] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1987 to 0x2c0000401:2017) [ 2976.790397] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1911 to 0x280000401:2049) [ 2978.789513] Lustre: DEBUG MARKER: oleg213-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2979.365347] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2983.414751] Lustre: DEBUG MARKER: == replay-single test 203: resend can hit original request ========================================================== 19:52:32 (1788911552) [ 2983.997603] LustreError: 107055:0:(mdt_handler.c:2126:mdt_getattr_name_lock()) cfs_fail_timeout id 2403 sleeping for 2000ms [ 2986.080164] LustreError: 107055:0:(mdt_handler.c:2126:mdt_getattr_name_lock()) cfs_fail_timeout id 2403 awake [ 2986.084215] Lustre: 107055:0:(service.c:2628:ptlrpc_server_handle_request()) @@@ pause req after reply req@ffff9105754d8a80 x1875806702491008/t0(0) o101->4ec02880-225d-4406-ba42-7d08ca4ec3d5@192.168.202.13@tcp:258/0 lens 592/1888 e 0 to 0 dl 1788911603 ref 1 fl Complete:/600/0 rc 0/0 job:'stat.0' uid:0 gid:0 projid:0 [ 2989.152193] Lustre: 107055:0:(service.c:2630:ptlrpc_server_handle_request()) @@@ continue req@ffff9105754d8a80 x1875806702491008/t0(0) o101->4ec02880-225d-4406-ba42-7d08ca4ec3d5@192.168.202.13@tcp:258/0 lens 592/1888 e 0 to 0 dl 1788911603 ref 1 fl Complete:/600/0 rc 0/0 job:'stat.0' uid:0 gid:0 projid:0 [ 2989.553217] Lustre: DEBUG MARKER: == replay-single test complete, duration 2750 sec ======== 19:52:38 (1788911558) [ 2990.230154] Lustre: DEBUG MARKER: === replay-single: start cleanup 19:52:38 (1788911558) === [ 2992.867500] Lustre: DEBUG MARKER: === replay-single: finish cleanup 19:52:41 (1788911561) === [ 2993.702338] Lustre: Failing over lustre-MDT0000 [ 2993.841698] Lustre: server umount lustre-MDT0000 complete [ 2996.708553] LustreError: 6503:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788911566 with bad export cookie 10752212430050062705 [ 2996.712686] LustreError: 6503:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 3010.760491] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3012.539180] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3016.214808] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2051 to 0x280000401:2081) [ 3016.214967] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2019 to 0x2c0000401:2049) [ 3018.326764] Lustre: DEBUG MARKER: oleg213-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3018.926787] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3021.426606] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3021.429695] Lustre: Skipped 4 previous similar messages [ 3029.560989] Lustre: server umount lustre-MDT0000 complete [ 3033.121868] LustreError: 6504:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788911602 with bad export cookie 10752212430050070958 [ 3033.126959] LustreError: 6504:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 3033.262798] Lustre: server umount lustre-MDT0001 complete [ 3046.231825] Lustre: server umount lustre-OST0000 complete [ 3060.075853] Lustre: server umount lustre-OST0001 complete [ 3067.129641] Lustre: DEBUG MARKER: oleg213-server.virtnet: executing unload_modules_local [ 3068.444995] Key type lgssc unregistered [ 3068.616865] LNet: 117959:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 3068.626321] LNetError: 117959:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 3068.642800] LNet: Removed LNI 192.168.202.113@tcp [ 3069.111171] Key type .llcrypt unregistered [ 3069.112840] Key type ._llcrypt unregistered