[ 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.16.2-1.fc38 04/01/2014 [ 0.000000] Hypervisor detected: KVM [ 0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00 [ 0.000000] kvm-clock: using sched offset of 497767970 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 0x000f5b30-0x000f5b3f] [ 0.000000] RAMDISK: [mem 0xbcc54000-0xbffbffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F5950 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE1BB7 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE1A53 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 001A13 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE1AC7 000090 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE1B57 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE1B8F 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe1a53-0xbffe1ac6] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe1a52] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe1ac7-0xbffe1b56] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe1b57-0xbffe1b8e] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe1b8f-0xbffe1bb6] [ 0.000000] No NUMA configuration found [ 0.000000] Faking a node at [mem 0x0000000000000000-0x0000000146dfffff] [ 0.000000] NODE_DATA(0) allocated [mem 0x1465a3000-0x1465cdfff] [ 0.000000] Reserving 256MB of memory at 2752MB for crashkernel (System RAM: 4205MB) [ 0.000000] Zone ranges: [ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.000000] DMA32 [mem 0x0000000001000000-0x00000000ffffffff] [ 0.000000] Normal [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Device empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff] [ 0.000000] node 0: [mem 0x0000000000100000-0x00000000bffcdfff] [ 0.000000] node 0: [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Zeroed struct page in unavailable ranges: 4756 pages [ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x0000000146dfffff] [ 0.000000] ACPI: PM-Timer IO Port: 0x608 [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) [ 0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) [ 0.000000] Using ACPI (MADT) for SMP configuration information [ 0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000] TSC deadline timer available [ 0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs [ 0.000000] kvm-guest: KVM setup pv remote TLB flush [ 0.000000] kvm-guest: setup PV sched yield [ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff] [ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff] [ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff] [ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff] [ 0.000000] PM: Registered nosave memory: [mem 0xbffce000-0xbfffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xc0000000-0xfeffbfff] [ 0.000000] PM: Registered nosave memory: [mem 0xfeffc000-0xfeffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xff000000-0xfffbffff] [ 0.000000] PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff] [ 0.000000] [mem 0xc0000000-0xfeffbfff] available for PCI devices [ 0.000000] Booting paravirtualized kernel on KVM [ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns [ 0.000000] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1 [ 0.000000] percpu: Embedded 63 pages/cpu s221184 r8192 d28672 u524288 [ 0.000000] kvm-guest: PV spinlocks enabled [ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1059606 [ 0.000000] Policy zone: Normal [ 0.000000] Kernel command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] Specific versions of hardware are certified with Red Hat Enterprise Linux 8. Please see the list of hardware certified with Red Hat Enterprise Linux 8 at https://catalog.redhat.com. [ 0.000000] audit: disabled (until reboot) [ 0.000000] software IO TLB: area num 4. [ 0.000000] Memory: 2829652K/4306352K available (18435K kernel code, 11221K rwdata, 7248K rodata, 2908K init, 18040K bss, 524580K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] ftrace: allocating 41240 entries in 162 pages [ 0.000000] ftrace: allocated 162 pages with 3 groups [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] rcu: RCU event tracing is enabled. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ 0.000000] rcu: RCU callback double-/use-after-free debug enabled. [ 0.000000] Rude variant of Tasks RCU enabled. [ 0.000000] Tracing variant of Tasks RCU enabled. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 0.000000] NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16 [ 0.000000] random: get_random_bytes called from start_kernel+0x622/0x9a8 with crng_init=0 [ 0.001000] Console: colour *CGA 80x25 [ 0.001000] printk: console [ttyS1] enabled [ 0.001000] ACPI: Core revision 20220331 [ 0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.001014] APIC: Switch to symmetric I/O mode setup [ 0.002377] x2apic enabled [ 0.003010] Switched APIC routing to physical x2apic. [ 0.004015] kvm-guest: setup PV IPIs [ 0.006764] ..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.007024] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.008016] pid_max: default: 32768 minimum: 301 [ 0.009149] LSM: Security Framework initializing [ 0.010047] Yama: becoming mindful. [ 0.011031] SELinux: Initializing. [ 0.012087] *** VALIDATE selinux *** [ 0.020577] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.025901] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.026177] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.027143] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.028173] *** VALIDATE tmpfs *** [ 0.030537] *** VALIDATE proc *** [ 0.032278] *** VALIDATE cgroup *** [ 0.033015] *** VALIDATE cgroup2 *** [ 0.034345] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.036166] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.037025] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.038041] Spectre V2 : User space: Vulnerable [ 0.039023] Speculative Store Bypass: Vulnerable [ 0.042398] debug: unmapping init [mem 0xffffffffb2a59000-0xffffffffb2a60fff] [ 0.045000] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.045789] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.046032] ... version: 2 [ 0.047022] ... bit width: 48 [ 0.048017] ... generic registers: 4 [ 0.049015] ... value mask: 0000ffffffffffff [ 0.050019] ... max period: 00007fffffffffff [ 0.051017] ... fixed-purpose events: 3 [ 0.052019] ... event mask: 000000070000000f [ 0.053407] rcu: Hierarchical SRCU implementation. [ 0.055727] smp: Bringing up secondary CPUs ... [ 0.056735] x86: Booting SMP configuration: [ 0.057040] .... node #0, CPUs: #1 #2 #3 [ 0.067572] smp: Brought up 1 node, 4 CPUs [ 0.069018] smpboot: Max logical packages: 1 [ 0.070018] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.146036] node 0 deferred pages initialised in 74ms [ 0.149021] devtmpfs: initialized [ 0.150340] x86/mm: Memory block size: 128MB [ 0.152778] gcov: version magic: 0x41383552 [ 0.155651] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.159160] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.162512] pinctrl core: initialized pinctrl subsystem [ 0.164238] [ 0.164791] ************************************************************* [ 0.167017] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.169014] ** ** [ 0.171018] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.174016] ** ** [ 0.176015] ** This means that this kernel is built to expose internal ** [ 0.178020] ** IOMMU data structures, which may compromise security on ** [ 0.181018] ** your system. ** [ 0.183017] ** ** [ 0.185019] ** If you see this message and you are not debugging the ** [ 0.187018] ** kernel, report this immediately to your vendor! ** [ 0.189024] ** ** [ 0.191019] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.194018] ************************************************************* [ 0.196807] NET: Registered protocol family 16 [ 0.198501] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.201087] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.204102] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.207580] cpuidle: using governor menu [ 0.208578] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.211104] PCI: Using configuration type 1 for base access [ 0.213159] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.222115] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.225054] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.229118] cryptd: max_cpu_qlen set to 1000 [ 0.231617] ACPI: Added _OSI(Module Device) [ 0.233019] ACPI: Added _OSI(Processor Device) [ 0.234015] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.236018] ACPI: Added _OSI(Processor Aggregator Device) [ 0.240641] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.249682] ACPI: Interpreter enabled [ 0.252087] ACPI: PM: (supports S0 S3 S4 S5) [ 0.253013] ACPI: Using IOAPIC for interrupt routing [ 0.255185] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.259466] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.270031] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.272058] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.275029] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.278117] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.283284] acpiphp: Slot [2] registered [ 0.284174] acpiphp: Slot [3] registered [ 0.286135] acpiphp: Slot [4] registered [ 0.287120] acpiphp: Slot [5] registered [ 0.289216] acpiphp: Slot [6] registered [ 0.291175] acpiphp: Slot [7] registered [ 0.292182] acpiphp: Slot [8] registered [ 0.294174] acpiphp: Slot [9] registered [ 0.296272] acpiphp: Slot [10] registered [ 0.298163] acpiphp: Slot [11] registered [ 0.299136] acpiphp: Slot [12] registered [ 0.301132] acpiphp: Slot [13] registered [ 0.302115] acpiphp: Slot [14] registered [ 0.304152] acpiphp: Slot [15] registered [ 0.305131] acpiphp: Slot [16] registered [ 0.307174] acpiphp: Slot [17] registered [ 0.309132] acpiphp: Slot [18] registered [ 0.310130] acpiphp: Slot [19] registered [ 0.312146] acpiphp: Slot [20] registered [ 0.313130] acpiphp: Slot [21] registered [ 0.315140] acpiphp: Slot [22] registered [ 0.316178] acpiphp: Slot [23] registered [ 0.318192] acpiphp: Slot [24] registered [ 0.319128] acpiphp: Slot [25] registered [ 0.321138] acpiphp: Slot [26] registered [ 0.322188] acpiphp: Slot [27] registered [ 0.324163] acpiphp: Slot [28] registered [ 0.326124] acpiphp: Slot [29] registered [ 0.327108] acpiphp: Slot [30] registered [ 0.329136] acpiphp: Slot [31] registered [ 0.330069] PCI host bridge to bus 0000:00 [ 0.332026] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.334033] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.337032] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.340038] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.343043] pci_bus 0000:00: root bus resource [mem 0x180000000-0x1ffffffff window] [ 0.346038] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.348242] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.352791] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.357738] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.367759] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.372398] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.374025] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.376024] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.378024] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.381567] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.385079] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.387058] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.390740] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.396022] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.408027] pci 0000:00:02.0: reg 0x20: [mem 0xfebe4000-0xfebe7fff 64bit pref] [ 0.413798] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.418826] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.426040] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.433029] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.451024] pci 0000:00:05.0: reg 0x20: [mem 0xfebe8000-0xfebebfff 64bit pref] [ 0.463000] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.472021] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.478024] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.497030] pci 0000:00:06.0: reg 0x20: [mem 0xfebec000-0xfebeffff 64bit pref] [ 0.509665] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.515024] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.522034] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.538030] pci 0000:00:07.0: reg 0x20: [mem 0xfebf0000-0xfebf3fff 64bit pref] [ 0.548925] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.556023] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.560022] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.580024] pci 0000:00:08.0: reg 0x20: [mem 0xfebf4000-0xfebf7fff 64bit pref] [ 0.592901] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.605024] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.612025] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.631029] pci 0000:00:09.0: reg 0x20: [mem 0xfebf8000-0xfebfbfff 64bit pref] [ 0.645347] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.651028] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.655023] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.670023] pci 0000:00:0a.0: reg 0x20: [mem 0xfebfc000-0xfebfffff 64bit pref] [ 0.682226] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.684467] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.686479] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.689437] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.691282] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.695163] iommu: Default domain type: Passthrough [ 0.697505] SCSI subsystem initialized [ 0.699166] ACPI: bus type USB registered [ 0.701124] usbcore: registered new interface driver usbfs [ 0.703079] usbcore: registered new interface driver hub [ 0.704081] usbcore: registered new device driver usb [ 0.706184] pps_core: LinuxPPS API ver. 1 registered [ 0.707011] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.710140] PTP clock support registered [ 0.712132] EDAC MC: Ver: 3.0.0 [ 0.714122] PCI: Using ACPI for IRQ routing [ 0.715710] NetLabel: Initializing [ 0.717023] NetLabel: domain hash size = 128 [ 0.718023] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.720122] NetLabel: unlabeled traffic allowed by default [ 0.723200] vgaarb: loaded [ 0.725345] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.728025] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.734435] clocksource: Switched to clocksource kvm-clock [ 0.842616] VFS: Disk quotas dquot_6.6.0 [ 0.843943] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.846426] *** VALIDATE ramfs *** [ 0.847718] *** VALIDATE hugetlbfs *** [ 0.849620] pnp: PnP ACPI init [ 0.851985] pnp: PnP ACPI: found 6 devices [ 0.869465] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.872604] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.874062] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.875635] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.877875] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.880405] pci_bus 0000:00: resource 8 [mem 0x180000000-0x1ffffffff window] [ 0.883029] NET: Registered protocol family 2 [ 0.885119] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.889411] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.892983] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.900148] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.905087] TCP: Hash tables configured (established 65536 bind 65536) [ 0.908857] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.912867] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.916189] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.920099] NET: Registered protocol family 1 [ 0.922856] RPC: Registered named UNIX socket transport module. [ 0.924961] RPC: Registered udp transport module. [ 0.926843] RPC: Registered tcp transport module. [ 0.928493] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.930588] NET: Registered protocol family 44 [ 0.932372] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.934375] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.936634] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.939130] PCI: CLS 0 bytes, default 64 [ 0.941627] Unpacking initramfs... [ 2.361525] debug: unmapping init [mem 0xffff927c7cc54000-0xffff927c7ffbffff] [ 2.366039] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.367757] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.371151] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 2.867421] Initialise system trusted keyrings [ 2.868748] Key type blacklist registered [ 2.870165] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.878554] zbud: loaded [ 2.881550] *** VALIDATE nfs *** [ 2.882510] *** VALIDATE nfs4 *** [ 2.885187] pstore: using deflate compression [ 2.887879] Platform Keyring initialized [ 3.027371] NET: Registered protocol family 38 [ 3.029108] Key type asymmetric registered [ 3.030152] Asymmetric key parser 'x509' registered [ 3.031531] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 3.033588] io scheduler mq-deadline registered [ 3.034665] io scheduler kyber registered [ 3.035860] io scheduler bfq registered [ 3.037163] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 3.039167] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 3.041089] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 3.044157] ACPI: Power Button [PWRF] [ 3.135389] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 3.223358] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 3.408925] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 3.506329] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 3.690587] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 3.726873] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.757410] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.762347] Non-volatile memory driver v1.3 [ 3.763654] Linux agpgart interface v0.103 [ 3.795097] virtio_blk virtio1: [vda] 133848 512-byte logical blocks (68.5 MB/65.4 MiB) [ 3.798075] vda: detected capacity change from 0 to 68530176 [ 3.812926] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.816095] vdb: detected capacity change from 0 to 1073741824 [ 3.832235] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.835158] vdc: detected capacity change from 0 to 2621440000 [ 3.849091] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.851869] vdd: detected capacity change from 0 to 2621440000 [ 3.865887] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.868621] vde: detected capacity change from 0 to 4294967296 [ 3.882713] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.885546] vdf: detected capacity change from 0 to 4294967296 [ 3.895941] libphy: Fixed MDIO Bus: probed [ 3.904440] usbcore: registered new interface driver usbserial_generic [ 3.907071] usbserial: USB Serial support registered for generic [ 3.909272] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.913638] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.915549] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.917857] mousedev: PS/2 mouse device common for all mice [ 3.920713] rtc_cmos 00:05: RTC can wake from S4 [ 3.923646] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.925247] rtc_cmos 00:05: registered as rtc0 [ 3.929362] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.932167] intel_pstate: CPU model not supported [ 3.935185] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.939156] hid: raw HID events driver (C) Jiri Kosina [ 3.942555] usbcore: registered new interface driver usbhid [ 3.944672] usbhid: USB HID core driver [ 3.946292] drop_monitor: Initializing network drop monitor service [ 3.946738] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.948133] Initializing XFRM netlink socket [ 3.951921] NET: Registered protocol family 10 [ 3.954627] Segment Routing with IPv6 [ 3.955963] NET: Registered protocol family 17 [ 3.958034] mpls_gso: MPLS GSO support [ 3.964080] RAS: Correctable Errors collector initialized. [ 3.966060] AVX version of gcm_enc/dec engaged. [ 3.967633] AES CTR mode by8 optimization enabled [ 4.039304] sched_clock: Marking stable (4039281430, 0)->(4989007211, -949725781) [ 4.043135] registered taskstats version 1 [ 4.044970] Loading compiled-in X.509 certificates [ 4.046958] zswap: loaded using pool lzo/zbud [ 4.076285] Key type big_key registered [ 4.087623] Key type encrypted registered [ 4.089670] ima: No TPM chip found, activating TPM-bypass! [ 4.092921] ima: Allocated hash algorithm: sha1 [ 4.094749] ima: No architecture policies found [ 4.096528] evm: Initialising EVM extended attributes: [ 4.098368] evm: security.selinux [ 4.099487] evm: security.ima [ 4.100592] evm: security.capability [ 4.101897] evm: HMAC attrs: 0x1 [ 4.104638] rtc_cmos 00:05: setting system clock to 2025-11-17 00:33:31 UTC (1763339611) [ 4.110959] debug: unmapping init [mem 0xffffffffb3a03000-0xffffffffb3bfffff] [ 4.114214] debug: unmapping init [mem 0xffffffffb2782000-0xffffffffb2a58fff] [ 4.123144] Write protecting the kernel read-only data: 28672k [ 4.126570] debug: unmapping init [mem 0xffffffffb0e03000-0xffffffffb0ffffff] [ 4.129548] debug: unmapping init [mem 0xffffffffb1714000-0xffffffffb17fffff] [ 4.171541] 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.178701] systemd[1]: Detected virtualization kvm. [ 4.180475] systemd[1]: Detected architecture x86-64. [ 4.182330] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 4.207170] systemd[1]: No hostname configured. [ 4.209160] systemd[1]: Set hostname to . [ 4.211201] random: systemd: uninitialized urandom read (16 bytes read) [ 4.213588] systemd[1]: Initializing machine ID from random generator. [ 4.273823] random: ln: uninitialized urandom read (6 bytes read) [ 4.368154] random: systemd: uninitialized urandom read (16 bytes read) [ 4.371112] systemd[1]: Reached target Slices. [ OK ] Reached target Slices. [ 4.375356] systemd[1]: Reached target Timers. [ OK ] Reached target Timers. [ 4.379565] systemd[1]: Started Dispatch Password Requests to Console Directory Watch. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Listening on Journal Socket. [ OK ] Reached target Local File Systems. Starting Apply Kernel Variables... Starting Create list of required st…ce nodes for the current kernel... Starting Create Volatile Files and Directories... [ OK ] Reached target Swap. [ OK ] Started Memstrack Anylazing Service. [ OK ] Reached target Initrd Root Device. [ OK ] Reached target Paths. Starting Setup Virtual Console... [ OK ] Listening on udev Control Socket. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Listening on Journal Socket (/dev/log). Starting Journal Service... [ OK ] Listening on udev Kernel Socket. [ OK ] Reached target Sockets. [ OK ] Started Apply Kernel Variables. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Setup Virtual Console. Starting dracut cmdline hook... Starting Create Static Device Nodes in /dev... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started Journal Service. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 5.046178] device-mapper: uevent: version 1.0.3 [ 5.048682] device-mapper: ioctl: 4.46.0-ioctl (2022-02-22) initialised: dm-devel@redhat.com [ OK ] Started dracut pre-udev hook. Starting udev Kernel Device Manager... [ OK ] Started udev Kernel Device Manager. Starting dracut pre-trigger hook... [ OK ] Started dracut pre-trigger hook. Starting udev Coldplug all Devices... Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting dracut initqueue hook... [ 5.759087] virtio_net virtio0 ens2: renamed from eth0 [ 5.770314] random: fast init done [ 5.879906] scsi host0: ata_piix [ 5.938429] scsi host1: ata_piix [ 5.941392] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 5.944238] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 9.716091] dracut-initqueue[581]: RTNETLINK answers: File exists [ 10.607849] random: crng init done [ 10.609433] random: 7 urandom warning(s) missed due to ratelimiting Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Mounting /sysroot... [ 11.174966] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Timers. [ OK ] Stopped target Remote File Systems. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Paths. [ OK ] Stopped target Sockets. [ OK ] Stopped target Slices. [ OK ] Stopped target System Initialization. [ OK ] Stopped target Swap. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. Stopping udev Kernel Device Manager... [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Stopped 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... [ 12.377851] printk: systemd: 26 output lines suppressed due to ratelimiting [ 12.664794] SELinux: Disabled at runtime. [ 12.721061] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 12.728901] systemd[1]: Detected virtualization kvm. [ 12.730670] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 13.278818] systemd[1]: initrd-switch-root.service: Succeeded. [ 13.282280] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 13.287698] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 13.292918] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 13.297265] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 13.304859] systemd[1]: Starting Journal Service... Starting Journal Service... [ 13.309417] systemd[1]: Created slice User and Session Slice. [ OK ] Created slice User and Session Slice. [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Listening on Process Core Dump Socket. Mounting POSIX Message Queue File System... Mounting Huge Pages File System... [ OK ] Reached target rpc_pipefs.target. Activating swap /dev/disk/by-label/SWAP... [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Listening on udev Control Socket. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Started Forw[ 13.397217] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS ard Password Requests to Wall Directory Watch. [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd Root File System. [ OK ] Stopped target Initrd File Systems. [ OK ] Started Dispatch Password Requests to Console Directory Watch. Mounting Kernel Debug File System... [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Reached target RPC Port Mapper. [ OK ] Listening on udev Kernel Socket. [ OK ] Created slice system-getty.slice. Starting udev Coldplug all Devices... [ OK ] Reached target Slices. [ OK ] Reached target Paths. Starting Remount Root and Kernel File Systems... [ OK ] Reached target Local Encrypted Volumes. Starting Apply Kernel Variables... [ OK ] Started Journal Service. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Mounted Huge Pages File System. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Mounted Kernel Debug File System. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Started Apply Kernel Variables. Starting Configure read-only root support... Starting Create Static Device Nodes in /dev... [ OK ] Reached target Swap. Starting Flush Journal to Persistent Storage... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. Starting udev Kernel Device Manager... [ OK ] Reached target Local File Systems (Pre). Mounting /home/green/git/lustre-release... Mounting /mnt... [ OK ] Mounted /mnt. [ OK ] Started udev Coldplug all Devices. [ 13.846407] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 14.218313] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 14.391914] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 14.460983] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 14.481369] EDAC sbridge: Ver: 1.1.2 [ 16.096484] Key type dns_resolver registered [ 16.406697] NFS: Registering the id_resolver key type [ 16.408843] Key type id_resolver registered [ 16.410441] Key type id_legacy registered [ OK ] Started Configure read-only root support. [ OK ] Reached target Local File Systems. Starting Create Volatile Files and Directories... Starting Rebuild Dynamic Linker Cache... Starting Mark the need to relabel after reboot... Starting Load/Save Random Seed... [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Load/Save Random Seed. [ OK ] Started Create Volatile Files and Directories. Starting RPC Bind... Starting Update UTMP about System Boot/Shutdown... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Started dnf makecache --timer. [ OK ] Reached target Timers. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Started irqbalance daemon. [ OK ] Started D-Bus System Message Bus. Starting Network Manager... Starting Restore /run/initramfs on shutdown... Starting Login Service... [ OK ] Reached target sshd-keygen.target. [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Login Service. [ OK ] Started Network Manager. [ OK ] Reached target Network. Starting Dynamic System Tuning Daemon... Starting OpenSSH server daemon... Starting GSSAPI Proxy Daemon... Starting Network Manager Wait Online... Starting Hostname Service... [ OK ] Started OpenSSH server daemon. [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... [ OK ] Started Permit User Sessions. [ OK ] Started Serial Getty on ttyS1. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Getty on tty1. [ OK ] Reached target Login Prompts. [ OK ] Started Command Scheduler. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting Notify NFS peers of a restart... Starting System Logging Service... Starting Crash recovery kernel arming... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Starting Authorization Manager... [ OK ] Started Authorization Manager. [ OK ] Started Dynamic System Tuning Daemon. [ OK ] Reached target Multi-User System. [ OK ] Reached target Graphical Interface. Starting Update UTMP about System Runlevel Changes... [ OK ] Started Update UTMP about System Runlevel Changes. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg429-server login: [ 51.882932] libcfs: loading out-of-tree module taints kernel. [ 51.911716] Key type ._llcrypt registered [ 51.913300] Key type .llcrypt registered [ 51.975927] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_hostid [ 66.499798] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing load_modules_local [ 67.948932] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 67.958551] alg: No test for adler32 (adler32-zlib) [ 69.321416] Lustre: Lustre: Build Version: 2.16.61_49_g8566d6d [ 70.039674] LNet: Added LNI 192.168.204.129@tcp [8/256/0/180] [ 71.752457] Key type lgssc registered [ 73.293763] Lustre: Echo OBD driver; http://www.lustre.org/ [ 86.765317] hrtimer: interrupt took 3306487 ns [ 89.730449] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 90.721726] LDISKFS-fs (vdc): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 97.702579] LDISKFS-fs (vdd): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 104.128354] LDISKFS-fs (vde): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 111.030635] LDISKFS-fs (vdf): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 124.997881] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing load_modules_local [ 139.000991] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 139.051712] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 139.084945] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 140.346218] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 140.375925] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 140.488107] Lustre: lustre-MDT0000: new disk, initializing [ 140.605386] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 140.623231] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 144.890125] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 157.475542] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 157.527102] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 157.579178] Lustre: 6508:0:(mgs_llog.c:1346:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 157.606941] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 157.611661] Lustre: Skipped 1 previous similar message [ 157.689435] Lustre: lustre-MDT0001: new disk, initializing [ 157.759665] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 157.793327] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 157.797885] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 161.296995] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 165.942761] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 173.710447] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 173.762255] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 173.926594] Lustre: lustre-OST0000: new disk, initializing [ 173.928635] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 173.986481] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 178.407956] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 181.792851] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 181.804586] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 181.926320] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 191.678704] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 191.772542] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 191.861194] Lustre: lustre-OST0001: new disk, initializing [ 191.868408] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 191.936658] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 197.000803] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 199.709786] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 199.724577] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 199.794956] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 206.985876] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 214.809285] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 224.530411] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing check_logdir /tmp/testlogs/ [ 228.113257] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing yml_node [ 232.749627] Lustre: DEBUG MARKER: Client: 2.16.61.49 [ 234.893888] Lustre: DEBUG MARKER: MDS: 2.16.61.49 [ 237.199868] Lustre: DEBUG MARKER: OSS: 2.16.61.49 [ 239.097479] Lustre: DEBUG MARKER: -----============= acceptance-small: replay-single ============----- Sun Nov 16 19:37:24 EST 2025 [ 255.641505] Lustre: DEBUG MARKER: excepting tests: 110f 131b 59 36 [ 257.435432] Lustre: DEBUG MARKER: === replay-single: start setup 19:37:43 (1763339863) === [ 260.595355] Lustre: DEBUG MARKER: oleg429-client.virtnet: executing check_config_client /mnt/lustre [ 278.773753] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 282.496026] Lustre: 13187:0:(mgs_llog.c:1346:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 286.215662] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 292.404593] Lustre: DEBUG MARKER: === replay-single: finish setup 19:38:17 (1763339897) === [ 296.152715] Lustre: DEBUG MARKER: == replay-single test 100a: DNE: create striped dir, drop update rep from MDT1, fail MDT1 ========================================================== 19:38:21 (1763339901) [ 297.398497] Lustre: *** cfs_fail_loc=1701, val=2147483648*** [ 297.400702] LustreError: 6518:0:(ldlm_lib.c:3324:target_send_reply_msg()) @@@ dropping reply req@ffff927bc44f8700 x1848995665258368/t4294967300(0) o1000->lustre-MDT0000-mdtlov_UUID@0@lo:420/0 lens 264/4320 e 0 to 0 dl 1763339915 ref 1 fl Interpret:/200/0 rc 0/0 job:'osp_up1-0.0' uid:0 gid:0 projid:4294967295 [ 299.174659] Lustre: Failing over lustre-MDT0001 [ 299.283612] LustreError: 13713:0:(obd_class.h:479:obd_check_dev()) Device 27 not setup [ 299.411210] Lustre: server umount lustre-MDT0001 complete [ 302.051919] 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 [ 305.324823] LustreError: 6515:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0001: not available for connect from 192.168.204.29@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 305.337240] LustreError: 6515:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 5 previous similar messages [ 307.172579] LustreError: 6518:0:(ldlm_lib.c:1179: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. [ 307.199854] LustreError: 6518:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 2 previous similar messages [ 310.433210] LustreError: 6512:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0001: not available for connect from 192.168.204.29@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 312.811970] Lustre: 7879:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763339904/real 1763339904] req@ffff927bc44fad80 x1848995665258368/t0(0) o1000->lustre-MDT0001-osp-MDT0000@0@lo:24/4 lens 264/4320 e 0 to 1 dl 1763339920 ref 2 fl Rpc:XQr/200/ffffffff rc 0/-1 job:'osp_up1-0.0' uid:0 gid:0 projid:4294967295 [ 315.558831] LustreError: 13829:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0001: not available for connect from 192.168.204.29@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 315.566305] LustreError: 13829:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 3 previous similar messages [ 317.500243] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 317.744211] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 318.986904] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 321.095861] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 323.057206] Lustre: lustre-MDT0001-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 323.082956] Lustre: lustre-MDT0001: Recovery over after 0:05, of 2 clients 2 recovered and 0 were evicted. [ 327.858686] Lustre: DEBUG MARKER: oleg429-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 329.439298] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 338.014946] Lustre: DEBUG MARKER: == replay-single test 100b: DNE: create striped dir, fail MDT0 ========================================================== 19:39:04 (1763339944) [ 339.262792] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 339.268418] LustreError: 8803:0:(ldlm_lib.c:3324:target_send_reply_msg()) @@@ dropping reply req@ffff927bc369c380 x1848995648422272/t4294967361(0) o36->fdb43a2f-e000-4410-9082-8623578c23d8@192.168.204.29@tcp:501/0 lens 560/536 e 0 to 0 dl 1763339996 ref 1 fl Interpret:/200/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 340.580842] Lustre: Failing over lustre-MDT0000 [ 340.757305] LustreError: 14984:0:(obd_class.h:479:obd_check_dev()) Device 28 not setup [ 340.762137] LustreError: 14984:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 340.901280] Lustre: server umount lustre-MDT0000 complete [ 343.520936] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 343.522094] 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 [ 343.524699] LustreError: 8803:0:(ldlm_lib.c:1179: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. [ 343.524712] LustreError: 8803:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 3 previous similar messages [ 343.563855] Lustre: Skipped 5 previous similar messages [ 353.762072] LustreError: 6518:0:(ldlm_lib.c:1179: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. [ 353.777166] LustreError: 6518:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 12 previous similar messages [ 358.858270] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 358.884733] Lustre: 3649:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763339950/real 1763339950] req@ffff927bc369f800 x1848995665294080/t0(0) o400->MGC192.168.204.129@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1763339966 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 358.931100] LustreError: MGC192.168.204.129@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 369.130911] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x55f9c0109cac5e8c [ 369.134971] Lustre: MGC192.168.204.129@tcp: Connection restored to 0@lo (at 0@lo) [ 369.139264] Lustre: Skipped 2 previous similar messages [ 369.309120] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 370.835592] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 372.314640] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 374.761411] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 374.797126] Lustre: lustre-MDT0000: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 374.814040] Lustre: 8803:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff927bc539dc00 x1848995648422272/t4294967361(0) o36->fdb43a2f-e000-4410-9082-8623578c23d8@192.168.204.29@tcp:537/0 lens 560/2880 e 0 to 0 dl 1763340032 ref 1 fl Interpret:/202/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 374.841782] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:6 to 0x280000401:33) [ 374.844527] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:6 to 0x2c0000401:33) [ 378.397848] Lustre: DEBUG MARKER: oleg429-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 379.798404] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 388.155136] Lustre: DEBUG MARKER: == replay-single test 100c: DNE: create striped dir, abort_recov_mdt mds2 ========================================================== 19:39:54 (1763339994) [ 395.478636] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 397.382672] Lustre: Failing over lustre-MDT0001 [ 397.538412] LustreError: 16629:0:(obd_class.h:479:obd_check_dev()) Device 21 not setup [ 397.543900] LustreError: 16629:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 397.621574] Lustre: server umount lustre-MDT0001 complete [ 399.847687] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 399.858172] 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 [ 399.889944] LustreError: 6519:0:(ldlm_lib.c:1179: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. [ 399.915562] LustreError: 6519:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 15 previous similar messages [ 408.015712] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 408.017046] LDISKFS-fs (dm-1): recovery complete [ 408.029267] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 408.318156] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 408.353752] Lustre: lustre-MDT0001: Aborting MDT recovery [ 408.357792] LustreError: 17297:0:(lod_dev.c:510:lod_sub_recovery_thread()) lustre-MDT0000-osp-MDT0001: get update log duration 0, retries 0, failed: rc = -108 [ 410.408710] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 411.336141] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 413.686386] Lustre: lustre-MDT0001-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 413.689900] Lustre: Skipped 3 previous similar messages [ 413.777772] Lustre: lustre-MDT0001-osd: cancel update llog [0x240000400:0x1:0x0] [ 413.795758] Lustre: lustre-MDT0000-osp-MDT0001: cancel update llog [0x200000401:0x1:0x0] [ 413.827021] Lustre: lustre-MDT0001: Recovery over after 0:03, of 2 clients 2 recovered and 0 were evicted. [ 413.864584] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:46 to 0x280000400:65) [ 413.869553] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:46 to 0x2c0000400:65) [ 425.525971] Lustre: Failing over lustre-MDT0001 [ 425.645978] LustreError: 17873:0:(obd_class.h:479:obd_check_dev()) Device 21 not setup [ 425.651583] LustreError: 17873:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 425.720275] Lustre: server umount lustre-MDT0001 complete [ 429.026701] 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 [ 429.038618] Lustre: Skipped 4 previous similar messages [ 434.147286] LustreError: 8803:0:(ldlm_lib.c:1179: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. [ 434.167989] LustreError: 8803:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 14 previous similar messages [ 444.020369] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 444.496202] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 445.609139] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 448.791550] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 449.514330] Lustre: lustre-MDT0001-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 449.524501] Lustre: Skipped 2 previous similar messages [ 449.553987] Lustre: lustre-MDT0001: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 449.600027] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:70 to 0x2c0000400:97) [ 449.603374] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:70 to 0x280000400:97) [ 455.523588] Lustre: DEBUG MARKER: oleg429-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 457.105298] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 466.223492] Lustre: DEBUG MARKER: == replay-single test 100d: DNE: cancel update logs upon recovery abort ========================================================== 19:41:11 (1763340071) [ 484.738101] Lustre: Failing over lustre-MDT0000 [ 485.016530] LustreError: 19260:0:(obd_class.h:479:obd_check_dev()) Device 22 not setup [ 485.022349] LustreError: 19260:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 485.206698] Lustre: server umount lustre-MDT0000 complete [ 485.347356] Lustre: lustre-MDT0000-lwp-OST0000: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 485.373553] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 495.672567] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 495.835864] LustreError: MGC192.168.204.129@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 496.244095] Lustre: lustre-MDT0000: Aborting client recovery [ 496.246321] LustreError: 19709:0:(ldlm_lib.c:2982:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 496.258484] LustreError: 19740:0:(lod_dev.c:510:lod_sub_recovery_thread()) lustre-MDT0000-osd: get update log duration 0, retries 0, failed: rc = -108 [ 496.273099] Lustre: 19742:0:(ldlm_lib.c:2385:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 496.299237] LustreError: 19740:0:(lod_dev.c:510:lod_sub_recovery_thread()) Skipped 1 previous similar message [ 496.322319] Lustre: 19742:0:(genops.c:1618:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client fdb43a2f-e000-4410-9082-8623578c23d8@ [ 496.337878] Lustre: lustre-MDT0000: disconnecting 2 stale clients [ 496.353979] Lustre: lustre-MDT0000-osd: cancel update llog [0x200000400:0x1:0x0] [ 496.379238] Lustre: lustre-MDT0001-osp-MDT0000: cancel update llog [0x240000401:0x1:0x0] [ 496.478967] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:44 to 0x280000401:65) [ 496.481053] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:44 to 0x2c0000401:65) [ 501.230069] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 501.249318] Lustre: Skipped 2 previous similar messages [ 501.254837] LustreError: lustre-MDT0000-osp-MDT0001: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 501.392399] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 521.038544] Lustre: DEBUG MARKER: == replay-single test 100e: DNE: create striped dir on MDT0 and MDT1, fail MDT0, MDT1 ========================================================== 19:42:07 (1763340127) [ 528.336432] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 534.773406] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 536.544779] Lustre: Failing over lustre-MDT0000 [ 536.738933] LustreError: 21360:0:(obd_class.h:479:obd_check_dev()) Device 22 not setup [ 536.748813] LustreError: 21360:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 536.829280] Lustre: server umount lustre-MDT0000 complete [ 537.057299] 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 [ 537.070509] LustreError: 14505:0:(ldlm_lib.c:1179: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. [ 537.077276] Lustre: Skipped 5 previous similar messages [ 537.096341] LustreError: 14505:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 22 previous similar messages [ 539.955253] LustreError: 9475:0:(ldlm_lockd.c:2563:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1763340147 with bad export cookie 6195193940005401830 [ 539.957543] LustreError: MGC192.168.204.129@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 539.958062] Lustre: Failing over lustre-MDT0001 [ 539.971158] LustreError: 9475:0:(ldlm_lockd.c:2563:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 540.291917] Lustre: server umount lustre-MDT0001 complete [ 561.427634] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 561.429710] LDISKFS-fs (dm-0): recovery complete [ 561.456638] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 561.523185] LDISKFS-fs (dm-1): 7 truncates cleaned up [ 561.526411] LDISKFS-fs (dm-1): recovery complete [ 561.546753] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 565.021943] Lustre: lustre-MDT0001-lwp-OST0001: Connection to lustre-MDT0001 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 565.032720] Lustre: Skipped 2 previous similar messages [ 565.153515] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 565.156896] Lustre: Skipped 1 previous similar message [ 565.363754] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_connect to node 0@lo failed: rc = -114 [ 566.380465] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 568.961430] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 569.425803] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 570.853549] Lustre: lustre-MDT0001-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 570.872335] Lustre: Skipped 3 previous similar messages [ 571.475124] Lustre: lustre-MDT0001: Recovery over after 0:05, of 2 clients 2 recovered and 0 were evicted. [ 571.527856] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:70 to 0x2c0000400:129) [ 571.528180] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:70 to 0x280000400:129) [ 578.837501] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:44 to 0x2c0000401:97) [ 578.842973] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:44 to 0x280000401:97) [ 582.241243] Lustre: DEBUG MARKER: oleg429-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 583.715383] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 585.092927] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 592.617368] Lustre: DEBUG MARKER: == replay-single test 101: Shouldn't reassign precreated objs to other files after recovery ========================================================== 19:43:18 (1763340198) [ 597.475131] Lustre: 3647:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763340149/real 1763340149] req@ffff927bc6168a80 x1848995665639936/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1763340204 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 598.189708] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 599.521878] Lustre: 3650:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763340151/real 1763340151] req@ffff927bc6168380 x1848995665640064/t0(0) o400->lustre-MDT0001-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1763340206 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 599.536145] Lustre: 3650:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 604.640305] Lustre: 3650:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763340157/real 1763340157] req@ffff927bc6168700 x1848995665640832/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1763340212 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 604.672671] Lustre: 3650:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 4 previous similar messages [ 617.952530] Lustre: 3647:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763340170/real 1763340170] req@ffff927cf6d2ad80 x1848995665641856/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1763340225 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 618.004499] Lustre: 3647:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 4 previous similar messages [ 626.507549] Lustre: Failing over lustre-MDT0000 [ 626.711953] LustreError: 24325:0:(obd_class.h:479:obd_check_dev()) Device 27 not setup [ 626.715798] LustreError: 24325:0:(obd_class.h:479:obd_check_dev()) Skipped 15 previous similar messages [ 626.847447] Lustre: server umount lustre-MDT0000 complete [ 628.193478] 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 [ 628.205083] Lustre: Skipped 2 previous similar messages [ 637.299472] LDISKFS-fs (dm-0): 4 truncates cleaned up [ 637.301718] LDISKFS-fs (dm-0): recovery complete [ 637.310975] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 637.370345] LustreError: MGC192.168.204.129@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 637.593804] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 637.596704] Lustre: lustre-MDT0000: Aborting client recovery [ 637.598591] LustreError: 24971:0:(ldlm_lib.c:2982:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 637.607111] Lustre: 25004:0:(ldlm_lib.c:2385:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 637.613125] Lustre: 25004:0:(ldlm_lib.c:2385:target_recovery_overseer()) Skipped 2 previous similar messages [ 637.615486] LustreError: 25003:0:(lod_dev.c:510:lod_sub_recovery_thread()) lustre-MDT0001-osp-MDT0000: get update log duration 1, retries 0, failed: rc = -108 [ 637.627899] Lustre: 25004:0:(genops.c:1618:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client lustre-MDT0001-mdtlov_UUID@ [ 637.649192] Lustre: 25004:0:(genops.c:1618:class_disconnect_stale_exports()) Skipped 1 previous similar message [ 637.656563] Lustre: lustre-MDT0000: disconnecting 2 stale clients [ 637.668700] Lustre: lustre-MDT0000-osd: cancel update llog [0x2000013a0:0x1:0x0] [ 637.677299] Lustre: lustre-MDT0001-osp-MDT0000: cancel update llog [0x240001b71:0x1:0x0] [ 637.714302] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:44 to 0x280000401:641) [ 637.715922] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:641) [ 641.694466] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 643.050401] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 643.064519] Lustre: Skipped 5 previous similar messages [ 643.073504] LustreError: lustre-MDT0000-osp-MDT0001: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 728.886763] Lustre: DEBUG MARKER: == replay-single test 102a: check resend (request lost) with multiple modify RPCs in flight ========================================================== 19:45:34 (1763340334) [ 730.389310] Lustre: *** cfs_fail_loc=159, val=0*** [ 730.394662] Lustre: Skipped 3 previous similar messages [ 785.132710] Lustre: lustre-MDT0000: Client fdb43a2f-e000-4410-9082-8623578c23d8 (at 192.168.204.29@tcp) reconnecting [ 792.334601] Lustre: DEBUG MARKER: == replay-single test 102b: check resend (reply lost) with multiple modify RPCs in flight ========================================================== 19:46:38 (1763340398) [ 793.708392] Lustre: *** cfs_fail_loc=15a, val=0*** [ 793.716608] Lustre: Skipped 3 previous similar messages [ 848.579261] Lustre: lustre-MDT0001: Client fdb43a2f-e000-4410-9082-8623578c23d8 (at 192.168.204.29@tcp) reconnecting [ 848.602535] Lustre: 22745:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff927cc12ad880 x1848995651396864/t21474836523(0) o36->fdb43a2f-e000-4410-9082-8623578c23d8@192.168.204.29@tcp:255/0 lens 488/3152 e 0 to 0 dl 1763340505 ref 1 fl Interpret:/202/0 rc 0/0 job:'chmod.0' uid:0 gid:0 projid:4294967295 [ 848.653355] Lustre: 22745:0:(mdt_recovery.c:102:mdt_req_from_lrd()) Skipped 6 previous similar messages [ 856.582380] Lustre: DEBUG MARKER: == replay-single test 102c: check replay w/o reconstruction with multiple mod RPCs in flight ========================================================== 19:47:42 (1763340462) [ 863.442609] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 864.502056] Lustre: *** cfs_fail_loc=15a, val=0*** [ 864.510321] Lustre: Skipped 3 previous similar messages [ 867.940426] Lustre: Failing over lustre-MDT0000 [ 868.102728] LustreError: 26967:0:(obd_class.h:479:obd_check_dev()) Device 27 not setup [ 868.105688] LustreError: 26967:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 868.275660] Lustre: server umount lustre-MDT0000 complete [ 868.337673] 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 [ 868.342566] Lustre: Skipped 1 previous similar message [ 868.345279] LustreError: 22745:0:(ldlm_lib.c:1179: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. [ 868.369626] LustreError: 22745:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 16 previous similar messages [ 884.178249] Lustre: 3650:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763340475/real 1763340475] req@ffff927bc66e7480 x1848995666226944/t0(0) o400->MGC192.168.204.129@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1763340491 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 884.212518] Lustre: 3650:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 884.218635] LustreError: MGC192.168.204.129@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 889.083515] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 889.085572] LDISKFS-fs (dm-0): recovery complete [ 889.094889] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 894.680764] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 894.683039] Lustre: Skipped 2 previous similar messages [ 894.724517] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 894.739761] Lustre: Skipped 2 previous similar messages [ 895.646884] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 895.652754] Lustre: Skipped 1 previous similar message [ 898.018398] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 900.076639] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 900.092501] Lustre: Skipped 3 previous similar messages [ 900.148173] Lustre: lustre-MDT0000: Recovery over after 0:05, of 2 clients 2 recovered and 0 were evicted. [ 900.152075] Lustre: Skipped 1 previous similar message [ 900.179188] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1149 to 0x280000401:1185) [ 900.180989] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1149 to 0x2c0000401:1185) [ 904.418054] Lustre: DEBUG MARKER: oleg429-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 906.090377] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 914.745146] Lustre: DEBUG MARKER: == replay-single test 102d: check replay [ 916.295828] Lustre: *** cfs_fail_loc=15a, val=0*** [ 916.297120] Lustre: Skipped 6 previous similar messages [ 920.780440] Lustre: Failing over lustre-MDT0001 [ 921.137506] Lustre: server umount lustre-MDT0001 complete [ 925.664830] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 939.193595] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 939.419242] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 941.452382] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 942.704902] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 944.653543] Lustre: lustre-MDT0001: Recovery over after 0:03, of 2 clients 2 recovered and 0 were evicted. [ 944.669283] Lustre: 25844:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff927bc54b5500 x1848995651462272/t21474836572(0) o36->fdb43a2f-e000-4410-9082-8623578c23d8@192.168.204.29@tcp:352/0 lens 496/3152 e 0 to 0 dl 1763340602 ref 1 fl Interpret:/202/0 rc 0/0 job:'chmod.0' uid:0 gid:0 projid:4294967295 [ 944.696930] Lustre: 25844:0:(mdt_recovery.c:102:mdt_req_from_lrd()) Skipped 6 previous similar messages [ 944.697806] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:137 to 0x280000400:161) [ 944.698055] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:137 to 0x2c0000400:161) [ 949.950531] Lustre: DEBUG MARKER: oleg429-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 951.455045] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 959.651826] Lustre: DEBUG MARKER: == replay-single test 103: Check otr_next_id overflow ==== 19:49:25 (1763340565) [ 963.924671] Lustre: Failing over lustre-MDT0000 [ 964.133509] LustreError: 29811:0:(obd_class.h:479:obd_check_dev()) Device 27 not setup [ 964.146336] LustreError: 29811:0:(obd_class.h:479:obd_check_dev()) Skipped 15 previous similar messages [ 964.286201] Lustre: server umount lustre-MDT0000 complete [ 981.483585] Lustre: 3649:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763340572/real 1763340572] req@ffff927cc57e4000 x1848995666293248/t0(0) o400->MGC192.168.204.129@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1763340588 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 981.497166] LustreError: MGC192.168.204.129@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 982.142303] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 990.688877] LustreError: 3646:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff927cc57e4e00 x1848995666301184/t0(0) o250->MGC192.168.204.129@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 [ 991.036469] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 992.317489] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 994.924848] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 996.369449] Lustre: lustre-MDT0000: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 996.420285] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1201 to 0x2c0000401:1217) [ 996.423511] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1201 to 0x280000401:1217) [ 1001.885148] Lustre: DEBUG MARKER: oleg429-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1003.531439] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1010.977927] Lustre: DEBUG MARKER: == replay-single test 110a: DNE: create striped dir, fail MDT1 ========================================================== 19:50:16 (1763340616) [ 1018.290473] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1020.161349] Lustre: Failing over lustre-MDT0000 [ 1020.356105] Lustre: server umount lustre-MDT0000 complete [ 1021.921354] 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 [ 1021.923064] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1021.944806] Lustre: Skipped 12 previous similar messages [ 1038.305968] LustreError: MGC192.168.204.129@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1041.376391] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1041.379166] LDISKFS-fs (dm-0): recovery complete [ 1041.384941] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1048.767059] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1051.698930] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1054.185191] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 1054.192356] Lustre: Skipped 10 previous similar messages [ 1054.268288] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1201 to 0x280000401:1249) [ 1054.276688] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1201 to 0x2c0000401:1249) [ 1058.061730] Lustre: DEBUG MARKER: oleg429-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1059.648669] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1068.223208] Lustre: DEBUG MARKER: == replay-single test 110b: DNE: create striped dir, fail MDT1 and client ========================================================== 19:51:13 (1763340673) [ 1075.535233] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1077.622391] Lustre: Failing over lustre-MDT0000 [ 1077.949814] Lustre: server umount lustre-MDT0000 complete [ 1079.778061] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1096.032847] Lustre: 3649:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763340687/real 1763340687] req@ffff927cc719bb80 x1848995666373504/t0(0) o400->MGC192.168.204.129@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1763340703 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1096.055417] Lustre: 3649:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 1096.065782] LustreError: MGC192.168.204.129@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1097.807192] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1097.809705] LDISKFS-fs (dm-0): recovery complete [ 1097.820204] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1106.736025] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1110.875044] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1112.033613] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 1112.056134] Lustre: Skipped 1 previous similar message [ 1118.724484] Lustre: DEBUG MARKER: oleg429-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1121.291122] Lustre: lustre-MDT0000: Denying connection for new client e04ea87b-8373-4c63-8817-d78b52f4ea39 (at 192.168.204.29@tcp), waiting for 2 known clients (0 recovered, 1 in progress, and 0 evicted) to recover in 1:00 [ 1126.560827] Lustre: lustre-MDT0000: Denying connection for new client e04ea87b-8373-4c63-8817-d78b52f4ea39 (at 192.168.204.29@tcp), waiting for 2 known clients (0 recovered, 1 in progress, and 0 evicted) to recover in 0:55 [ 1131.682429] Lustre: lustre-MDT0000: Denying connection for new client e04ea87b-8373-4c63-8817-d78b52f4ea39 (at 192.168.204.29@tcp), waiting for 2 known clients (0 recovered, 1 in progress, and 0 evicted) to recover in 0:50 [ 1136.797150] Lustre: lustre-MDT0000: Denying connection for new client e04ea87b-8373-4c63-8817-d78b52f4ea39 (at 192.168.204.29@tcp), waiting for 2 known clients (0 recovered, 1 in progress, and 0 evicted) to recover in 0:45 [ 1141.920200] Lustre: lustre-MDT0000: Denying connection for new client e04ea87b-8373-4c63-8817-d78b52f4ea39 (at 192.168.204.29@tcp), waiting for 2 known clients (0 recovered, 1 in progress, and 0 evicted) to recover in 0:40 [ 1152.166674] Lustre: lustre-MDT0000: Denying connection for new client e04ea87b-8373-4c63-8817-d78b52f4ea39 (at 192.168.204.29@tcp), waiting for 2 known clients (0 recovered, 1 in progress, and 0 evicted) to recover in 0:29 [ 1152.187874] Lustre: Skipped 1 previous similar message [ 1172.651536] Lustre: lustre-MDT0000: Denying connection for new client e04ea87b-8373-4c63-8817-d78b52f4ea39 (at 192.168.204.29@tcp), waiting for 2 known clients (0 recovered, 1 in progress, and 0 evicted) to recover in 0:09 [ 1172.657930] Lustre: Skipped 3 previous similar messages [ 1182.000693] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 1182.010531] Lustre: 33919:0:(genops.c:1618:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client fdb43a2f-e000-4410-9082-8623578c23d8@ [ 1182.034482] Lustre: 33919:0:(genops.c:1618:class_disconnect_stale_exports()) Skipped 1 previous similar message [ 1182.040938] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 1182.067780] Lustre: lustre-MDT0000: Recovery over after 1:10, of 2 clients 1 recovered and 1 was evicted. [ 1182.079198] Lustre: Skipped 1 previous similar message [ 1182.147045] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1201 to 0x280000401:1281) [ 1182.150629] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1201 to 0x2c0000401:1281) [ 1192.525716] Lustre: DEBUG MARKER: == replay-single test 110c: DNE: create striped dir, fail MDT2 ========================================================== 19:53:18 (1763340798) [ 1199.194299] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 1201.233976] Lustre: Failing over lustre-MDT0001 [ 1201.359918] LustreError: 35075:0:(obd_class.h:479:obd_check_dev()) Device 10 not setup [ 1201.378973] LustreError: 35075:0:(obd_class.h:479:obd_check_dev()) Skipped 23 previous similar messages [ 1201.503360] Lustre: server umount lustre-MDT0001 complete [ 1203.385937] LustreError: 25844:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0001: not available for connect from 192.168.204.29@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1203.419505] LustreError: 25844:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 139 previous similar messages [ 1204.192585] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 1222.401150] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 1222.403133] LDISKFS-fs (dm-1): recovery complete [ 1222.410686] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 1222.624385] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 1222.627167] Lustre: Skipped 4 previous similar messages [ 1222.657784] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 1225.772707] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1227.815504] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:137 to 0x2c0000400:193) [ 1227.820314] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:137 to 0x280000400:193) [ 1233.443721] Lustre: DEBUG MARKER: oleg429-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 1235.457770] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1243.866651] Lustre: DEBUG MARKER: == replay-single test 110d: DNE: create striped dir, fail MDT2 and client ========================================================== 19:54:09 (1763340849) [ 1251.495363] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 1253.848337] Lustre: Failing over lustre-MDT0001 [ 1254.164890] Lustre: server umount lustre-MDT0001 complete [ 1275.616569] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 1275.618600] LDISKFS-fs (dm-1): recovery complete [ 1275.632858] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 1275.893562] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 1279.649574] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1281.001878] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 1281.015716] Lustre: Skipped 1 previous similar message [ 1286.156214] Lustre: DEBUG MARKER: oleg429-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 1288.941501] Lustre: lustre-MDT0001: Denying connection for new client 928a4b69-b6e2-487c-b47b-5b16dbd8c4f9 (at 192.168.204.29@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 1:01 [ 1288.948521] Lustre: Skipped 1 previous similar message [ 1350.000165] Lustre: lustre-MDT0001: recovery is timed out, evict stale exports [ 1350.005201] Lustre: 37524:0:(genops.c:1618:class_disconnect_stale_exports()) lustre-MDT0001: disconnect stale client e04ea87b-8373-4c63-8817-d78b52f4ea39@ [ 1350.011955] Lustre: lustre-MDT0001: disconnecting 1 stale clients [ 1350.029840] Lustre: lustre-MDT0001: Recovery over after 1:10, of 2 clients 1 recovered and 1 was evicted. [ 1350.030167] Lustre: lustre-MDT0001-osp-MDT0000: Connection restored to 0@lo (at 0@lo) [ 1350.060563] Lustre: Skipped 1 previous similar message [ 1350.077553] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:137 to 0x2c0000400:225) [ 1350.086251] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:137 to 0x280000400:225) [ 1350.118810] Lustre: Skipped 12 previous similar messages [ 1357.693141] Lustre: DEBUG MARKER: == replay-single test 110e: DNE: create striped dir, uncommit on MDT2, fail client/MDT1/MDT2 ========================================================== 19:56:03 (1763340963) [ 1364.905818] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 1372.316393] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1374.122373] Lustre: Failing over lustre-MDT0000 [ 1376.394783] Lustre: server umount lustre-MDT0000 complete [ 1378.274189] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1378.274902] Lustre: lustre-MDT0000-lwp-OST0000: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 1378.287109] LustreError: Skipped 1 previous similar message [ 1378.292132] Lustre: Skipped 13 previous similar messages [ 1379.454787] Lustre: Failing over lustre-MDT0001 [ 1379.457239] LustreError: 13189:0:(ldlm_lockd.c:2563:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1763340986 with bad export cookie 6195193940005607392 [ 1379.457629] LustreError: MGC192.168.204.129@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1379.499849] LustreError: 13189:0:(ldlm_lockd.c:2563:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 1379.736635] Lustre: server umount lustre-MDT0001 complete [ 1403.550880] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1403.560195] LDISKFS-fs (dm-0): recovery complete [ 1403.568910] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1403.879682] LustreError: 3646:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff927ce681c380 x1848995666541184/t0(0) o250->MGC192.168.204.129@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 [ 1403.970912] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 1403.974822] LDISKFS-fs (dm-1): recovery complete [ 1403.991473] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 1404.452617] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1409.467712] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1409.523461] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1410.670610] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1201 to 0x2c0000401:1313) [ 1410.679850] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1201 to 0x280000401:1313) [ 1416.391751] Lustre: DEBUG MARKER: oleg429-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 1418.887266] Lustre: lustre-MDT0001: Denying connection for new client 51c97dbf-8c97-4a92-b57f-78776c81fbb7 (at 192.168.204.29@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 1:01 [ 1418.897928] Lustre: Skipped 11 previous similar messages [ 1437.664167] Lustre: 3648:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763340990/real 1763340990] req@ffff927ce681f480 x1848995666539136/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1763341045 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1437.687961] Lustre: 3648:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 1480.000338] Lustre: lustre-MDT0001: recovery is timed out, evict stale exports [ 1480.003261] Lustre: 40460:0:(genops.c:1618:class_disconnect_stale_exports()) lustre-MDT0001: disconnect stale client 928a4b69-b6e2-487c-b47b-5b16dbd8c4f9@ [ 1480.018046] Lustre: lustre-MDT0001: disconnecting 1 stale clients [ 1480.094387] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:137 to 0x280000400:257) [ 1480.096289] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:137 to 0x2c0000400:257) [ 1487.333836] Lustre: DEBUG MARKER: SKIP: replay-single test_110f skipping excluded test 110f [ 1489.040825] Lustre: DEBUG MARKER: == replay-single test 110g: DNE: create striped dir, uncommit on MDT1, fail client/MDT1/MDT2 ========================================================== 19:58:14 (1763341094) [ 1495.978167] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1503.144529] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 1504.851377] Lustre: Failing over lustre-MDT0000 [ 1504.981596] LustreError: 42374:0:(obd_class.h:479:obd_check_dev()) Device 11 not setup [ 1504.984497] LustreError: 42374:0:(obd_class.h:479:obd_check_dev()) Skipped 31 previous similar messages [ 1505.118541] Lustre: server umount lustre-MDT0000 complete [ 1509.750114] Lustre: Failing over lustre-MDT0001 [ 1509.752507] LustreError: 13189:0:(ldlm_lockd.c:2563:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1763341117 with bad export cookie 6195193940005611760 [ 1509.753305] LustreError: MGC192.168.204.129@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1509.821182] LustreError: 13189:0:(ldlm_lockd.c:2563:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 1510.303911] Lustre: server umount lustre-MDT0001 complete [ 1534.607759] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 1534.610950] LDISKFS-fs (dm-1): recovery complete [ 1534.622403] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 1534.766359] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1534.770268] LDISKFS-fs (dm-0): recovery complete [ 1534.780939] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1534.811471] LustreError: 43653:0:(llog.c:1616:llog_backup()) MGC192.168.204.129@tcp: failed to open log lustre-sptlrpc: rc = -108 [ 1534.818677] Lustre: 43653:0:(mgc_request_server.c:732:mgc_llog_local_copy()) MGC192.168.204.129@tcp: failed to copy new config lustre-sptlrpc: rc = -108 [ 1535.904375] LustreError: 43679:0:(import.c:337:ptlrpc_invalidate_import()) MGS: timeout waiting for callback (1 != 0) [ 1535.910855] LustreError: 43679:0:(import.c:361:ptlrpc_invalidate_import()) @@@ still on sending list req@ffff927cc73f4700 x1848995666608128/t0(0) o250->MGC192.168.204.129@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 1763341143 ref 1 fl Rpc:NQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1535.921230] LustreError: 43679:0:(import.c:371:ptlrpc_invalidate_import()) MGS: Unregistering RPCs found (0). Network is sluggish? Waiting for them to error out. [ 1535.968979] LustreError: 3646:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff927cfba75f80 x1848995666610048/t0(0) o250->MGC192.168.204.129@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 [ 1535.982598] LustreError: 43679:0:(import.c:716:ptlrpc_connect_import_locked()) already connecting [ 1541.090617] Lustre: MGS: Client b6c90766-c675-4720-bd89-5949044041f2 (at 0@lo) reconnecting [ 1541.348671] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 1541.361989] Lustre: Skipped 1 previous similar message [ 1541.479889] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_connect to node 0@lo failed: rc = -114 [ 1541.482703] LustreError: Skipped 1 previous similar message [ 1544.614852] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 1544.629513] Lustre: Skipped 3 previous similar messages [ 1545.126420] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1545.198760] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1545.524348] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:137 to 0x280000400:289) [ 1545.524623] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:137 to 0x2c0000400:289) [ 1551.558667] Lustre: DEBUG MARKER: oleg429-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 1553.636688] Lustre: lustre-MDT0000: Denying connection for new client 0a06e814-deb9-430a-acb8-6e1b530accb4 (at 192.168.204.29@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 1:00 [ 1553.648544] Lustre: Skipped 11 previous similar messages [ 1614.000609] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 1614.005746] Lustre: 43769:0:(genops.c:1618:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 51c97dbf-8c97-4a92-b57f-78776c81fbb7@ [ 1614.013715] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 1614.027416] Lustre: lustre-MDT0000: Recovery over after 1:10, of 2 clients 1 recovered and 1 was evicted. [ 1614.031279] Lustre: Skipped 3 previous similar messages [ 1614.054535] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1201 to 0x280000401:1345) [ 1614.057197] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1201 to 0x2c0000401:1345) [ 1623.463891] Lustre: DEBUG MARKER: == replay-single test 111a: DNE: unlink striped dir, fail MDT1 ========================================================== 20:00:29 (1763341229) [ 1630.747888] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1632.642414] Lustre: Failing over lustre-MDT0000 [ 1632.737507] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1632.743890] Lustre: Skipped 3 previous similar messages [ 1632.921723] Lustre: server umount lustre-MDT0000 complete [ 1654.892133] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1654.893653] LDISKFS-fs (dm-0): recovery complete [ 1654.898754] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1664.482732] LustreError: 3646:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff927cf20bad80 x1848995666682240/t0(0) o250->MGC192.168.204.129@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 [ 1668.389680] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1670.208347] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1201 to 0x2c0000401:1377) [ 1670.208347] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1201 to 0x280000401:1377) [ 1675.253857] Lustre: DEBUG MARKER: oleg429-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1676.693730] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1685.039648] Lustre: DEBUG MARKER: == replay-single test 111b: DNE: unlink striped dir, fail MDT2 ========================================================== 20:01:30 (1763341290) [ 1692.839467] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 1695.146145] Lustre: Failing over lustre-MDT0001 [ 1695.414743] Lustre: server umount lustre-MDT0001 complete [ 1715.931481] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 1715.933931] LDISKFS-fs (dm-1): recovery complete [ 1715.942964] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 1720.141449] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1728.088334] Lustre: DEBUG MARKER: oleg429-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 1791.004545] Lustre: lustre-MDT0001: recovery is timed out, evict stale exports [ 1791.007357] Lustre: 47733:0:(genops.c:1618:class_disconnect_stale_exports()) lustre-MDT0001: disconnect stale client 0a06e814-deb9-430a-acb8-6e1b530accb4@ [ 1791.026237] Lustre: lustre-MDT0001: disconnecting 1 stale clients [ 1791.123155] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:137 to 0x280000400:321) [ 1791.124607] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:137 to 0x2c0000400:321) [ 1798.950909] Lustre: DEBUG MARKER: == replay-single test 111c: DNE: unlink striped dir, uncommit on MDT1, fail client/MDT1/MDT2 ========================================================== 20:03:24 (1763341404) [ 1806.215397] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1813.869824] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 1815.497172] Lustre: Failing over lustre-MDT0000 [ 1815.713802] Lustre: server umount lustre-MDT0000 complete [ 1818.600153] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1818.602648] LustreError: Skipped 1 previous similar message [ 1818.606322] LustreError: 44529:0:(ldlm_lib.c:1179: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. [ 1818.612223] LustreError: 44529:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 93 previous similar messages [ 1819.164289] Lustre: Failing over lustre-MDT0001 [ 1819.167736] LustreError: 25536:0:(ldlm_lockd.c:2563:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1763341426 with bad export cookie 6195193940005616527 [ 1819.168340] LustreError: MGC192.168.204.129@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1819.168345] LustreError: Skipped 2 previous similar messages [ 1819.194053] LustreError: 25536:0:(ldlm_lockd.c:2563:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 1819.469813] Lustre: server umount lustre-MDT0001 complete [ 1839.854502] Lustre: 3648:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763341431/real 1763341431] req@ffff927cc43ed180 x1848995666770944/t0(0) o400->lustre-MDT0001-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1763341447 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1839.893107] Lustre: 3648:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 26 previous similar messages [ 1842.628048] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1842.629681] LDISKFS-fs (dm-0): recovery complete [ 1842.641102] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1842.674284] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 1842.676116] LDISKFS-fs (dm-1): recovery complete [ 1842.687262] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 1842.847827] LustreError: 50581:0:(llog.c:1616:llog_backup()) MGC192.168.204.129@tcp: failed to open log lustre-sptlrpc: rc = -108 [ 1842.853489] Lustre: 50581:0:(mgc_request_server.c:732:mgc_llog_local_copy()) MGC192.168.204.129@tcp: failed to copy new config lustre-sptlrpc: rc = -108 [ 1843.808137] LustreError: 50575:0:(import.c:337:ptlrpc_invalidate_import()) MGS: timeout waiting for callback (1 != 0) [ 1843.819782] LustreError: 50575:0:(import.c:361:ptlrpc_invalidate_import()) @@@ still on sending list req@ffff927ceed8e680 x1848995666771840/t0(0) o250->MGC192.168.204.129@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 1763341451 ref 1 fl Rpc:NQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1843.859252] LustreError: 50575:0:(import.c:371:ptlrpc_invalidate_import()) MGS: Unregistering RPCs found (0). Network is sluggish? Waiting for them to error out. [ 1844.481700] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 1844.484482] Lustre: Skipped 7 previous similar messages [ 1844.506748] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 1844.508614] Lustre: Skipped 3 previous similar messages [ 1846.694106] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:137 to 0x280000400:353) [ 1846.706475] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:137 to 0x2c0000400:353) [ 1849.143167] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1849.722501] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1857.465939] Lustre: DEBUG MARKER: oleg429-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 1860.141157] Lustre: lustre-MDT0000: Denying connection for new client 8ad8c300-f19b-4bdc-8562-ff39d3a78c47 (at 192.168.204.29@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 0:54 [ 1860.176480] Lustre: Skipped 23 previous similar messages [ 1915.000458] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 1915.002931] Lustre: 50673:0:(genops.c:1618:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client b1c4c8d2-4390-441d-8364-22fa2538b45e@ [ 1915.008822] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 1915.023339] Lustre: lustre-MDT0000-osp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1915.033273] Lustre: Skipped 25 previous similar messages [ 1915.048817] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1201 to 0x280000401:1409) [ 1915.053174] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1201 to 0x2c0000401:1409) [ 1927.357475] Lustre: DEBUG MARKER: == replay-single test 111d: DNE: unlink striped dir, uncommit on MDT2, fail client/MDT1/MDT2 ========================================================== 20:05:33 (1763341533) [ 1935.563422] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 1943.531117] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1945.243269] Lustre: Failing over lustre-MDT0000 [ 1945.475606] Lustre: server umount lustre-MDT0000 complete [ 1946.081665] 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 [ 1946.086571] Lustre: Skipped 25 previous similar messages [ 1948.857423] Lustre: Failing over lustre-MDT0001 [ 1948.860335] LustreError: 13189:0:(ldlm_lockd.c:2563:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1763341556 with bad export cookie 6195193940005619397 [ 1948.869406] LustreError: 13189:0:(ldlm_lockd.c:2563:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 1949.196562] Lustre: server umount lustre-MDT0001 complete [ 1971.550512] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 1971.553563] LDISKFS-fs (dm-1): recovery complete [ 1971.576054] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 1971.772939] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1971.778405] LDISKFS-fs (dm-0): recovery complete [ 1971.801592] LustreError: 53820:0:(llog.c:1616:llog_backup()) MGC192.168.204.129@tcp: failed to open log lustre-sptlrpc: rc = -108 [ 1971.809411] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1971.813991] Lustre: 53820:0:(mgc_request_server.c:732:mgc_llog_local_copy()) MGC192.168.204.129@tcp: failed to copy new config lustre-sptlrpc: rc = -108 [ 1973.729150] LustreError: 3646:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff927bc7d0ea00 x1848995666841344/t0(0) o250->MGC192.168.204.129@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 [ 1977.659920] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1201 to 0x280000401:1441) [ 1977.666966] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1201 to 0x2c0000401:1441) [ 1978.976319] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1979.399657] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1987.996962] Lustre: DEBUG MARKER: oleg429-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 2047.001597] Lustre: lustre-MDT0001: recovery is timed out, evict stale exports [ 2047.004057] Lustre: 53896:0:(genops.c:1618:class_disconnect_stale_exports()) lustre-MDT0001: disconnect stale client 8ad8c300-f19b-4bdc-8562-ff39d3a78c47@ [ 2047.036630] Lustre: lustre-MDT0001: disconnecting 1 stale clients [ 2047.149169] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:137 to 0x280000400:385) [ 2047.154923] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:137 to 0x2c0000400:385) [ 2055.495764] Lustre: DEBUG MARKER: == replay-single test 111e: DNE: unlink striped dir, uncommit on MDT2, fail MDT1/MDT2 ========================================================== 20:07:41 (1763341661) [ 2062.951776] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 2070.856229] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2072.654223] Lustre: Failing over lustre-MDT0000 [ 2072.775902] Lustre: lustre-MDT0000: Not available for connect from 192.168.204.29@tcp (stopping) [ 2072.865215] LustreError: 55802:0:(obd_class.h:479:obd_check_dev()) Device 27 not setup [ 2072.868617] LustreError: 55802:0:(obd_class.h:479:obd_check_dev()) Skipped 63 previous similar messages [ 2072.967308] Lustre: server umount lustre-MDT0000 complete [ 2077.067492] LustreError: 13189:0:(ldlm_lockd.c:2563:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1763341684 with bad export cookie 6195193940005621581 [ 2077.068074] Lustre: Failing over lustre-MDT0001 [ 2077.572480] Lustre: server umount lustre-MDT0001 complete [ 2103.078128] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 2103.087860] LDISKFS-fs (dm-1): recovery complete [ 2103.099691] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2103.102779] LDISKFS-fs (dm-0): recovery complete [ 2103.111618] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 2103.179673] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2103.547104] LustreError: 57101:0:(llog.c:1616:llog_backup()) MGC192.168.204.129@tcp: failed to open log lustre-sptlrpc: rc = -108 [ 2103.555328] Lustre: 57101:0:(mgc_request_server.c:732:mgc_llog_local_copy()) MGC192.168.204.129@tcp: failed to copy new config lustre-sptlrpc: rc = -108 [ 2121.697087] LustreError: 3646:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff927cc4748a80 x1848995666909696/t0(0) o250->MGC192.168.204.129@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 [ 2123.227237] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 2123.235445] Lustre: Skipped 7 previous similar messages [ 2126.226030] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2126.578744] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2128.257441] Lustre: lustre-MDT0001: Recovery over after 0:05, of 2 clients 2 recovered and 0 were evicted. [ 2128.268194] Lustre: Skipped 6 previous similar messages [ 2128.325291] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:137 to 0x280000400:417) [ 2128.326558] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:137 to 0x2c0000400:417) [ 2128.416839] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1201 to 0x280000401:1473) [ 2128.418381] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1201 to 0x2c0000401:1473) [ 2135.221628] Lustre: DEBUG MARKER: oleg429-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 2137.271270] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2139.056885] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2149.379230] Lustre: DEBUG MARKER: == replay-single test 111f: DNE: unlink striped dir, uncommit on MDT1, fail MDT1/MDT2 ========================================================== 20:09:14 (1763341754) [ 2158.119261] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2167.241427] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 2169.511336] Lustre: Failing over lustre-MDT0000 [ 2169.750166] Lustre: server umount lustre-MDT0000 complete [ 2174.171948] LustreError: 6500:0:(ldlm_lockd.c:2563:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1763341781 with bad export cookie 6195193940005623898 [ 2174.178199] Lustre: Failing over lustre-MDT0001 [ 2174.189237] LustreError: 6500:0:(ldlm_lockd.c:2563:ldlm_cancel_handler()) Skipped 7 previous similar messages [ 2174.787556] Lustre: server umount lustre-MDT0001 complete [ 2199.251926] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 2199.254237] LDISKFS-fs (dm-1): recovery complete [ 2199.268660] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 2199.356466] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2199.358347] LDISKFS-fs (dm-0): recovery complete [ 2199.381152] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2199.570951] LustreError: 60412:0:(llog.c:1616:llog_backup()) MGC192.168.204.129@tcp: failed to open log lustre-sptlrpc: rc = -108 [ 2199.583363] Lustre: 60412:0:(mgc_request_server.c:732:mgc_llog_local_copy()) MGC192.168.204.129@tcp: failed to copy new config lustre-sptlrpc: rc = -108 [ 2218.979372] LustreError: 3646:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff927ceed8ed80 x1848995666963584/t0(0) o250->MGC192.168.204.129@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 [ 2219.183671] Lustre: lustre-MDT0001: Not available for connect from 192.168.204.29@tcp (not set up) [ 2224.765163] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2225.063336] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2225.764259] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:137 to 0x280000400:449) [ 2225.764349] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:137 to 0x2c0000400:449) [ 2225.853422] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1201 to 0x2c0000401:1505) [ 2225.860902] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1201 to 0x280000401:1505) [ 2232.802822] Lustre: DEBUG MARKER: oleg429-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 2234.536968] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2236.105839] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2243.948771] Lustre: DEBUG MARKER: == replay-single test 111g: DNE: unlink striped dir, fail MDT1/MDT2 ========================================================== 20:10:49 (1763341849) [ 2251.768810] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2259.255749] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 2261.317541] Lustre: Failing over lustre-MDT0000 [ 2261.629374] Lustre: server umount lustre-MDT0000 complete [ 2265.780843] LustreError: 6498:0:(ldlm_lockd.c:2563:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1763341873 with bad export cookie 6195193940005626201 [ 2265.786866] Lustre: Failing over lustre-MDT0001 [ 2265.799388] LustreError: 6498:0:(ldlm_lockd.c:2563:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 2266.205847] Lustre: server umount lustre-MDT0001 complete [ 2290.716120] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2290.721782] LDISKFS-fs (dm-0): recovery complete [ 2290.742477] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2290.789905] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 2290.794808] LDISKFS-fs (dm-1): recovery complete [ 2290.807541] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 2291.621624] LustreError: 3646:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff927cc59c8000 x1848995667015296/t0(0) o250->MGC192.168.204.129@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 [ 2296.638817] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2297.152037] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2298.565645] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:137 to 0x280000400:481) [ 2298.577135] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:137 to 0x2c0000400:481) [ 2302.827805] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1201 to 0x280000401:1537) [ 2302.831031] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1201 to 0x2c0000401:1537) [ 2307.296315] Lustre: DEBUG MARKER: oleg429-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 2308.914817] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2310.672830] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2320.067481] Lustre: DEBUG MARKER: == replay-single test 112a: DNE: cross MDT rename, fail MDT1 ========================================================== 20:12:05 (1763341925) [ 2322.194140] Lustre: DEBUG MARKER: SKIP: replay-single test_112a needs >= 4 MDTs [ 2324.488580] Lustre: DEBUG MARKER: == replay-single test 112b: DNE: cross MDT rename, fail MDT2 ========================================================== 20:12:09 (1763341929) [ 2326.436329] Lustre: DEBUG MARKER: SKIP: replay-single test_112b needs >= 4 MDTs [ 2328.384091] Lustre: DEBUG MARKER: == replay-single test 112c: DNE: cross MDT rename, fail MDT3 ========================================================== 20:12:14 (1763341934) [ 2329.910342] Lustre: DEBUG MARKER: SKIP: replay-single test_112c needs >= 4 MDTs [ 2331.975480] Lustre: DEBUG MARKER: == replay-single test 112d: DNE: cross MDT rename, fail MDT4 ========================================================== 20:12:17 (1763341937) [ 2333.758200] Lustre: DEBUG MARKER: SKIP: replay-single test_112d needs >= 4 MDTs [ 2335.814894] Lustre: DEBUG MARKER: == replay-single test 112e: DNE: cross MDT rename, fail MDT1 and MDT2 ========================================================== 20:12:21 (1763341941) [ 2337.573128] Lustre: DEBUG MARKER: SKIP: replay-single test_112e needs >= 4 MDTs [ 2339.293324] Lustre: DEBUG MARKER: == replay-single test 112f: DNE: cross MDT rename, fail MDT1 and MDT3 ========================================================== 20:12:25 (1763341945) [ 2341.082316] Lustre: DEBUG MARKER: SKIP: replay-single test_112f needs >= 4 MDTs [ 2343.504565] Lustre: DEBUG MARKER: == replay-single test 112g: DNE: cross MDT rename, fail MDT1 and MDT4 ========================================================== 20:12:28 (1763341948) [ 2345.166955] Lustre: DEBUG MARKER: SKIP: replay-single test_112g needs >= 4 MDTs [ 2346.901553] Lustre: DEBUG MARKER: == replay-single test 112h: DNE: cross MDT rename, fail MDT2 and MDT3 ========================================================== 20:12:32 (1763341952) [ 2348.446359] Lustre: DEBUG MARKER: SKIP: replay-single test_112h needs >= 4 MDTs [ 2350.067459] Lustre: DEBUG MARKER: == replay-single test 112i: DNE: cross MDT rename, fail MDT2 and MDT4 ========================================================== 20:12:35 (1763341955) [ 2351.460641] Lustre: DEBUG MARKER: SKIP: replay-single test_112i needs >= 4 MDTs [ 2353.087878] Lustre: DEBUG MARKER: == replay-single test 112j: DNE: cross MDT rename, fail MDT3 and MDT4 ========================================================== 20:12:38 (1763341958) [ 2354.458811] Lustre: DEBUG MARKER: SKIP: replay-single test_112j needs >= 4 MDTs [ 2356.162637] Lustre: DEBUG MARKER: == replay-single test 112k: DNE: cross MDT rename, fail MDT1,MDT2,MDT3 ========================================================== 20:12:41 (1763341961) [ 2357.723509] Lustre: DEBUG MARKER: SKIP: replay-single test_112k needs >= 4 MDTs [ 2359.398722] Lustre: DEBUG MARKER: == replay-single test 112l: DNE: cross MDT rename, fail MDT1,MDT2,MDT4 ========================================================== 20:12:45 (1763341965) [ 2360.771956] Lustre: DEBUG MARKER: SKIP: replay-single test_112l needs >= 4 MDTs [ 2362.460446] Lustre: DEBUG MARKER: == replay-single test 112m: DNE: cross MDT rename, fail MDT1,MDT3,MDT4 ========================================================== 20:12:48 (1763341968) [ 2364.062736] Lustre: DEBUG MARKER: SKIP: replay-single test_112m needs >= 4 MDTs [ 2365.955644] Lustre: DEBUG MARKER: == replay-single test 112n: DNE: cross MDT rename, fail MDT2,MDT3,MDT4 ========================================================== 20:12:51 (1763341971) [ 2367.513405] Lustre: DEBUG MARKER: SKIP: replay-single test_112n needs >= 4 MDTs [ 2369.383294] Lustre: DEBUG MARKER: == replay-single test 115: failover for create/unlink striped directory ========================================================== 20:12:55 (1763341975) [ 2376.276097] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 2378.818855] Lustre: Failing over lustre-MDT0001 [ 2379.019945] Lustre: server umount lustre-MDT0001 complete [ 2380.785770] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 2380.792139] LustreError: Skipped 7 previous similar messages [ 2402.253726] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 2402.260206] LDISKFS-fs (dm-1): recovery complete [ 2402.285545] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 2402.747271] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 2402.758331] Lustre: Skipped 9 previous similar messages [ 2407.427684] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2408.127838] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:137 to 0x2c0000400:513) [ 2408.131473] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:137 to 0x280000400:513) [ 2415.027592] Lustre: DEBUG MARKER: oleg429-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 2416.724459] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2426.129528] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2428.571191] Lustre: Failing over lustre-MDT0000 [ 2428.886255] Lustre: server umount lustre-MDT0000 complete [ 2430.136293] LustreError: 64574:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.204.29@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 2430.160139] LustreError: 64574:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 93 previous similar messages [ 2450.409301] Lustre: 3649:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763342040/real 1763342040] req@ffff927cc756aa00 x1848995667125888/t0(0) o400->MGC192.168.204.129@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1763342056 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2450.454856] Lustre: 3649:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 41 previous similar messages [ 2450.470210] LustreError: MGC192.168.204.129@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2450.484813] LustreError: Skipped 4 previous similar messages [ 2452.928375] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2452.931297] LDISKFS-fs (dm-0): recovery complete [ 2452.941279] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2459.618646] LustreError: 3646:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff927cfb46bb80 x1848995667134464/t0(0) o250->MGC192.168.204.129@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 [ 2459.869590] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 2459.877774] Lustre: Skipped 10 previous similar messages [ 2463.630776] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2465.453398] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1201 to 0x280000401:1569) [ 2465.454303] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1201 to 0x2c0000401:1569) [ 2470.326295] Lustre: DEBUG MARKER: oleg429-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2471.893563] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2480.754345] Lustre: DEBUG MARKER: == replay-single test 116a: large update log master MDT recovery ========================================================== 20:14:46 (1763342086) [ 2487.564896] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2488.546202] Lustre: *** cfs_fail_loc=1702, val=0*** [ 2490.661702] Lustre: Failing over lustre-MDT0000 [ 2490.843686] Lustre: server umount lustre-MDT0000 complete [ 2513.373087] LDISKFS-fs (dm-0): 4 truncates cleaned up [ 2513.374929] LDISKFS-fs (dm-0): recovery complete [ 2513.393499] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2526.943903] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2528.239787] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 2528.249694] Lustre: Skipped 31 previous similar messages [ 2528.379898] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1201 to 0x280000401:1601) [ 2528.379936] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1201 to 0x2c0000401:1601) [ 2533.684598] Lustre: DEBUG MARKER: oleg429-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2535.172625] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2542.636181] Lustre: DEBUG MARKER: == replay-single test 116b: large update log slave MDT recovery ========================================================== 20:15:48 (1763342148) [ 2549.299771] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 2550.151794] Lustre: *** cfs_fail_loc=1702, val=0*** [ 2552.070673] Lustre: Failing over lustre-MDT0001 [ 2552.341572] Lustre: server umount lustre-MDT0001 complete [ 2553.829281] 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 [ 2553.835147] Lustre: Skipped 30 previous similar messages [ 2573.460673] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 2573.462420] LDISKFS-fs (dm-1): recovery complete [ 2573.477469] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 2577.576111] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2578.988461] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:137 to 0x280000400:545) [ 2578.988537] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:137 to 0x2c0000400:545) [ 2584.290804] Lustre: DEBUG MARKER: oleg429-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 2585.876624] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2594.267317] Lustre: DEBUG MARKER: == replay-single test 117: DNE: cross MDT unlink, fail MDT1 and MDT2 ========================================================== 20:16:40 (1763342200) [ 2595.815491] Lustre: DEBUG MARKER: SKIP: replay-single test_117 needs >= 4 MDTs [ 2597.399288] Lustre: DEBUG MARKER: == replay-single test 118: invalidate osp update will not cause update log corruption ========================================================== 20:16:43 (1763342203) [ 2598.860156] Lustre: *** cfs_fail_loc=1705, val=0*** [ 2606.165400] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2608.182399] Lustre: Failing over lustre-MDT0000 [ 2608.477112] Lustre: server umount lustre-MDT0000 complete [ 2630.489147] LDISKFS-fs (dm-0): 3 truncates cleaned up [ 2630.491981] LDISKFS-fs (dm-0): recovery complete [ 2630.501774] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2635.744897] LustreError: 3646:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff927bc348d500 x1848995667265920/t0(0) o250->MGC192.168.204.129@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 [ 2635.783390] LustreError: 3646:0:(client.c:1390:ptlrpc_import_delay_req()) Skipped 2 previous similar messages [ 2639.919185] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2641.513508] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1201 to 0x2c0000401:1633) [ 2641.518876] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1201 to 0x280000401:1633) [ 2647.866879] Lustre: DEBUG MARKER: oleg429-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2649.706515] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2658.913737] Lustre: DEBUG MARKER: == replay-single test 119: timeout of normal replay does not cause DNE replay fails ========================================================== 20:17:44 (1763342264) [ 2667.085648] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2670.304180] Lustre: Failing over lustre-MDT0000 [ 2670.635965] Lustre: server umount lustre-MDT0000 complete [ 2685.243419] LDISKFS-fs (dm-0): 3 truncates cleaned up [ 2685.245049] LDISKFS-fs (dm-0): recovery complete [ 2685.273103] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2688.096928] Lustre: 64574:0:(ldlm_lib.c:2067:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 60, extend: 0 [ 2689.457451] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2691.042591] Lustre: 8412:0:(ldlm_lib.c:2067:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 60, extend: 0 [ 2691.060836] LustreError: 76772:0:(ldlm_lib.c:2671:replay_request_or_update()) cfs_fail_timeout id 714 sleeping for 65000ms [ 2695.670733] Lustre: DEBUG MARKER: oleg429-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2756.104149] LustreError: 76772:0:(ldlm_lib.c:2671:replay_request_or_update()) cfs_fail_timeout id 714 awake [ 2756.134674] Lustre: 76772:0:(genops.c:1618:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client e070d777-4ebc-4b90-98ea-c42fb4f5f802@192.168.204.29@tcp [ 2756.140186] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 2756.142568] Lustre: 76772:0:(ldlm_lib.c:1897:abort_req_replay_queue()) @@@ aborted: req@ffff927cf5c05c00 x1848995651863680/t0(85899345925) o36->e070d777-4ebc-4b90-98ea-c42fb4f5f802@192.168.204.29@tcp:617/0 lens 528/0 e 7 to 0 dl 1763342377 ref 1 fl Complete:/204/ffffffff rc 0/-1 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 2756.152766] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 2756.159762] Lustre: 76772:0:(ldlm_lib.c:2067:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 60, extend: 1 [ 2756.176628] Lustre: lustre-MDT0000: Denying connection for new client e070d777-4ebc-4b90-98ea-c42fb4f5f802 (at 192.168.204.29@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 1 evicted) already passed deadline 0:08 [ 2756.182516] Lustre: Skipped 22 previous similar messages [ 2756.233079] Lustre: 76772:0:(ldlm_lib.c:2375:target_recovery_overseer()) lustre-MDT0000 recovery is aborted by hard timeout [ 2756.239760] Lustre: 76772:0:(ldlm_lib.c:2385:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 2756.243823] Lustre: 76772:0:(ldlm_lib.c:2385:target_recovery_overseer()) Skipped 2 previous similar messages [ 2756.256430] Lustre: lustre-MDT0000-osd: cancel update llog [0x200002340:0x1:0x0] [ 2756.305384] Lustre: lustre-MDT0001-osp-MDT0000: cancel update llog [0x240002342:0x1:0x0] [ 2756.325429] Lustre: 76772:0:(ldlm_lib.c:2929:target_recovery_thread()) too long recovery - read logs [ 2756.330264] LustreError: dumping log to /tmp/lustre-log.1763342363.76772 [ 2756.402827] Lustre: lustre-MDT0000: Recovery over after 1:08, of 2 clients 1 recovered and 1 was evicted. [ 2756.406262] Lustre: Skipped 10 previous similar messages [ 2756.437497] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1201 to 0x280000401:1665) [ 2756.438062] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1201 to 0x2c0000401:1665) [ 2762.014695] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 59 sec [ 2775.902463] Lustre: DEBUG MARKER: == replay-single test 120: DNE fail abort should stop both normal and DNE replay ========================================================== 20:19:41 (1763342381) [ 2782.675120] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2789.826033] Lustre: Failing over lustre-MDT0000 [ 2789.958205] LustreError: 77978:0:(obd_class.h:479:obd_check_dev()) Device 27 not setup [ 2789.961249] LustreError: 77978:0:(obd_class.h:479:obd_check_dev()) Skipped 95 previous similar messages [ 2790.037393] Lustre: server umount lustre-MDT0000 complete [ 2802.806822] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2802.810548] LDISKFS-fs (dm-0): recovery complete [ 2802.825049] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2803.206244] Lustre: lustre-MDT0000: Aborting client recovery [ 2803.213497] LustreError: 78623:0:(ldlm_lib.c:2982:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 2803.231222] LustreError: 78655:0:(lod_dev.c:510:lod_sub_recovery_thread()) lustre-MDT0001-osp-MDT0000: get update log duration 0, retries 0, failed: rc = -108 [ 2803.231340] Lustre: 78656:0:(ldlm_lib.c:2385:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 2803.231344] Lustre: 78656:0:(ldlm_lib.c:2385:target_recovery_overseer()) Skipped 1 previous similar message [ 2803.312371] Lustre: lustre-MDT0000-osd: cancel update llog [0x20000a040:0x3:0x0] [ 2803.337607] Lustre: lustre-MDT0001-osp-MDT0000: cancel update llog [0x2400088d2:0x1:0x0] [ 2803.419721] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1201 to 0x2c0000401:1697) [ 2803.423591] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1201 to 0x280000401:1697) [ 2808.109643] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2808.313836] LustreError: lustre-MDT0000-osp-MDT0001: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 2829.395858] Lustre: DEBUG MARKER: == replay-single test 121: lock replay timed out and race ========================================================== 20:20:35 (1763342435) [ 2832.456446] Lustre: Failing over lustre-MDT0000 [ 2832.725860] Lustre: server umount lustre-MDT0000 complete [ 2836.637449] Lustre: *** cfs_fail_loc=721, val=0*** [ 2836.641288] Lustre: Skipped 4 previous similar messages [ 2839.013146] Lustre: *** cfs_fail_loc=721, val=0*** [ 2839.015126] Lustre: Skipped 8 previous similar messages [ 2840.032474] Lustre: *** cfs_fail_loc=721, val=0*** [ 2842.220195] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2842.370522] Lustre: *** cfs_fail_loc=721, val=0*** [ 2842.380940] Lustre: Skipped 4 previous similar messages [ 2846.119664] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2846.885501] Lustre: *** cfs_fail_loc=721, val=0*** [ 2846.887631] Lustre: Skipped 78 previous similar messages [ 2846.887778] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 2846.895040] Lustre: Skipped 10 previous similar messages [ 2847.730942] Lustre: *** cfs_fail_loc=721, val=1*** [ 2847.733109] Lustre: Skipped 6 previous similar messages [ 2855.396978] Lustre: *** cfs_fail_loc=721, val=1*** [ 2855.398380] Lustre: Skipped 47 previous similar messages [ 2863.280219] Lustre: lustre-MDT0000: Client e070d777-4ebc-4b90-98ea-c42fb4f5f802 (at 192.168.204.29@tcp) reconnected, waiting for 2 clients in recovery for 0:52 [ 2873.313246] Lustre: *** cfs_fail_loc=721, val=1*** [ 2873.316019] Lustre: Skipped 60 previous similar messages [ 2877.923594] Lustre: lustre-MDT0000: Received new MDS connection from 0@lo, keep former export from same NID [ 2877.938466] Lustre: *** cfs_fail_loc=721, val=1*** [ 2879.651072] Lustre: lustre-MDT0000: Client e070d777-4ebc-4b90-98ea-c42fb4f5f802 (at 192.168.204.29@tcp) reconnected, waiting for 2 clients in recovery for 0:36 [ 2895.028475] Lustre: lustre-MDT0000: Client e070d777-4ebc-4b90-98ea-c42fb4f5f802 (at 192.168.204.29@tcp) reconnected, waiting for 2 clients in recovery for 0:20 [ 2906.592847] Lustre: *** cfs_fail_loc=721, val=1*** [ 2906.600552] Lustre: Skipped 122 previous similar messages [ 2908.129357] Lustre: lustre-MDT0000: Received new MDS connection from 0@lo, keep former export from same NID [ 2908.150108] Lustre: *** cfs_fail_loc=721, val=1*** [ 2911.395342] Lustre: lustre-MDT0000: Client e070d777-4ebc-4b90-98ea-c42fb4f5f802 (at 192.168.204.29@tcp) reconnected, waiting for 2 clients in recovery for 0:17 [ 2927.784728] Lustre: lustre-MDT0000: Client e070d777-4ebc-4b90-98ea-c42fb4f5f802 (at 192.168.204.29@tcp) reconnected, waiting for 2 clients in recovery for 0:01 [ 2938.339793] Lustre: lustre-MDT0000: Received new MDS connection from 0@lo, keep former export from same NID [ 2938.343734] Lustre: *** cfs_fail_loc=721, val=1*** [ 2938.346180] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 2944.170839] Lustre: lustre-MDT0000: Client e070d777-4ebc-4b90-98ea-c42fb4f5f802 (at 192.168.204.29@tcp) reconnected, waiting for 2 clients in recovery for 0:24 [ 2960.558923] Lustre: lustre-MDT0000: Client e070d777-4ebc-4b90-98ea-c42fb4f5f802 (at 192.168.204.29@tcp) reconnected, waiting for 2 clients in recovery for 0:08 [ 2968.544525] Lustre: lustre-MDT0000: Received new MDS connection from 0@lo, keep former export from same NID [ 2968.552850] Lustre: *** cfs_fail_loc=721, val=1*** [ 2970.790727] Lustre: *** cfs_fail_loc=721, val=1*** [ 2970.798864] Lustre: Skipped 261 previous similar messages [ 2992.285620] Lustre: lustre-MDT0000: Recovery already passed deadline 0:03. If you do not want to wait more, you may force taget eviction via 'lctl --device lustre-MDT0000 abort_recovery. [ 2998.758105] Lustre: lustre-MDT0000: Received new MDS connection from 0@lo, keep former export from same NID [ 2998.773432] Lustre: *** cfs_fail_loc=721, val=1*** [ 2998.775676] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 2998.778371] Lustre: 80061:0:(ldlm_lib.c:2067:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 2998.797513] Lustre: 80061:0:(ldlm_lib.c:2067:extend_recovery_timer()) Skipped 20 previous similar messages [ 3008.688835] Lustre: lustre-MDT0000: Client e070d777-4ebc-4b90-98ea-c42fb4f5f802 (at 192.168.204.29@tcp) reconnected, waiting for 2 clients in recovery for 0:17 [ 3008.700484] Lustre: Skipped 1 previous similar message [ 3028.960674] Lustre: lustre-MDT0000: Received new MDS connection from 0@lo, keep former export from same NID [ 3028.983382] Lustre: 80061:0:(ldlm_lib.c:2067:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3028.991683] Lustre: 80061:0:(ldlm_lib.c:2375:target_recovery_overseer()) lustre-MDT0000 recovery is aborted by hard timeout [ 3028.998357] Lustre: 80061:0:(ldlm_lib.c:2375:target_recovery_overseer()) Skipped 1 previous similar message [ 3029.007087] Lustre: 80061:0:(ldlm_lib.c:2385:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 3029.014852] Lustre: 80061:0:(ldlm_lib.c:2385:target_recovery_overseer()) Skipped 2 previous similar messages [ 3029.019247] Lustre: 80061:0:(genops.c:1618:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client e070d777-4ebc-4b90-98ea-c42fb4f5f802@192.168.204.29@tcp [ 3029.028211] Lustre: 80061:0:(genops.c:1618:class_disconnect_stale_exports()) Skipped 2 previous similar messages [ 3029.042575] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 3029.056145] Lustre: Skipped 1 previous similar message [ 3029.058544] LustreError: 80061:0:(ldlm_lib.c:1917:abort_lock_replay_queue()) @@@ aborted: req@ffff927cc7693800 x1848995652013440/t0(0) o101->e070d777-4ebc-4b90-98ea-c42fb4f5f802@192.168.204.29@tcp:0/0 lens 328/0 e 0 to 0 dl 1763342513 ref 1 fl Complete:/240/ffffffff rc 0/-1 job:'ldlm_lock_repla.0' uid:0 gid:0 projid:4294967295 [ 3029.110457] Lustre: lustre-MDT0000-osd: cancel update llog [0x20000a810:0x1:0x0] [ 3029.138389] Lustre: lustre-MDT0001-osp-MDT0000: cancel update llog [0x2400088d3:0x1:0x0] [ 3029.177177] Lustre: 80061:0:(ldlm_lib.c:2929:target_recovery_thread()) too long recovery - read logs [ 3029.180934] LustreError: dumping log to /tmp/lustre-log.1763342636.80061 [ 3029.351550] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1699 to 0x280000401:1729) [ 3029.351660] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1201 to 0x2c0000401:1729) [ 3043.631215] Lustre: DEBUG MARKER: == replay-single test 130a: DoM file create (setstripe) replay ========================================================== 20:24:09 (1763342649) [ 3050.345369] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3051.959294] Lustre: Failing over lustre-MDT0000 [ 3052.163039] Lustre: server umount lustre-MDT0000 complete [ 3054.563266] LustreError: 65544:0:(ldlm_lib.c:1179: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. [ 3054.575572] LustreError: 65544:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 162 previous similar messages [ 3069.923801] Lustre: 3648:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763342661/real 1763342661] req@ffff927cc59c8700 x1848995667534336/t0(0) o400->MGC192.168.204.129@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1763342677 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3069.965492] Lustre: 3648:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 8 previous similar messages [ 3069.972966] LustreError: MGC192.168.204.129@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3069.995745] LustreError: Skipped 5 previous similar messages [ 3073.406467] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3073.412328] LDISKFS-fs (dm-0): recovery complete [ 3073.421177] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3080.161259] LustreError: 3646:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff927cf6169f80 x1848995667543936/t0(0) o250->MGC192.168.204.129@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 [ 3080.353928] Lustre: lustre-MDT0000: Not available for connect from 192.168.204.29@tcp (not set up) [ 3080.490770] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3080.496442] Lustre: Skipped 6 previous similar messages [ 3080.552777] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 3080.564915] Lustre: Skipped 9 previous similar messages [ 3084.315103] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3085.991313] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1699 to 0x280000401:1761) [ 3085.991672] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1201 to 0x2c0000401:1761) [ 3091.621152] Lustre: DEBUG MARKER: oleg429-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3093.442980] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3101.602239] Lustre: DEBUG MARKER: == replay-single test 130b: DoM file create (inherited) replay ========================================================== 20:25:07 (1763342707) [ 3109.760540] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3111.502807] Lustre: Failing over lustre-MDT0000 [ 3111.678272] Lustre: server umount lustre-MDT0000 complete [ 3111.905703] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3111.920321] LustreError: Skipped 4 previous similar messages [ 3132.597881] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3132.600393] LDISKFS-fs (dm-0): recovery complete [ 3132.612675] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3142.115047] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x55f9c0109cb09208 [ 3142.128158] Lustre: MGC192.168.204.129@tcp: Connection restored to 0@lo (at 0@lo) [ 3142.140660] Lustre: Skipped 26 previous similar messages [ 3145.875871] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3148.005157] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1201 to 0x2c0000401:1793) [ 3148.016479] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1699 to 0x280000401:1793) [ 3153.289994] Lustre: DEBUG MARKER: oleg429-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3154.906666] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3163.310461] Lustre: DEBUG MARKER: == replay-single test 131a: DoM file write lock replay === 20:26:09 (1763342769) [ 3170.803651] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3172.498477] Lustre: Failing over lustre-MDT0000 [ 3172.810823] Lustre: server umount lustre-MDT0000 complete [ 3173.346189] 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 [ 3173.364059] Lustre: Skipped 29 previous similar messages [ 3193.947824] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3193.949977] LDISKFS-fs (dm-0): recovery complete [ 3193.956618] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3202.424828] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3204.678779] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1699 to 0x280000401:1825) [ 3204.682640] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1201 to 0x2c0000401:1825) [ 3208.655654] Lustre: DEBUG MARKER: oleg429-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3209.918128] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3217.513864] Lustre: DEBUG MARKER: SKIP: replay-single test_131b skipping excluded test 131b [ 3219.343546] Lustre: DEBUG MARKER: == replay-single test 132a: PFL new component instantiate replay ========================================================== 20:27:04 (1763342824) [ 3226.785966] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3228.911528] Lustre: Failing over lustre-MDT0000 [ 3231.109195] Lustre: server umount lustre-MDT0000 complete [ 3251.593943] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3251.595844] LDISKFS-fs (dm-0): recovery complete [ 3251.605098] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3259.438913] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3261.497213] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1827 to 0x280000401:1857) [ 3261.500349] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1828 to 0x2c0000401:1857) [ 3265.900353] Lustre: DEBUG MARKER: oleg429-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3267.718925] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3277.173458] Lustre: DEBUG MARKER: == replay-single test 133: check resend of ongoing requests for lwp during failover ========================================================== 20:28:02 (1763342882) [ 3282.504782] Lustre: *** cfs_fail_loc=123, val=2147483648*** [ 3282.506981] Lustre: Skipped 277 previous similar messages [ 3285.682719] Lustre: Failing over lustre-MDT0000 [ 3286.028718] Lustre: server umount lustre-MDT0000 complete [ 3297.958117] Lustre: lustre-MDT0001: Client 8ce95de6-d099-4358-b1d7-2b805874f181 (at 192.168.204.29@tcp) reconnecting [ 3305.321961] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3316.361660] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3318.263076] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000300000400-0x0000000340000400]:1:mdt [ 3318.266720] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000300000400-0x0000000340000400]:1:mdt] [ 3318.302777] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1828 to 0x2c0000401:1889) [ 3318.307074] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1827 to 0x280000401:1889) [ 3324.409986] Lustre: DEBUG MARKER: == replay-single test 134: replay creation of a file created in a pool ========================================================== 20:28:50 (1763342930) [ 3338.786372] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3340.755499] Lustre: Failing over lustre-MDT0000 [ 3341.017208] Lustre: server umount lustre-MDT0000 complete [ 3361.419786] LDISKFS-fs (dm-0): 4 truncates cleaned up [ 3361.421771] LDISKFS-fs (dm-0): recovery complete [ 3361.437631] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3374.247921] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3376.190584] Lustre: lustre-MDT0000: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 3376.197861] Lustre: Skipped 6 previous similar messages [ 3376.257159] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1827 to 0x280000401:1921) [ 3376.257655] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1828 to 0x2c0000401:1921) [ 3380.824416] Lustre: DEBUG MARKER: oleg429-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3382.328655] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3399.844743] Lustre: DEBUG MARKER: == replay-single test 135: Server failure in lock replay phase ========================================================== 20:30:05 (1763343005) [ 3409.359098] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 3411.485016] Lustre: Failing over lustre-OST0000 [ 3411.527115] LustreError: 92143:0:(obd_class.h:479:obd_check_dev()) Device 19 not setup [ 3411.534496] LustreError: 92143:0:(obd_class.h:479:obd_check_dev()) Skipped 63 previous similar messages [ 3411.662541] Lustre: server umount lustre-OST0000 complete [ 3416.605389] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing load_module ../libcfs/libcfs/libcfs [ 3425.823719] LDISKFS-fs (dm-2): 3 truncates cleaned up [ 3425.828393] LDISKFS-fs (dm-2): recovery complete [ 3425.839369] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 3427.796462] Lustre: *** cfs_fail_loc=32d, val=20*** [ 3427.800806] Lustre: Skipped 1 previous similar message [ 3431.820111] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3437.543027] Lustre: DEBUG MARKER: oleg429-client.virtnet: executing wait_import_state_mount REPLAY_LOCKS osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 3439.380158] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in REPLAY_LOCKS state after 0 sec [ 3441.147762] Lustre: DEBUG MARKER: replay-single test_135: @@@@@@ FAIL: Unexpected sync success [ 3443.390051] Lustre: lustre-OST0000: Client 8ce95de6-d099-4358-b1d7-2b805874f181 (at 192.168.204.29@tcp) reconnected, waiting for 3 clients in recovery for 1:24 [ 3443.420137] Lustre: Skipped 1 previous similar message [ 3449.238430] Lustre: DEBUG MARKER: == replay-single test 136: MDS to disconnect all OSPs first, then cleanup ldlm ========================================================== 20:30:54 (1763343054) [ 3450.809828] Lustre: DEBUG MARKER: SKIP: replay-single test_136 needs > 2 MDTs [ 3452.501151] Lustre: DEBUG MARKER: == replay-single test 137a: DNE: create under striped dir, fail MDT1 ========================================================== 20:30:58 (1763343058) [ 3465.665825] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3467.564554] Lustre: Failing over lustre-MDT0000 [ 3467.907444] Lustre: server umount lustre-MDT0000 complete [ 3489.593736] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3489.596815] LDISKFS-fs (dm-0): recovery complete [ 3489.620201] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3495.590088] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 3495.593513] Lustre: Skipped 7 previous similar messages [ 3498.069139] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3499.629677] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1828 to 0x2c0000401:1953) [ 3499.635996] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1827 to 0x280000401:1953) [ 3505.327098] Lustre: DEBUG MARKER: oleg429-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3506.692271] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3514.958492] Lustre: DEBUG MARKER: == replay-single test 137b: DNE: create under striped dir, fail MDT2 ========================================================== 20:32:00 (1763343120) [ 3521.538858] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 3523.455449] Lustre: Failing over lustre-MDT0001 [ 3523.723807] Lustre: server umount lustre-MDT0001 complete [ 3543.827221] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 3543.829137] LDISKFS-fs (dm-1): recovery complete [ 3543.853245] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 3547.500477] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3549.761666] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:548 to 0x2c0000400:577) [ 3549.762119] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:567 to 0x280000400:609) [ 3554.500111] Lustre: DEBUG MARKER: oleg429-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 3555.912447] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3564.793827] Lustre: DEBUG MARKER: == replay-single test 137c: DNE: create under striped dir, fail MDT1/MDT2 ========================================================== 20:32:50 (1763343170) [ 3571.062649] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3577.313760] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 3579.088619] Lustre: Failing over lustre-MDT0001 [ 3579.357646] Lustre: server umount lustre-MDT0001 complete [ 3582.540608] Lustre: Failing over lustre-MDT0000 [ 3582.883330] Lustre: server umount lustre-MDT0000 complete [ 3604.022365] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 3604.024100] LDISKFS-fs (dm-1): recovery complete [ 3604.034721] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 3604.116865] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3604.119239] LDISKFS-fs (dm-0): recovery complete [ 3604.125977] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3604.163848] LustreError: 99805:0:(llog.c:1616:llog_backup()) MGC192.168.204.129@tcp: failed to open log lustre-sptlrpc: rc = -108 [ 3604.172405] Lustre: 99805:0:(mgc_request_server.c:732:mgc_llog_local_copy()) MGC192.168.204.129@tcp: failed to copy new config lustre-sptlrpc: rc = -108 [ 3611.047275] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x55f9c0109cb0cd73 [ 3615.669879] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3616.093301] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3616.976278] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1828 to 0x2c0000401:1985) [ 3616.980809] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1827 to 0x280000401:1985) [ 3620.120481] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:548 to 0x2c0000400:609) [ 3620.121204] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:567 to 0x280000400:641) [ 3623.596305] Lustre: DEBUG MARKER: oleg429-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 3625.527755] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3627.498380] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3637.714782] Lustre: DEBUG MARKER: == replay-single test 200: Dropping one OBD_PING should not cause disconnect ========================================================== 20:34:03 (1763343243) [ 3639.440577] Lustre: DEBUG MARKER: SKIP: replay-single test_200 Need remote client [ 3641.449905] Lustre: DEBUG MARKER: == replay-single test 201: MDT umount cascading disconnects timeouts ========================================================== 20:34:07 (1763343247) [ 3646.678807] LustreError: 99835:0:(tgt_handler.c:1124:tgt_disconnect()) cfs_fail_timeout id 245 sleeping for 8000ms [ 3650.718422] LustreError: 25528:0:(tgt_handler.c:1124:tgt_disconnect()) cfs_fail_timeout id 245 sleeping for 8000ms [ 3654.720473] LustreError: 99835:0:(tgt_handler.c:1124:tgt_disconnect()) cfs_fail_timeout id 245 awake [ 3654.731201] Lustre: Failing over lustre-MDT0001 [ 3654.738858] LustreError: 8411:0:(tgt_handler.c:1124:tgt_disconnect()) cfs_fail_timeout id 245 sleeping for 8000ms [ 3654.746636] LustreError: 8411:0:(tgt_handler.c:1124:tgt_disconnect()) Skipped 2 previous similar messages [ 3655.853474] Lustre: lustre-MDT0001: Not available for connect from 192.168.204.29@tcp (stopping) [ 3657.697400] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 3657.700868] Lustre: Skipped 2 previous similar messages [ 3658.761684] LustreError: 25528:0:(tgt_handler.c:1124:tgt_disconnect()) cfs_fail_timeout id 245 awake [ 3660.957485] Lustre: lustre-MDT0001: Not available for connect from 192.168.204.29@tcp (stopping) [ 3660.972799] Lustre: Skipped 1 previous similar message [ 3662.760129] LustreError: 8403:0:(tgt_handler.c:1124:tgt_disconnect()) cfs_fail_timeout id 245 awake [ 3662.823985] LustreError: 8411:0:(ldlm_lib.c:1179: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. [ 3662.841839] LustreError: 8411:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 262 previous similar messages [ 3662.869690] Lustre: server umount lustre-MDT0001 complete [ 3670.386946] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 3674.713609] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3676.212326] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:567 to 0x280000400:673) [ 3676.217453] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:548 to 0x2c0000400:641) [ 3683.641820] Lustre: DEBUG MARKER: == replay-single test 202: pfl replay should recovery layout generation ========================================================== 20:34:49 (1763343289) [ 3691.409922] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3693.330502] Lustre: Failing over lustre-MDT0000 [ 3693.553490] Lustre: server umount lustre-MDT0000 complete [ 3712.977390] Lustre: 3647:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763343304/real 1763343304] req@ffff927bc4779c00 x1848995667956736/t0(0) o400->MGC192.168.204.129@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1763343320 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3712.988098] Lustre: 3647:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 15 previous similar messages [ 3712.992429] LustreError: MGC192.168.204.129@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3713.006853] LustreError: Skipped 7 previous similar messages [ 3714.041342] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3714.043467] LDISKFS-fs (dm-0): recovery complete [ 3714.051063] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3723.239076] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x55f9c0109cb0daa8 [ 3723.429341] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3723.434287] Lustre: Skipped 11 previous similar messages [ 3723.466943] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 3723.481491] Lustre: Skipped 11 previous similar messages [ 3727.017059] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3729.036048] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1827 to 0x280000401:2017) [ 3729.043373] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1987 to 0x2c0000401:2017) [ 3734.429065] Lustre: DEBUG MARKER: oleg429-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3736.164623] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3745.284499] Lustre: DEBUG MARKER: == replay-single test 203: resend can hit original request ========================================================== 20:35:50 (1763343350) [ 3747.062513] LustreError: 101551:0:(mdt_handler.c:2116:mdt_getattr_name_lock()) cfs_fail_timeout id 2403 sleeping for 2000ms [ 3749.161969] LustreError: 101551:0:(mdt_handler.c:2116:mdt_getattr_name_lock()) cfs_fail_timeout id 2403 awake [ 3749.167826] LustreError: 101551:0:(mdt_handler.c:2116:mdt_getattr_name_lock()) Skipped 2 previous similar messages [ 3749.175952] Lustre: 101551:0:(service.c:2606:ptlrpc_server_handle_request()) @@@ pause req after reply req@ffff927ce626d180 x1848995652294912/t0(0) o101->8ce95de6-d099-4358-b1d7-2b805874f181@192.168.204.29@tcp:134/0 lens 592/1888 e 0 to 0 dl 1763343404 ref 1 fl Complete:/600/0 rc 0/0 job:'stat.0' uid:0 gid:0 projid:0 [ 3752.224198] Lustre: 101551:0:(service.c:2608:ptlrpc_server_handle_request()) @@@ continue req@ffff927ce626d180 x1848995652294912/t0(0) o101->8ce95de6-d099-4358-b1d7-2b805874f181@192.168.204.29@tcp:134/0 lens 592/1888 e 0 to 0 dl 1763343404 ref 1 fl Complete:/600/0 rc 0/0 job:'stat.0' uid:0 gid:0 projid:0 [ 3759.371636] Lustre: DEBUG MARKER: == replay-single test complete, duration 3518 sec ======== 20:36:04 (1763343364) [ 3761.022747] Lustre: DEBUG MARKER: === replay-single: start cleanup 20:36:06 (1763343366) === [ 3769.309691] Lustre: DEBUG MARKER: === replay-single: finish cleanup 20:36:14 (1763343374) === [ 3771.463086] Lustre: Failing over lustre-MDT0000 [ 3771.573449] Lustre: lustre-MDT0000: Not available for connect from 192.168.204.29@tcp (stopping) [ 3771.792917] Lustre: server umount lustre-MDT0000 complete [ 3773.934098] LustreError: lustre-MDT0000-osp-MDT0001: operation out_update to node 0@lo failed: rc = -107 [ 3773.948091] LustreError: Skipped 9 previous similar messages [ 3773.950323] 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 [ 3773.984785] Lustre: Skipped 33 previous similar messages [ 3796.692551] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3805.709212] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3807.206581] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 3807.216676] Lustre: Skipped 44 previous similar messages [ 3807.395946] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2019 to 0x280000401:2049) [ 3807.396199] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2019 to 0x2c0000401:2049) [ 3812.673497] Lustre: DEBUG MARKER: oleg429-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3814.151221] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3822.562355] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3822.572967] Lustre: Skipped 3 previous similar messages [ 3825.477328] Lustre: server umount lustre-MDT0000 complete [ 3833.714745] LustreError: 9475:0:(ldlm_lockd.c:2563:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1763343441 with bad export cookie 6195193940005683377 [ 3833.723370] LustreError: 9475:0:(ldlm_lockd.c:2563:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 3833.941649] Lustre: server umount lustre-MDT0001 complete [ 3852.100250] Lustre: server umount lustre-OST0000 complete [ 3870.031463] Lustre: server umount lustre-OST0001 complete [ 3884.941440] Lustre: DEBUG MARKER: oleg429-server.virtnet: executing unload_modules_local [ 3887.853593] Key type lgssc unregistered [ 3888.116560] LNet: 108301:0:(lib-ptl.c:967:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 3888.124466] LNetError: 108301:0:(acceptor.c:264:lnet_acceptor_remove_socket()) Interface ens2 not found [ 3888.138296] LNet: Removed LNI 192.168.204.129@tcp [ 3888.941194] Key type .llcrypt unregistered [ 3888.943146] Key type ._llcrypt unregistered