[ 0.000000] Linux version 4.18.0rh8.10-debug (green@maintenance) (gcc version 8.5.0 20210514 (Red Hat 8.5.0-26) (GCC)) #2 SMP Mon Jul 14 01:24:22 EDT 2025 [ 0.000000] Command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers' [ 0.000000] x86/fpu: xstate_offset[2]: 576, xstate_sizes[2]: 256 [ 0.000000] x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'standard' format. [ 0.000000] signal: max sigframe size: 1776 [ 0.000000] BIOS-provided physical RAM map: [ 0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable [ 0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000000100000-0x00000000bffcdfff] usable [ 0.000000] BIOS-e820: [mem 0x00000000bffce000-0x00000000bfffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000100000000-0x0000000146dfffff] usable [ 0.000000] NX (Execute Disable) protection: active [ 0.000000] SMBIOS 2.8 present. [ 0.000000] DMI: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.17.0-10.fc44 06/10/2025 [ 0.000000] Hypervisor detected: KVM [ 0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00 [ 0.000000] kvm-clock: using sched offset of 507227482 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2399.998 MHz processor [ 0.000000] last_pfn = 0x146e00 max_arch_pfn = 0x400000000 [ 0.000000] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT [ 0.000000] last_pfn = 0xbffce max_arch_pfn = 0x400000000 [ 0.000000] found SMP MP-table at [mem 0x000f54b0-0x000f54bf] [ 0.000000] RAMDISK: [mem 0xbcc54000-0xbffbffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F52D0 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE247C 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE2318 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 0022D8 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE238C 000090 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE241C 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE2454 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe2318-0xbffe238b] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe2317] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe238c-0xbffe241b] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe241c-0xbffe2453] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe2454-0xbffe247b] [ 0.000000] No NUMA configuration found [ 0.000000] Faking a node at [mem 0x0000000000000000-0x0000000146dfffff] [ 0.000000] NODE_DATA(0) allocated [mem 0x1465a3000-0x1465cdfff] [ 0.000000] Reserving 256MB of memory at 2544MB 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, 524584K 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.001015] APIC: Switch to symmetric I/O mode setup [ 0.003239] x2apic enabled [ 0.004010] Switched APIC routing to physical x2apic. [ 0.005018] kvm-guest: setup PV IPIs [ 0.008661] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.009000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.009026] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.010012] pid_max: default: 32768 minimum: 301 [ 0.011143] LSM: Security Framework initializing [ 0.012060] Yama: becoming mindful. [ 0.013045] SELinux: Initializing. [ 0.014083] *** VALIDATE selinux *** [ 0.023345] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.028349] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.029173] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.030118] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.031150] *** VALIDATE tmpfs *** [ 0.033211] *** VALIDATE proc *** [ 0.034357] *** VALIDATE cgroup *** [ 0.035016] *** VALIDATE cgroup2 *** [ 0.036331] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.037169] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.038010] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.039032] Spectre V2 : User space: Vulnerable [ 0.040017] Speculative Store Bypass: Vulnerable [ 0.043534] debug: unmapping init [mem 0xffffffffaba59000-0xffffffffaba60fff] [ 0.045225] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.046802] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.047030] ... version: 2 [ 0.048016] ... bit width: 48 [ 0.049017] ... generic registers: 4 [ 0.050010] ... value mask: 0000ffffffffffff [ 0.051023] ... max period: 00007fffffffffff [ 0.052016] ... fixed-purpose events: 3 [ 0.053017] ... event mask: 000000070000000f [ 0.054377] rcu: Hierarchical SRCU implementation. [ 0.056621] smp: Bringing up secondary CPUs ... [ 0.057727] x86: Booting SMP configuration: [ 0.058030] .... node #0, CPUs: #1 #2 #3 [ 0.061516] smp: Brought up 1 node, 4 CPUs [ 0.062983] smpboot: Max logical packages: 1 [ 0.063011] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.113022] node 0 deferred pages initialised in 47ms [ 0.116271] devtmpfs: initialized [ 0.118334] x86/mm: Memory block size: 128MB [ 0.121075] gcov: version magic: 0x41383552 [ 0.125061] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.126061] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.127449] pinctrl core: initialized pinctrl subsystem [ 0.129198] [ 0.129749] ************************************************************* [ 0.132014] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.135012] ** ** [ 0.137011] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.139014] ** ** [ 0.141013] ** This means that this kernel is built to expose internal ** [ 0.143014] ** IOMMU data structures, which may compromise security on ** [ 0.145011] ** your system. ** [ 0.148015] ** ** [ 0.150010] ** If you see this message and you are not debugging the ** [ 0.152014] ** kernel, report this immediately to your vendor! ** [ 0.154011] ** ** [ 0.157022] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.159014] ************************************************************* [ 0.162069] NET: Registered protocol family 16 [ 0.164448] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.167070] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.169082] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.173151] cpuidle: using governor menu [ 0.174301] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.177621] PCI: Using configuration type 1 for base access [ 0.179093] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.186121] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.188049] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.191043] cryptd: max_cpu_qlen set to 1000 [ 0.193245] ACPI: Added _OSI(Module Device) [ 0.194019] ACPI: Added _OSI(Processor Device) [ 0.195014] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.196012] ACPI: Added _OSI(Processor Aggregator Device) [ 0.201000] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.205260] ACPI: Interpreter enabled [ 0.206057] ACPI: PM: (supports S0 S3 S4 S5) [ 0.206961] ACPI: Using IOAPIC for interrupt routing [ 0.209084] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.211405] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.219891] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.221041] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.223014] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.225124] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.233449] acpiphp: Slot [2] registered [ 0.234091] acpiphp: Slot [5] registered [ 0.235126] acpiphp: Slot [6] registered [ 0.236117] acpiphp: Slot [7] registered [ 0.238106] acpiphp: Slot [8] registered [ 0.239115] acpiphp: Slot [9] registered [ 0.241152] acpiphp: Slot [10] registered [ 0.242124] acpiphp: Slot [3] registered [ 0.244121] acpiphp: Slot [4] registered [ 0.245218] acpiphp: Slot [11] registered [ 0.247143] acpiphp: Slot [12] registered [ 0.248121] acpiphp: Slot [13] registered [ 0.250135] acpiphp: Slot [14] registered [ 0.251120] acpiphp: Slot [15] registered [ 0.253122] acpiphp: Slot [16] registered [ 0.254126] acpiphp: Slot [17] registered [ 0.256142] acpiphp: Slot [18] registered [ 0.257130] acpiphp: Slot [19] registered [ 0.259148] acpiphp: Slot [20] registered [ 0.261138] acpiphp: Slot [21] registered [ 0.262218] acpiphp: Slot [22] registered [ 0.264143] acpiphp: Slot [23] registered [ 0.266136] acpiphp: Slot [24] registered [ 0.267182] acpiphp: Slot [25] registered [ 0.268239] acpiphp: Slot [26] registered [ 0.270113] acpiphp: Slot [27] registered [ 0.272134] acpiphp: Slot [28] registered [ 0.273221] acpiphp: Slot [29] registered [ 0.275131] acpiphp: Slot [30] registered [ 0.276108] acpiphp: Slot [31] registered [ 0.277052] PCI host bridge to bus 0000:00 [ 0.279017] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.280028] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.281021] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.283025] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.286030] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.288046] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.290173] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.292880] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.296390] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.306786] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.311530] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.314025] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.316020] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.319020] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.321630] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.325108] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.328062] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.331862] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.337023] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.351017] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.357024] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.362870] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.371022] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.380020] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.398021] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.409771] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.416020] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.422017] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.442017] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.454937] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.461019] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.473018] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.492023] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.504956] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.510019] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.516020] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.536015] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.547099] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.554017] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.561021] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.581020] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 0.596094] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.604021] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.611019] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.628020] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 0.642479] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.644362] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.647396] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.649381] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.652254] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.657355] iommu: Default domain type: Passthrough [ 0.659481] SCSI subsystem initialized [ 0.661148] ACPI: bus type USB registered [ 0.663112] usbcore: registered new interface driver usbfs [ 0.664121] usbcore: registered new interface driver hub [ 0.667090] usbcore: registered new device driver usb [ 0.668258] pps_core: LinuxPPS API ver. 1 registered [ 0.670033] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.675083] PTP clock support registered [ 0.678110] EDAC MC: Ver: 3.0.0 [ 0.681117] PCI: Using ACPI for IRQ routing [ 0.682608] NetLabel: Initializing [ 0.684011] NetLabel: domain hash size = 128 [ 0.684795] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.685094] NetLabel: unlabeled traffic allowed by default [ 0.687107] vgaarb: loaded [ 0.688290] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.691040] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.699630] clocksource: Switched to clocksource kvm-clock [ 0.815498] VFS: Disk quotas dquot_6.6.0 [ 0.817038] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.819564] *** VALIDATE ramfs *** [ 0.820972] *** VALIDATE hugetlbfs *** [ 0.822600] pnp: PnP ACPI init [ 0.825180] pnp: PnP ACPI: found 6 devices [ 0.845387] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.848865] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.851145] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.853528] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.856216] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.858883] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.861626] NET: Registered protocol family 2 [ 0.863822] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.868991] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.871901] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.877186] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.880984] TCP: Hash tables configured (established 65536 bind 65536) [ 0.883814] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.886683] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.889206] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.892422] NET: Registered protocol family 1 [ 0.895691] RPC: Registered named UNIX socket transport module. [ 0.897659] RPC: Registered udp transport module. [ 0.899361] RPC: Registered tcp transport module. [ 0.901080] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.903505] NET: Registered protocol family 44 [ 0.905331] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.907186] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.908908] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.910724] PCI: CLS 0 bytes, default 64 [ 0.912336] Unpacking initramfs... [ 2.274443] debug: unmapping init [mem 0xffff8f773cc54000-0xffff8f773ffbffff] [ 2.278594] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.280400] software IO TLB: mapped [mem 0x00000000b8c54000-0x00000000bcc54000] (64MB) [ 2.283367] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 2.756565] Initialise system trusted keyrings [ 2.757949] Key type blacklist registered [ 2.759517] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.768740] zbud: loaded [ 2.771586] *** VALIDATE nfs *** [ 2.772709] *** VALIDATE nfs4 *** [ 2.774084] pstore: using deflate compression [ 2.777720] Platform Keyring initialized [ 2.875872] NET: Registered protocol family 38 [ 2.877666] Key type asymmetric registered [ 2.878996] Asymmetric key parser 'x509' registered [ 2.881290] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 2.884623] io scheduler mq-deadline registered [ 2.886270] io scheduler kyber registered [ 2.888198] io scheduler bfq registered [ 2.890420] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 2.893478] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 2.896291] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 2.899411] ACPI: Power Button [PWRF] [ 2.905937] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 2.912938] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 2.931818] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 2.939137] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 2.960222] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 2.987834] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.016594] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.022402] Non-volatile memory driver v1.3 [ 3.023450] Linux agpgart interface v0.103 [ 3.054815] virtio_blk virtio1: [vda] 149888 512-byte logical blocks (76.7 MB/73.2 MiB) [ 3.057581] vda: detected capacity change from 0 to 76742656 [ 3.078525] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.080411] vdb: detected capacity change from 0 to 1073741824 [ 3.092726] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.094736] vdc: detected capacity change from 0 to 2621440000 [ 3.106301] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.107987] vdd: detected capacity change from 0 to 2621440000 [ 3.120254] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.123041] vde: detected capacity change from 0 to 4294967296 [ 3.138884] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.141783] vdf: detected capacity change from 0 to 4294967296 [ 3.147101] libphy: Fixed MDIO Bus: probed [ 3.153188] usbcore: registered new interface driver usbserial_generic [ 3.155469] usbserial: USB Serial support registered for generic [ 3.157390] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.160745] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.162318] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.164470] mousedev: PS/2 mouse device common for all mice [ 3.168386] rtc_cmos 00:05: RTC can wake from S4 [ 3.173357] rtc_cmos 00:05: registered as rtc0 [ 3.173567] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.174503] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.178255] intel_pstate: CPU model not supported [ 3.180348] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.182545] hid: raw HID events driver (C) Jiri Kosina [ 3.184587] usbcore: registered new interface driver usbhid [ 3.186233] usbhid: USB HID core driver [ 3.187728] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.190485] drop_monitor: Initializing network drop monitor service [ 3.193043] Initializing XFRM netlink socket [ 3.194870] NET: Registered protocol family 10 [ 3.197920] Segment Routing with IPv6 [ 3.199356] NET: Registered protocol family 17 [ 3.200822] mpls_gso: MPLS GSO support [ 3.205342] RAS: Correctable Errors collector initialized. [ 3.206736] AVX version of gcm_enc/dec engaged. [ 3.208350] AES CTR mode by8 optimization enabled [ 3.280992] sched_clock: Marking stable (3280966310, 0)->(4220750624, -939784314) [ 3.284463] registered taskstats version 1 [ 3.286487] Loading compiled-in X.509 certificates [ 3.288364] zswap: loaded using pool lzo/zbud [ 3.309915] Key type big_key registered [ 3.319574] Key type encrypted registered [ 3.321019] ima: No TPM chip found, activating TPM-bypass! [ 3.322235] ima: Allocated hash algorithm: sha1 [ 3.323175] ima: No architecture policies found [ 3.324188] evm: Initialising EVM extended attributes: [ 3.325170] evm: security.selinux [ 3.325793] evm: security.ima [ 3.326390] evm: security.capability [ 3.327145] evm: HMAC attrs: 0x1 [ 3.328695] rtc_cmos 00:05: setting system clock to 2026-09-15 18:40:51 UTC (1789497651) [ 3.332365] debug: unmapping init [mem 0xffffffffaca03000-0xffffffffacbfffff] [ 3.334162] debug: unmapping init [mem 0xffffffffab782000-0xffffffffaba58fff] [ 3.342080] Write protecting the kernel read-only data: 28672k [ 3.344290] debug: unmapping init [mem 0xffffffffa9e03000-0xffffffffa9ffffff] [ 3.345913] debug: unmapping init [mem 0xffffffffaa714000-0xffffffffaa7fffff] [ 3.371423] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 3.376725] systemd[1]: Detected virtualization kvm. [ 3.377818] systemd[1]: Detected architecture x86-64. [ 3.378885] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.400747] systemd[1]: No hostname configured. [ 3.402542] systemd[1]: Set hostname to . [ 3.404384] random: systemd: uninitialized urandom read (16 bytes read) [ 3.406515] systemd[1]: Initializing machine ID from random generator. [ 3.462867] random: ln: uninitialized urandom read (6 bytes read) [ 3.541704] random: systemd: uninitialized urandom read (16 bytes read) [ 3.544045] systemd[1]: Listening on Journal Socket (/dev/log). [ OK ] Listening on Journal Socket (/dev/log). [ 3.547521] systemd[1]: Listening on udev Control Socket. [ OK ] Listening on udev Control Socket. [ 3.550809] systemd[1]: Started Dispatch Password Requests to Console Directory Watch. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Swap. [ OK ] Listening on udev Kernel Socket. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Listening on Journal Socket. Starting Setup Virtual Console... [ OK ] Reached target Slices. [ OK ] Reached target Timers. Starting Apply Kernel Variables... [ OK ] Reached target Sockets. [ OK ] Started Memstrack Anylazing Service. [ OK ] Reached target Paths. Starting Journal Service... [ OK ] Reached target Local File Systems. [ OK ] Reached target Initrd Root Device. Starting Create Volatile Files and Directories... Starting Create list of required st…ce nodes for the current kernel... [ OK ] Started Setup Virtual Console. [ 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. Starting Create Static Device Nodes in /dev... Starting dracut cmdline hook... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started Journal Service. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 4.126487] device-mapper: uevent: version 1.0.3 [ 4.128620] device-mapper: ioctl: 4.46.0-ioctl (2022-02-22) initialised: dm-devel@redhat.com [ OK ] Started dracut pre-udev hook. Starting udev Kernel Device Manager... [ OK ] Started udev Kernel Device Manager. Starting dracut pre-trigger hook... [ OK ] Started dracut pre-trigger hook. Starting udev Coldplug all Devices... Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. Starting dracut initqueue hook... [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ 4.750968] virtio_net virtio0 ens2: renamed from eth0 [ 4.760359] random: fast init done [ 4.792070] scsi host0: ata_piix [ 4.796208] scsi host1: ata_piix [ 4.797839] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 4.800443] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 8.564110] dracut-initqueue[578]: RTNETLINK answers: File exists [ 9.848287] random: crng init done [ 9.849761] random: 7 urandom warning(s) missed due to ratelimiting Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. Mounting /sysroot... [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. [ 10.218282] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped target Timers. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Paths. [ OK ] Stopped target Sockets. [ OK ] Stopped target System Initialization. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Swap. [ OK ] Stopped target Local File Systems. [ 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 target Slices. [ 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 Control Socket. [ OK ] Closed udev Kernel Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 11.256041] printk: systemd: 26 output lines suppressed due to ratelimiting [ 11.464674] SELinux: Disabled at runtime. [ 11.524355] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 11.530420] systemd[1]: Detected virtualization kvm. [ 11.531707] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 12.002140] systemd[1]: initrd-switch-root.service: Succeeded. [ 12.005630] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 12.009284] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 12.011586] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 12.013645] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 12.021606] systemd[1]: Starting Journal Service... Starting Journal Service... [ 12.029912] systemd[1]: Listening on RPCbind Server Activation Socket. [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Reached target RPC Port Mapper. [ OK ] Reached target rpc_pipefs.target. [ OK ] Listening on udev Kernel Socket. [ OK ] Created slice system-sshd\x2dkeygen.slice. Starting Create list of required st…ce nodes for the current kernel... Mounting POSIX Message Queue File System... Mounting Kernel Debug File System... [ OK ] Created slice system-getty.slice. Activating swap /dev/disk/by-label/SWAP... Mounting Huge Pages File System... [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. Starting Remount Root and Kernel File Systems... Starting Apply Kernel Variables... [ 12.115710] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd Root File System. [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Created slice User and Session Slice. [ OK ] Reached target Slices. [ OK ] Stopped target Initrd File Systems. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Listening on Process Core Dump Socket. [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. [ OK ] Listening on udev Control Socket. Starting udev Coldplug all Devices... [ OK ] Started Journal Service. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Mounted Kernel Debug File System. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Mounted Huge Pages File System. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Started Apply Kernel Variables. Starting Configure read-only root support... [ OK ] Reached target Swap. Starting Create Static Device Nodes in /dev... Starting Flush Journal to Persistent Storage... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Reached target Local File Systems (Pre). Mounting /mnt... Mounting /home/green/git/lustre-release... Starting udev Kernel Device Manager... [ OK ] Mounted /mnt. [ 12.411936] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Coldplug all Devices. [ OK ] Started udev Kernel Device Manager. [ 12.720077] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 12.813117] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 12.927605] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 12.937356] EDAC sbridge: Ver: 1.1.2 [ 14.514128] Key type dns_resolver registered [ 14.799198] NFS: Registering the id_resolver key type [ 14.801244] Key type id_resolver registered [ 14.802674] Key type id_legacy registered [ OK ] Started Configure read-only root support. [ OK ] Reached target Local File Systems. Starting Mark the need to relabel after reboot... Starting Create Volatile Files and Directories... Starting Rebuild Dynamic Linker Cache... 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 ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. Starting Restore /run/initramfs on shutdown... [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting Login Service... [ OK ] Reached target sshd-keygen.target. [ OK ] Started D-Bus System Message Bus. Starting Network Manager... [ OK ] Started irqbalance daemon. [ OK ] Started dnf makecache --timer. [ OK ] Reached target Timers. [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Login Service. [ OK ] Started Network Manager. Starting Network Manager Wait Online... [ OK ] Reached target Network. Starting GSSAPI Proxy Daemon... Starting Dynamic System Tuning Daemon... Starting OpenSSH server daemon... Starting Hostname Service... [ 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 OpenSSH server daemon. [ OK ] Started Permit User Sessions. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Command Scheduler. [ OK ] Started Serial Getty on ttyS1. [ OK ] Started Getty on tty1. [ OK ] Reached target Login Prompts. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting System Logging Service... Starting Crash recovery kernel arming... Starting Notify NFS peers of a restart... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Starting Authorization Manager... [ OK ] Started Authorization Manager. [ OK ] Started Dynamic System Tuning Daemon. [ OK ] Reached target Multi-User System. [ OK ] Reached target Graphical Interface. Starting Update UTMP about System Runlevel Changes... [ OK ] Started Update UTMP about System Runlevel Changes. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg114-server login: [ 31.700136] hrtimer: interrupt took 22125837 ns [ 61.052875] libcfs: loading out-of-tree module taints kernel. [ 61.199595] Key type ._llcrypt registered [ 61.211239] Key type .llcrypt registered [ 61.413144] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_hostid [ 82.794851] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing load_modules_local [ 85.096978] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 85.133154] alg: No test for adler32 (adler32-zlib) [ 87.132518] Lustre: Lustre: Build Version: 2.17.58_39_g104cf8c [ 88.346965] LNet: Added LNI 192.168.201.114@tcp [8/256/0/180] [ 90.208642] Key type lgssc registered [ 92.696874] Lustre: Echo OBD driver; http://www.lustre.org/ [ 115.592573] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 168.431573] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing load_modules_local [ 185.486751] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 185.525536] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 187.032358] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 187.071952] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 187.218163] Lustre: lustre-MDT0000: new disk, initializing [ 187.352531] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 187.386283] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 191.869539] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 210.714213] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 210.832678] Lustre: 6511:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 210.868402] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 210.872108] Lustre: Skipped 1 previous similar message [ 210.963732] Lustre: lustre-MDT0001: new disk, initializing [ 211.047136] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 211.065246] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 211.072053] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 215.700626] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 221.382748] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 237.114302] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 237.503713] Lustre: lustre-OST0000: new disk, initializing [ 237.507634] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 237.523744] Lustre: 8450:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 237.619029] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 244.276508] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 244.281871] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 244.388959] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 246.670204] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 264.716517] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 264.966161] Lustre: lustre-OST0001: new disk, initializing [ 264.973267] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 264.984439] Lustre: 9523:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 265.138044] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 271.772946] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 272.478630] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 272.490372] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 272.565974] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 284.465076] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 290.641238] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 298.186860] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing check_logdir /tmp/testlogs/ [ 303.419430] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing yml_node [ 307.831458] Lustre: DEBUG MARKER: Client: 2.17.58.39 [ 311.284587] Lustre: DEBUG MARKER: MDS: 2.17.58.39 [ 314.830765] Lustre: DEBUG MARKER: OSS: 2.17.58.39 [ 316.598281] Lustre: DEBUG MARKER: -----============= acceptance-small: replay-dual ============----- Tue Sep 15 14:46:03 EDT 2026 [ 337.865696] Lustre: DEBUG MARKER: excepting tests: 14b 21b [ 339.702863] Lustre: DEBUG MARKER: skipping tests SLOW=no: 21b [ 341.687420] Lustre: DEBUG MARKER: === replay-dual: start setup 14:46:28 (1789497988) === [ 349.757120] Lustre: DEBUG MARKER: oleg114-client.virtnet: executing check_config_client /mnt/lustre [ 376.543622] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 381.136677] Lustre: 13384:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 385.582409] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug -1 all [ 391.749186] Lustre: DEBUG MARKER: === replay-dual: finish setup 14:47:18 (1789498038) === [ 393.641567] Lustre: DEBUG MARKER: == replay-dual test 0a: expired recovery with lost client ========================================================== 14:47:20 (1789498040) [ 401.472110] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 405.897860] Lustre: Failing over lustre-MDT0000 [ 405.988121] 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 [ 406.003079] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 406.008413] Lustre: Skipped 1 previous similar message [ 406.029907] Lustre: Skipped 2 previous similar messages [ 406.327226] Lustre: server umount lustre-MDT0000 complete [ 410.593370] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 410.606405] 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 [ 410.625044] Lustre: Skipped 1 previous similar message [ 414.669672] LustreError: 9530:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.201.14@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 414.689944] LustreError: 9530:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 8 previous similar messages [ 416.243309] LustreError: 6521:0:(ldlm_lib.c:1199: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. [ 416.279157] LustreError: 6521:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 3 previous similar messages [ 419.804751] LustreError: 6516:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.201.14@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 419.832238] LustreError: 6516:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 1 previous similar message [ 424.913497] LustreError: 13486:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.201.14@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 424.931710] LustreError: 13486:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 4 previous similar messages [ 427.499306] Lustre: 3641:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789498059/real 1789498059] req@ffff8f7684cc6300 x1876424378149888/t0(0) o400->MGC192.168.201.114@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789498075 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 427.531716] LustreError: MGC192.168.201.114@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 430.032906] LustreError: 6517:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.201.14@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 430.063840] LustreError: 6517:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 12 previous similar messages [ 430.911806] LDISKFS-fs (dm-0): 10 truncates cleaned up [ 430.913683] LDISKFS-fs (dm-0): recovery complete [ 430.923603] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 437.758361] LustreError: 3639:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8f77b180aa00 x1876424378158720/t0(0) o250->MGC192.168.201.114@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 [ 438.289106] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 439.013389] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 443.391736] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 445.763905] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug -1 all [ 546.500673] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 546.506662] Lustre: 14927:0:(genops.c:1600:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client ce7116d5-2af1-4713-9338-7698a4fe6f8a@192.168.201.14@tcp [ 546.522061] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 546.545891] Lustre: lustre-MDT0000-osp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 546.546409] Lustre: 14927:0:(ldlm_lib.c:2985:target_recovery_thread()) too long recovery - read logs [ 546.557407] Lustre: Skipped 2 previous similar messages [ 546.570360] LustreError: dumping log to /tmp/lustre-log.1789498194.14927 [ 546.723301] Lustre: lustre-MDT0000: Recovery over after 1:47, of 3 clients 2 recovered and 1 was evicted. [ 546.759113] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:28 to 0x2c0000401:65) [ 546.764285] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:28 to 0x280000401:65) [ 570.239337] Lustre: DEBUG MARKER: == replay-dual test 0b: lost client during waiting for next transno ========================================================== 14:50:16 (1789498216) [ 580.080433] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 582.263169] Lustre: Failing over lustre-MDT0000 [ 582.556855] Lustre: server umount lustre-MDT0000 complete [ 582.629537] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 582.638058] 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 [ 582.654414] LustreError: 6521:0:(ldlm_lib.c:1199: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. [ 582.669476] LustreError: 6521:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 12 previous similar messages [ 586.735831] 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 [ 586.760182] Lustre: Skipped 1 previous similar message [ 600.601938] LustreError: 6517:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.201.14@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 600.645172] LustreError: 6517:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 15 previous similar messages [ 602.455666] Lustre: 3642:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789498234/real 1789498234] req@ffff8f77b1813480 x1876424378233728/t0(0) o400->MGC192.168.201.114@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789498250 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 602.495625] LustreError: MGC192.168.201.114@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 607.782964] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 607.790411] LDISKFS-fs (dm-0): recovery complete [ 607.828800] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 612.845027] LustreError: 3639:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8f77b91eea00 x1876424378242176/t0(0) o250->MGC192.168.201.114@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 [ 613.149303] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 613.203856] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 614.569960] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 618.498170] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 618.660796] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug -1 all [ 632.290166] Lustre: lustre-MDT0000: Denying connection for new client f65e8b81-876a-4aba-ae6f-9448fd994aec (at 192.168.201.14@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:52 [ 637.387382] Lustre: lustre-MDT0000: Denying connection for new client f65e8b81-876a-4aba-ae6f-9448fd994aec (at 192.168.201.14@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:47 [ 642.508312] Lustre: lustre-MDT0000: Denying connection for new client f65e8b81-876a-4aba-ae6f-9448fd994aec (at 192.168.201.14@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:41 [ 644.081168] Lustre: lustre-MDT0001: haven't heard from client ce7116d5-2af1-4713-9338-7698a4fe6f8a (at 192.168.201.14@tcp) in 102 seconds. I think it's dead, and I am evicting it. exp ffff8f77bf40b800, cur 1789498292 deadline 1789498290 last 1789498190 [ 647.629092] Lustre: lustre-MDT0000: Denying connection for new client f65e8b81-876a-4aba-ae6f-9448fd994aec (at 192.168.201.14@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:36 [ 652.746713] Lustre: lustre-MDT0000: Denying connection for new client f65e8b81-876a-4aba-ae6f-9448fd994aec (at 192.168.201.14@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:31 [ 663.003048] Lustre: lustre-MDT0000: Denying connection for new client f65e8b81-876a-4aba-ae6f-9448fd994aec (at 192.168.201.14@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:21 [ 663.033633] Lustre: Skipped 1 previous similar message [ 683.476238] Lustre: lustre-MDT0000: Denying connection for new client f65e8b81-876a-4aba-ae6f-9448fd994aec (at 192.168.201.14@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:01 [ 683.497699] Lustre: Skipped 3 previous similar messages [ 684.500221] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 684.503229] Lustre: 16673:0:(genops.c:1600:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client fb53e974-8435-4cde-90b0-f6eb0bf3cde2@ [ 684.509699] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 719.305439] Lustre: lustre-MDT0000: Denying connection for new client f65e8b81-876a-4aba-ae6f-9448fd994aec (at 192.168.201.14@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 1 evicted) to recover in 1:06 [ 719.320036] Lustre: Skipped 6 previous similar messages [ 720.872048] Lustre: lustre-MDT0001: haven't heard from client 90f1633d-f602-4fa1-bf41-d249fc39402e (at 192.168.201.14@tcp) in 101 seconds. I think it's dead, and I am evicting it. exp ffff8f77bf36b000, cur 1789498369 deadline 1789498368 last 1789498268 [ 785.501340] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 785.514445] Lustre: 16673:0:(genops.c:1600:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 90f1633d-f602-4fa1-bf41-d249fc39402e@192.168.201.14@tcp [ 785.533890] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 785.539961] Lustre: 16673:0:(ldlm_lib.c:2119:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 785.559812] Lustre: lustre-MDT0000-osp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 785.561506] Lustre: 16673:0:(ldlm_lib.c:2985:target_recovery_thread()) too long recovery - read logs [ 785.568303] Lustre: Skipped 2 previous similar messages [ 785.600675] LustreError: dumping log to /tmp/lustre-log.1789498433.16673 [ 785.834286] Lustre: lustre-MDT0000: Recovery over after 2:51, of 3 clients 1 recovered and 2 were evicted. [ 785.912209] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:28 to 0x280000401:97) [ 785.912830] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:28 to 0x2c0000401:97) [ 796.181924] Lustre: DEBUG MARKER: == replay-dual test 1: |X| simple create ================= 14:54:02 (1789498442) [ 804.145992] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 806.063120] Lustre: Failing over lustre-MDT0000 [ 806.369886] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 806.378340] 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 [ 806.402035] Lustre: Skipped 1 previous similar message [ 806.424020] LustreError: 6522:0:(ldlm_lib.c:1199: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. [ 806.454814] LustreError: 6522:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 14 previous similar messages [ 806.526343] Lustre: server umount lustre-MDT0000 complete [ 824.290706] Lustre: 3641:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789498456/real 1789498456] req@ffff8f77bb7f1180 x1876424378325376/t0(0) o400->MGC192.168.201.114@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789498472 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 824.312847] LustreError: MGC192.168.201.114@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 829.784271] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 829.790126] LDISKFS-fs (dm-0): recovery complete [ 829.800400] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 834.533828] LustreError: 3639:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8f7782db2300 x1876424378333568/t0(0) o250->MGC192.168.201.114@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 [ 835.018081] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 835.122669] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 835.419269] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 840.217020] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 840.452026] Lustre: lustre-MDT0000: Recovery over after 0:05, of 3 clients 3 recovered and 0 were evicted. [ 840.571585] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:129) [ 840.591542] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:129) [ 840.883187] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug -1 all [ 850.340342] Lustre: DEBUG MARKER: oleg114-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 852.679595] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 863.014878] Lustre: DEBUG MARKER: == replay-dual test 2: |X| mkdir adir ==================== 14:55:09 (1789498509) [ 872.564558] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 875.220919] Lustre: Failing over lustre-MDT0000 [ 875.846351] Lustre: server umount lustre-MDT0000 complete [ 876.010762] 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 [ 876.027142] LustreError: 6522:0:(ldlm_lib.c:1199: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. [ 876.035136] Lustre: Skipped 4 previous similar messages [ 876.092864] LustreError: 6522:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 45 previous similar messages [ 892.451332] Lustre: 3640:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789498524/real 1789498524] req@ffff8f7682166a00 x1876424378363392/t0(0) o400->MGC192.168.201.114@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789498540 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 892.492966] LustreError: MGC192.168.201.114@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 902.234872] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 902.237353] LDISKFS-fs (dm-0): recovery complete [ 902.255623] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 917.489445] LustreError: 3639:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8f77abdc4000 x1876424378376832/t0(0) o250->MGC192.168.201.114@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 [ 917.958777] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 918.061636] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 918.835054] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 923.124285] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 923.132537] Lustre: Skipped 3 previous similar messages [ 923.264900] Lustre: lustre-MDT0000: Recovery over after 0:05, of 3 clients 3 recovered and 0 were evicted. [ 923.324461] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:161) [ 923.334534] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:161) [ 923.381498] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug -1 all [ 935.398882] Lustre: DEBUG MARKER: oleg114-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 937.211048] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 947.515301] Lustre: DEBUG MARKER: == replay-dual test 3: |X| mkdir adir, mkdir adir/bdir === 14:56:34 (1789498594) [ 957.095774] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 960.011588] Lustre: Failing over lustre-MDT0000 [ 960.330067] Lustre: server umount lustre-MDT0000 complete [ 964.075792] 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 [ 964.091757] Lustre: Skipped 4 previous similar messages [ 980.452253] Lustre: 3640:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789498612/real 1789498612] req@ffff8f7683762d80 x1876424378413568/t0(0) o400->MGC192.168.201.114@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789498628 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 980.496886] LustreError: MGC192.168.201.114@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 987.709080] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 987.714403] LDISKFS-fs (dm-0): recovery complete [ 987.728350] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 989.919191] LustreError: 22271:0:(import.c:339:ptlrpc_invalidate_import()) MGS: timeout waiting for callback (1 != 0) [ 989.933062] LustreError: 22271:0:(import.c:363:ptlrpc_invalidate_import()) @@@ still on sending list req@ffff8f76827b9500 x1876424378419328/t0(0) o250->MGC192.168.201.114@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 1789498638 ref 1 fl Rpc:NQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 989.956537] LustreError: 22271:0:(import.c:373:ptlrpc_invalidate_import()) MGS: Unregistering RPCs found (0). Network is sluggish? Waiting for them to error out. [ 991.099737] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 991.164702] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 991.792850] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 994.968621] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug -1 all [ 996.369395] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 996.390028] Lustre: Skipped 3 previous similar messages [ 996.565147] Lustre: lustre-MDT0000: Recovery over after 0:05, of 3 clients 3 recovered and 0 were evicted. [ 996.617126] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:193) [ 996.625758] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:193) [ 1005.792791] Lustre: DEBUG MARKER: oleg114-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1007.156693] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1016.730434] Lustre: DEBUG MARKER: == replay-dual test 4: |X| mkdir adir (-EEXIST), mkdir adir/bdir ========================================================== 14:57:43 (1789498663) [ 1026.454645] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1028.537441] Lustre: Failing over lustre-MDT0000 [ 1028.863827] Lustre: server umount lustre-MDT0000 complete [ 1032.175775] 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 [ 1032.189140] LustreError: 6521:0:(ldlm_lib.c:1199: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. [ 1032.197192] Lustre: Skipped 4 previous similar messages [ 1032.217753] LustreError: 6521:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 96 previous similar messages [ 1048.609609] Lustre: 3642:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789498680/real 1789498680] req@ffff8f7782db6300 x1876424378460288/t0(0) o400->MGC192.168.201.114@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789498696 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1048.650034] LustreError: MGC192.168.201.114@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1054.785992] LDISKFS-fs (dm-0): 4 truncates cleaned up [ 1054.789138] LDISKFS-fs (dm-0): recovery complete [ 1054.802072] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1058.285658] LustreError: 3639:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8f7782d96680 x1876424378468736/t0(0) o250->MGC192.168.201.114@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 [ 1058.828261] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1059.281207] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 1063.773788] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug -1 all [ 1063.925614] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1063.939072] Lustre: Skipped 3 previous similar messages [ 1064.107669] Lustre: lustre-MDT0000: Recovery over after 0:05, of 3 clients 3 recovered and 0 were evicted. [ 1064.181625] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:225) [ 1064.183300] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:225) [ 1075.154086] Lustre: DEBUG MARKER: oleg114-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1077.019971] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1086.205204] Lustre: DEBUG MARKER: == replay-dual test 5: open, unlink |X| close ============ 14:58:53 (1789498733) [ 1095.942125] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1098.149314] Lustre: Failing over lustre-MDT0000 [ 1098.561557] Lustre: server umount lustre-MDT0000 complete [ 1099.751078] 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 [ 1099.767704] Lustre: Skipped 3 previous similar messages [ 1115.103263] Lustre: 3641:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789498747/real 1789498747] req@ffff8f77b4a44700 x1876424378499584/t0(0) o400->MGC192.168.201.114@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789498763 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1115.130558] LustreError: MGC192.168.201.114@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1121.930935] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1121.936826] LDISKFS-fs (dm-0): recovery complete [ 1121.944832] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1125.350604] LustreError: 3639:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8f77bb7f0380 x1876424378506880/t0(0) o250->MGC192.168.201.114@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 [ 1125.776283] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1125.780501] Lustre: Skipped 1 previous similar message [ 1125.836650] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1125.847408] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 1130.853539] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug -1 all [ 1130.995736] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1131.001360] Lustre: Skipped 3 previous similar messages [ 1131.207512] Lustre: lustre-MDT0000: Recovery over after 0:06, of 3 clients 3 recovered and 0 were evicted. [ 1131.270656] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:257) [ 1131.272555] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:257) [ 1141.392416] Lustre: DEBUG MARKER: oleg114-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1143.436563] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1152.682930] Lustre: DEBUG MARKER: == replay-dual test 6: open1, open2, unlink |X| close1 [fail mds1] close2 ========================================================== 14:59:59 (1789498799) [ 1160.937740] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1163.626357] Lustre: Failing over lustre-MDT0000 [ 1163.918632] Lustre: server umount lustre-MDT0000 complete [ 1182.113698] Lustre: 3640:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789498814/real 1789498814] req@ffff8f768500a300 x1876424378536192/t0(0) o400->MGC192.168.201.114@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789498830 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1182.163867] LustreError: MGC192.168.201.114@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1188.075551] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1188.078589] LDISKFS-fs (dm-0): recovery complete [ 1188.086625] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1192.426828] LustreError: 3639:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8f7681af0380 x1876424378544384/t0(0) o250->MGC192.168.201.114@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 [ 1192.858876] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1194.076709] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 1198.173835] Lustre: lustre-MDT0000: Recovery over after 0:04, of 3 clients 3 recovered and 0 were evicted. [ 1198.181666] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug -1 all [ 1198.226739] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:289) [ 1198.227918] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:289) [ 1208.991853] Lustre: DEBUG MARKER: oleg114-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1210.497325] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1220.315965] Lustre: DEBUG MARKER: == replay-dual test 8: replay of resent request ========== 15:01:07 (1789498867) [ 1230.003332] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1231.260042] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 1231.272235] LustreError: 9530:0:(ldlm_lib.c:3382:target_send_reply_msg()) @@@ dropping reply req@ffff8f7682166300 x1876424355246592/t38654705670(0) o36->f65e8b81-876a-4aba-ae6f-9448fd994aec@192.168.201.14@tcp:155/0 lens 512/448 e 0 to 0 dl 1789498890 ref 1 fl Interpret:/200/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 1246.694157] Lustre: lustre-MDT0000: Client f65e8b81-876a-4aba-ae6f-9448fd994aec (at 192.168.201.14@tcp) reconnecting [ 1246.715827] Lustre: 6516:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff8f7782db3480 x1876424355246592/t38654705670(0) o36->f65e8b81-876a-4aba-ae6f-9448fd994aec@192.168.201.14@tcp:170/0 lens 512/2880 e 0 to 0 dl 1789498905 ref 1 fl Interpret:/202/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 1250.672956] Lustre: Failing over lustre-MDT0000 [ 1250.958921] Lustre: server umount lustre-MDT0000 complete [ 1254.371353] 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 [ 1254.401814] Lustre: Skipped 5 previous similar messages [ 1270.210899] Lustre: 3640:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789498902/real 1789498902] req@ffff8f77b99e1180 x1876424378581632/t0(0) o400->MGC192.168.201.114@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789498918 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1270.253381] LustreError: MGC192.168.201.114@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1274.851428] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1274.854251] LDISKFS-fs (dm-0): recovery complete [ 1274.868626] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1280.957924] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1281.628774] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 1286.143514] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1286.151795] Lustre: Skipped 7 previous similar messages [ 1286.322316] Lustre: lustre-MDT0000: Recovery over after 0:05, of 3 clients 3 recovered and 0 were evicted. [ 1286.397487] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:321) [ 1286.398295] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:321) [ 1287.674731] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug -1 all [ 1300.418154] Lustre: DEBUG MARKER: oleg114-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1302.501242] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1312.737552] Lustre: DEBUG MARKER: == replay-dual test 9: resending a replayed create ======= 15:02:39 (1789498959) [ 1324.146997] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1328.377742] Lustre: Failing over lustre-MDT0000 [ 1328.943730] Lustre: server umount lustre-MDT0000 complete [ 1332.196156] LustreError: 7891:0:(ldlm_lib.c:1199: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. [ 1332.226940] LustreError: 7891:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 153 previous similar messages [ 1353.603221] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1353.605637] LDISKFS-fs (dm-0): recovery complete [ 1353.619666] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1359.347759] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1364.523609] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 1364.532142] LustreError: 32197:0:(ldlm_lib.c:3382:target_send_reply_msg()) @@@ dropping reply req@ffff8f7682457b80 x1876424355266560/t42949672962(42949672962) o36->f65e8b81-876a-4aba-ae6f-9448fd994aec@192.168.201.14@tcp:285/0 lens 528/448 e 0 to 0 dl 1789499020 ref 1 fl Complete:/204/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 1364.667770] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug -1 all [ 1377.589858] Lustre: lustre-MDT0000: Client f65e8b81-876a-4aba-ae6f-9448fd994aec (at 192.168.201.14@tcp) reconnected, waiting for 3 clients in recovery for 1:27 [ 1377.796310] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:353) [ 1377.800352] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:353) [ 1384.721084] Lustre: DEBUG MARKER: oleg114-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1386.329548] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1395.870669] Lustre: DEBUG MARKER: == replay-dual test 10: resending a replayed unlink ====== 15:04:03 (1789499043) [ 1404.031761] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1406.809629] Lustre: Failing over lustre-MDT0000 [ 1407.125859] Lustre: server umount lustre-MDT0000 complete [ 1408.482211] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1426.785242] Lustre: 3643:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789499058/real 1789499058] req@ffff8f7782db0700 x1876424378665984/t0(0) o400->MGC192.168.201.114@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789499074 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1426.817304] Lustre: 3643:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 1426.829837] LustreError: MGC192.168.201.114@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1426.840246] LustreError: Skipped 1 previous similar message [ 1431.409626] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1431.412141] LDISKFS-fs (dm-0): recovery complete [ 1431.418604] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1437.174408] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x17a4b0d063ebe8e0 [ 1437.511861] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1437.516755] Lustre: Skipped 3 previous similar messages [ 1438.157362] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 1438.167910] Lustre: Skipped 1 previous similar message [ 1442.651920] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug -1 all [ 1442.877361] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 1442.890793] LustreError: 34256:0:(ldlm_lib.c:3382:target_send_reply_msg()) @@@ dropping reply req@ffff8f77b4a46680 x1876424355288192/t47244640260(47244640260) o36->f65e8b81-876a-4aba-ae6f-9448fd994aec@192.168.201.14@tcp:362/0 lens 528/448 e 0 to 0 dl 1789499097 ref 1 fl Complete:/204/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 1453.547938] Lustre: lustre-MDT0000: Client f65e8b81-876a-4aba-ae6f-9448fd994aec (at 192.168.201.14@tcp) reconnected, waiting for 3 clients in recovery for 1:29 [ 1453.629493] Lustre: lustre-MDT0000: Recovery over after 0:15, of 3 clients 3 recovered and 0 were evicted. [ 1453.642792] Lustre: Skipped 1 previous similar message [ 1453.687355] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:385) [ 1453.690846] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:385) [ 1459.534446] Lustre: DEBUG MARKER: oleg114-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1461.441733] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1471.003534] Lustre: DEBUG MARKER: == replay-dual test 11: both clients timeout during replay ========================================================== 15:05:18 (1789499118) [ 1479.602282] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1482.856676] Lustre: Failing over lustre-MDT0000 [ 1483.147676] Lustre: server umount lustre-MDT0000 complete [ 1509.188623] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1509.191814] LDISKFS-fs (dm-0): recovery complete [ 1509.199584] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1524.726173] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x17a4b0d063ebef54 [ 1525.140458] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1525.143610] Lustre: Skipped 1 previous similar message [ 1529.424680] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug -1 all [ 1530.403141] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 1530.407421] LustreError: 36295:0:(ldlm_lib.c:3382:target_send_reply_msg()) @@@ dropping reply req@ffff8f77b9f70380 x1876424355306752/t51539607554(51539607554) o36->f65e8b81-876a-4aba-ae6f-9448fd994aec@192.168.201.14@tcp:449/0 lens 528/448 e 0 to 0 dl 1789499184 ref 1 fl Complete:/204/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 1536.897450] Lustre: DEBUG MARKER: oleg114-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1540.603351] Lustre: lustre-MDT0000: Client f65e8b81-876a-4aba-ae6f-9448fd994aec (at 192.168.201.14@tcp) reconnected, waiting for 3 clients in recovery for 1:29 [ 1540.763209] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:417) [ 1540.763645] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:417) [ 1542.996959] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 4 sec [ 1551.004376] Lustre: DEBUG MARKER: == replay-dual test 12: open resend timeout ============== 15:06:38 (1789499198) [ 1559.850375] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1563.134719] Lustre: Failing over lustre-MDT0000 [ 1563.371665] Lustre: server umount lustre-MDT0000 complete [ 1566.179662] 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 [ 1566.205631] Lustre: Skipped 17 previous similar messages [ 1587.631139] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1587.637289] LDISKFS-fs (dm-0): recovery complete [ 1587.645869] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1592.816652] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x17a4b0d063ebf64d [ 1592.821583] Lustre: MGC192.168.201.114@tcp: Connection restored to 0@lo (at 0@lo) [ 1592.825323] Lustre: Skipped 17 previous similar messages [ 1598.603089] Lustre: *** cfs_fail_loc=302, val=2147483648*** [ 1598.967046] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug -1 all [ 1614.848526] Lustre: lustre-MDT0000: Client f65e8b81-876a-4aba-ae6f-9448fd994aec (at 192.168.201.14@tcp) reconnected, waiting for 3 clients in recovery for 1:24 [ 1615.029249] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:449) [ 1615.030958] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:449) [ 1622.943054] Lustre: DEBUG MARKER: == replay-dual test 13: close resend timeout ============= 15:07:49 (1789499269) [ 1633.151653] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1636.706194] Lustre: Failing over lustre-MDT0000 [ 1637.159115] Lustre: server umount lustre-MDT0000 complete [ 1663.841724] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1663.855248] LDISKFS-fs (dm-0): recovery complete [ 1663.873142] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1670.194350] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug -1 all [ 1670.714950] Lustre: *** cfs_fail_loc=115, val=2147483648*** [ 1687.049499] Lustre: lustre-MDT0000: Client f65e8b81-876a-4aba-ae6f-9448fd994aec (at 192.168.201.14@tcp) reconnected, waiting for 3 clients in recovery for 1:24 [ 1687.197888] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:481) [ 1687.211698] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:481) [ 1694.536545] Lustre: DEBUG MARKER: SKIP: replay-dual test_14b skipping ALWAYS excluded test 14b [ 1696.265253] Lustre: DEBUG MARKER: == replay-dual test 15a: timeout waiting for lost client during replay, 1 client completes ========================================================== 15:09:03 (1789499343) [ 1704.029050] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1706.931146] Lustre: Failing over lustre-MDT0000 [ 1707.354519] Lustre: server umount lustre-MDT0000 complete [ 1708.001957] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1727.967474] Lustre: 3642:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789499359/real 1789499359] req@ffff8f7683c8b100 x1876424378822912/t0(0) o400->MGC192.168.201.114@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789499375 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1728.022701] Lustre: 3642:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 1728.045817] LustreError: MGC192.168.201.114@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1728.067324] LustreError: Skipped 3 previous similar messages [ 1733.966301] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1733.969297] LDISKFS-fs (dm-0): recovery complete [ 1733.976301] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1739.233617] LustreError: 41931:0:(import.c:339:ptlrpc_invalidate_import()) MGS: timeout waiting for callback (1 != 0) [ 1739.243865] LustreError: 41931:0:(import.c:363:ptlrpc_invalidate_import()) @@@ still on sending list req@ffff8f77b5b9b480 x1876424378828544/t0(0) o250->MGC192.168.201.114@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 1789499386 ref 1 fl Rpc:NQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1739.281328] LustreError: 41931:0:(import.c:373:ptlrpc_invalidate_import()) MGS: Unregistering RPCs found (0). Network is sluggish? Waiting for them to error out. [ 1739.809450] LustreError: 3639:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8f7791ec5500 x1876424378832384/t0(0) o250->MGC192.168.201.114@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 [ 1742.007110] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 1742.014996] Lustre: Skipped 3 previous similar messages [ 1745.353771] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug -1 all [ 1812.501443] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 1812.508921] Lustre: 41964:0:(genops.c:1600:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 71e90221-6de0-4117-9036-0c45d6ae2194@ [ 1812.523089] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 1813.386991] Lustre: lustre-MDT0000: Recovery over after 1:11, of 3 clients 2 recovered and 1 was evicted. [ 1813.396229] Lustre: Skipped 3 previous similar messages [ 1813.438277] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:494 to 0x2c0000401:513) [ 1813.441305] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:495 to 0x280000401:513) [ 1821.033594] Lustre: DEBUG MARKER: oleg114-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1823.176771] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1833.142280] Lustre: DEBUG MARKER: == replay-dual test 15c: remove multiple OST orphans ===== 15:11:19 (1789499479) [ 1841.734402] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1947.618761] Lustre: Failing over lustre-MDT0000 [ 1948.085738] Lustre: server umount lustre-MDT0000 complete [ 1949.159861] LustreError: 9530:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.201.14@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1949.177721] LustreError: 9530:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 253 previous similar messages [ 1972.266166] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1972.268655] LDISKFS-fs (dm-0): recovery complete [ 1972.279516] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1977.177774] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1977.181966] Lustre: Skipped 4 previous similar messages [ 1977.228553] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1977.243358] Lustre: Skipped 3 previous similar messages [ 1982.009594] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug -1 all [ 2047.500147] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 2047.508391] Lustre: 43978:0:(genops.c:1600:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 32524460-6a93-4824-b207-a29ee336e871@ [ 2047.534623] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 2047.678071] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:495 to 0x280000401:1537) [ 2047.678472] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:494 to 0x2c0000401:1537) [ 2056.192474] Lustre: DEBUG MARKER: oleg114-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2058.642234] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2069.137715] Lustre: DEBUG MARKER: == replay-dual test 16: fail MDS during recovery (3571) == 15:15:16 (1789499716) [ 2078.215224] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2081.701969] Lustre: Failing over lustre-MDT0000 [ 2081.760230] Lustre: lustre-MDT0000: Not available for connect from 192.168.201.14@tcp (stopping) [ 2082.171757] Lustre: server umount lustre-MDT0000 complete [ 2083.809427] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 2083.811876] 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 [ 2083.820792] Lustre: Skipped 12 previous similar messages [ 2105.473469] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2105.476233] LDISKFS-fs (dm-0): recovery complete [ 2105.481687] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2111.469033] LustreError: 3639:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8f77b5944000 x1876424379013376/t0(0) o250->MGC192.168.201.114@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 [ 2117.056706] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug -1 all [ 2117.120337] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 2117.132112] Lustre: Skipped 16 previous similar messages [ 2142.066380] Lustre: Failing over lustre-MDT0000 [ 2142.096593] LustreError: 46422:0:(ldlm_lib.c:3038:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 2142.113508] Lustre: 45947:0:(ldlm_lib.c:2438:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 2142.132927] Lustre: 45947:0:(ldlm_lib.c:1948:abort_req_replay_queue()) @@@ aborted: req@ffff8f7687c95500 x1876424357767424/t0(73014444033) o36->f65e8b81-876a-4aba-ae6f-9448fd994aec@192.168.201.14@tcp:305/0 lens 528/0 e 2 to 0 dl 1789499795 ref 1 fl Complete:/204/ffffffff rc 0/-1 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 2142.171881] Lustre: lustre-MDT0000-osd: cancel update llog [0x200000400:0x1:0x0] [ 2142.193829] Lustre: lustre-MDT0000: Not available for connect from 192.168.201.14@tcp (stopping) [ 2142.220524] Lustre: lustre-MDT0001-osp-MDT0000: cancel update llog [0x240000401:0x1:0x0] [ 2142.234815] LustreError: 45947:0:(client.c:1394:ptlrpc_import_delay_req()) @@@ IMP_CLOSED req@ffff8f77bf42e300 x1876424379034752/t0(0) o700->lustre-MDT0001-osp-MDT0000@0@lo:30/10 lens 264/248 e 0 to 0 dl 0 ref 2 fl Rpc:QU/200/ffffffff rc 0/-1 job:'tgt_recover_0.0' uid:0 gid:0 projid:4294967295 [ 2142.256435] LustreError: 45947:0:(fid_request.c:217:seq_client_alloc_seq()) cli-cli-lustre-MDT0001-osp-MDT0000: Cannot allocate new meta-sequence: rc = -5 [ 2142.263059] LustreError: 45947:0:(fid_request.c:321:seq_client_alloc_fid()) cli-cli-lustre-MDT0001-osp-MDT0000: Can't allocate new sequence: rc = -5 [ 2142.727060] Lustre: server umount lustre-MDT0000 complete [ 2161.861627] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2167.430408] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug -1 all [ 2232.500172] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 2232.509840] Lustre: 46877:0:(genops.c:1600:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client baff88ce-e721-4471-81c0-acf6bd2c8445@ [ 2232.528484] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 2233.458945] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1551 to 0x2c0000401:1569) [ 2233.460920] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1550 to 0x280000401:1569) [ 2244.155710] Lustre: DEBUG MARKER: oleg114-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2246.244498] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2259.992718] Lustre: DEBUG MARKER: == replay-dual test 17: fail OST during recovery (3571) == 15:18:27 (1789499907) [ 2271.964708] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 2274.196209] Lustre: Failing over lustre-OST0000 [ 2274.324803] Lustre: server umount lustre-OST0000 complete [ 2274.785849] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 2301.046551] LDISKFS-fs (dm-2): 3 truncates cleaned up [ 2301.055482] LDISKFS-fs (dm-2): recovery complete [ 2301.071723] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2302.441387] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 4 clients reconnect [ 2302.455956] Lustre: Skipped 3 previous similar messages [ 2308.721812] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug -1 all [ 2334.074631] Lustre: Failing over lustre-OST0000 [ 2334.086989] LustreError: 49395:0:(ldlm_lib.c:3038:target_stop_recovery_thread()) lustre-OST0000: Aborting recovery [ 2334.092356] Lustre: 48829:0:(ldlm_lib.c:2438:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 2334.096717] Lustre: 48829:0:(ldlm_lib.c:2438:target_recovery_overseer()) Skipped 2 previous similar messages [ 2334.102325] LustreError: 48829:0:(ofd_obd.c:1325:ofd_iocontrol()) lustre-OST0000: iocontrol from 'tgt_recover_0' cmd=c00866c1 _IOWR('f', 193, 8) unrecognized: rc = -25 [ 2334.110401] Lustre: lustre-OST0000: Recovery over after 0:32, of 4 clients 0 recovered and 4 were evicted. [ 2334.115912] Lustre: Skipped 3 previous similar messages [ 2334.311933] Lustre: server umount lustre-OST0000 complete [ 2352.785050] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2355.104109] Lustre: 3639:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789499951/real 1789499951] req@ffff8f77c14b5f80 x1876424379111808/t0(0) o400->lustre-OST0000-osc-MDT0001@0@lo:28/4 lens 224/224 e 3 to 1 dl 1789500003 ref 1 fl Rpc:XQr/2c0/ffffffff rc 0/-1 job:'ldlm_lock_repla.0' uid:0 gid:0 projid:4294967295 [ 2355.127285] Lustre: 3639:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 2358.452182] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug -1 all [ 2424.500177] Lustre: lustre-OST0000: recovery is timed out, evict stale exports [ 2424.507611] Lustre: 49840:0:(genops.c:1600:class_disconnect_stale_exports()) lustre-OST0000: disconnect stale client 0801b734-f1b4-43e5-ab36-6b65a7a2cae2@ [ 2424.527075] Lustre: lustre-OST0000: disconnecting 1 stale clients [ 2429.707884] Lustre: DEBUG MARKER: oleg114-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 2431.205580] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 2440.356156] Lustre: DEBUG MARKER: == replay-dual test 18: ldlm_handle_enqueue succeeds on evicted export (3822) ========================================================== 15:21:27 (1789500087) [ 2444.933593] LustreError: 13486:0:(ldlm_lockd.c:1361:ldlm_handle_enqueue()) cfs_fail_timeout id 30b sleeping for 40000ms [ 2484.968335] LustreError: 13486:0:(ldlm_lockd.c:1361:ldlm_handle_enqueue()) cfs_fail_timeout id 30b awake [ 2499.034601] Lustre: DEBUG MARKER: == replay-dual test 19: resend of open request =========== 15:22:25 (1789500145) [ 2507.359062] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2508.877431] Lustre: *** cfs_fail_loc=157, val=2147483648*** [ 2508.880992] LustreError: 6518:0:(ldlm_lib.c:3382:target_send_reply_msg()) @@@ dropping reply req@ffff8f77abe70700 x1876424357894016/t0(0) o101->f65e8b81-876a-4aba-ae6f-9448fd994aec@192.168.201.14@tcp:749/0 lens 576/688 e 0 to 0 dl 1789500239 ref 1 fl Interpret:/600/0 rc 0/0 job:'createmany.0' uid:0 gid:0 projid:0 [ 2596.301341] Lustre: lustre-MDT0000: Client f65e8b81-876a-4aba-ae6f-9448fd994aec (at 192.168.201.14@tcp) reconnecting [ 2599.981721] Lustre: Failing over lustre-MDT0000 [ 2600.277488] Lustre: server umount lustre-MDT0000 complete [ 2600.940292] LustreError: 17063:0:(ldlm_lib.c:1199: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. [ 2600.954624] LustreError: 17063:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 108 previous similar messages [ 2617.314586] LustreError: MGC192.168.201.114@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2617.325059] LustreError: Skipped 3 previous similar messages [ 2623.930377] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2623.932134] LDISKFS-fs (dm-0): recovery complete [ 2623.942772] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2627.571057] LustreError: 3639:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8f76810a7b80 x1876424379259264/t0(0) o250->MGC192.168.201.114@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 [ 2627.972550] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 2627.977106] Lustre: Skipped 4 previous similar messages [ 2628.028176] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 2628.040727] Lustre: Skipped 4 previous similar messages [ 2633.244419] Lustre: 52485:0:(ldlm_lib.c:2119:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 2633.411919] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug -1 all [ 2633.456378] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1584 to 0x2c0000401:1601) [ 2633.459565] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1584 to 0x280000401:1601) [ 2643.923472] Lustre: DEBUG MARKER: oleg114-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2645.526987] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2654.812679] Lustre: DEBUG MARKER: == replay-dual test 20: recovery time is not increasing == 15:25:01 (1789500301) [ 2663.164079] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2665.816773] Lustre: Failing over lustre-MDT0000 [ 2666.189306] Lustre: server umount lustre-MDT0000 complete [ 2689.487590] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2689.496417] LDISKFS-fs (dm-0): recovery complete [ 2689.516312] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2696.259134] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x17a4b0d063ee2fae [ 2702.038208] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug -1 all [ 2838.500342] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 2838.503520] Lustre: 54429:0:(genops.c:1600:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 8a0d5045-0830-4a0c-861b-ee535e65afda@ [ 2838.512913] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 2838.534325] Lustre: 54429:0:(ldlm_lib.c:2119:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 2838.539403] Lustre: 54429:0:(ldlm_lib.c:2119:extend_recovery_timer()) Skipped 6 previous similar messages [ 2838.597970] Lustre: lustre-MDT0000-osp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 2838.614002] Lustre: Skipped 16 previous similar messages [ 2838.656864] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1584 to 0x280000401:1633) [ 2838.659362] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1603 to 0x2c0000401:1633) [ 2844.923599] Lustre: DEBUG MARKER: oleg114-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2846.661629] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2857.721152] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2859.892662] Lustre: Failing over lustre-MDT0000 [ 2860.132364] Lustre: server umount lustre-MDT0000 complete [ 2860.514620] 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 [ 2860.531191] Lustre: Skipped 19 previous similar messages [ 2884.845587] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2884.848131] LDISKFS-fs (dm-0): recovery complete [ 2884.854170] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2886.047227] LustreError: 56179:0:(import.c:339:ptlrpc_invalidate_import()) MGS: timeout waiting for callback (1 != 0) [ 2886.060510] LustreError: 56179:0:(import.c:363:ptlrpc_invalidate_import()) @@@ still on sending list req@ffff8f77bb7f3100 x1876424379372416/t0(0) o250->MGC192.168.201.114@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 1789500534 ref 1 fl Rpc:NQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2886.085207] LustreError: 56179:0:(import.c:373:ptlrpc_invalidate_import()) MGS: Unregistering RPCs found (0). Network is sluggish? Waiting for them to error out. [ 2886.123259] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x17a4b0d063ee35b2 [ 2891.072814] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug -1 all [ 3032.502941] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 3032.516283] Lustre: 56213:0:(genops.c:1600:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 5d65189c-2525-41cc-b040-0d9ff555f13e@ [ 3032.539471] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 3032.629534] Lustre: 56213:0:(ldlm_lib.c:2119:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3032.651535] Lustre: 56213:0:(ldlm_lib.c:2119:extend_recovery_timer()) Skipped 4 previous similar messages [ 3032.768449] Lustre: lustre-MDT0000: Recovery over after 2:21, of 3 clients 2 recovered and 1 was evicted. [ 3032.781937] Lustre: Skipped 3 previous similar messages [ 3032.852533] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1635 to 0x280000401:1665) [ 3032.857929] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1603 to 0x2c0000401:1665) [ 3042.761294] Lustre: DEBUG MARKER: oleg114-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3044.744788] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3055.626958] Lustre: DEBUG MARKER: == replay-dual test 21a: commit on sharing =============== 15:31:42 (1789500702) [ 3064.327946] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3066.589492] Lustre: Failing over lustre-MDT0000 [ 3066.934096] Lustre: server umount lustre-MDT0000 complete [ 3068.907418] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3085.282058] Lustre: 3643:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789500717/real 1789500717] req@ffff8f77b9f49f80 x1876424379456256/t0(0) o400->MGC192.168.201.114@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789500733 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3085.307766] Lustre: 3643:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 4 previous similar messages [ 3090.533232] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3090.535667] LDISKFS-fs (dm-0): recovery complete [ 3090.563623] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3095.522078] LustreError: 3639:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8f77c0d17100 x1876424379465344/t0(0) o250->MGC192.168.201.114@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 0 ref 1 fl Rpc:NQU/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3096.942415] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 3096.962623] Lustre: Skipped 4 previous similar messages [ 3101.571874] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug -1 all [ 3236.500170] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 3236.507073] Lustre: 58255:0:(genops.c:1600:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client eb68bc00-2728-48ab-b4be-8f0569f21774@ [ 3236.524115] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 3236.571893] Lustre: 58255:0:(ldlm_lib.c:2119:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3236.588413] Lustre: 58255:0:(ldlm_lib.c:2119:extend_recovery_timer()) Skipped 4 previous similar messages [ 3236.692516] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1603 to 0x2c0000401:1697) [ 3236.697681] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1667 to 0x280000401:1697) [ 3247.022478] Lustre: DEBUG MARKER: SKIP: replay-dual test_21b skipping SLOW test 21b [ 3248.777006] Lustre: DEBUG MARKER: == replay-dual test 22a: c1 lfs mkdir -i 1 dir1, M1 drop reply [ 3249.770463] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 3249.772438] LustreError: 6518:0:(ldlm_lib.c:3382:target_send_reply_msg()) @@@ dropping reply req@ffff8f7788783b80 x1876424358015616/t4294967346(0) o36->f65e8b81-876a-4aba-ae6f-9448fd994aec@192.168.201.14@tcp:733/0 lens 560/448 e 0 to 0 dl 1789500978 ref 1 fl Interpret:/200/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 3252.739400] Lustre: Failing over lustre-MDT0001 [ 3253.125917] Lustre: server umount lustre-MDT0001 complete [ 3254.758811] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 3254.775416] LustreError: 13486:0:(ldlm_lib.c:1199: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. [ 3254.794979] LustreError: 13486:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 142 previous similar messages [ 3272.712987] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3273.139106] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 3273.148279] Lustre: Skipped 3 previous similar messages [ 3273.193421] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 3273.224107] Lustre: Skipped 3 previous similar messages [ 3277.989644] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug -1 all [ 3278.412860] Lustre: 17063:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff8f77b4a46a00 x1876424358015616/t4294967346(0) o36->f65e8b81-876a-4aba-ae6f-9448fd994aec@192.168.201.14@tcp:7/0 lens 560/2880 e 0 to 0 dl 1789501007 ref 1 fl Interpret:/202/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 3288.979460] Lustre: DEBUG MARKER: oleg114-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 3290.884226] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3302.166475] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3304.498665] Lustre: Failing over lustre-MDT0000 [ 3304.885286] Lustre: server umount lustre-MDT0000 complete [ 3309.027478] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3325.407349] LustreError: MGC192.168.201.114@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3325.415585] LustreError: Skipped 3 previous similar messages [ 3330.009705] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3330.012691] LDISKFS-fs (dm-0): recovery complete [ 3330.021450] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3335.669947] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x17a4b0d063ee448b [ 3340.136739] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug -1 all [ 3341.366589] Lustre: 61325:0:(ldlm_lib.c:2119:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3341.492868] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1603 to 0x2c0000401:1729) [ 3341.494320] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1667 to 0x280000401:1729) [ 3350.889269] Lustre: DEBUG MARKER: oleg114-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3352.865590] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3362.597295] Lustre: DEBUG MARKER: == replay-dual test 22b: c1 lfs mkdir -i 1 d1, M1 drop reply [ 3364.063874] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 3364.070808] LustreError: 9530:0:(ldlm_lib.c:3382:target_send_reply_msg()) @@@ dropping reply req@ffff8f77c0d10700 x1876424358057728/t8589934617(0) o36->f65e8b81-876a-4aba-ae6f-9448fd994aec@192.168.201.14@tcp:92/0 lens 560/448 e 0 to 0 dl 1789501092 ref 1 fl Interpret:/200/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 3366.652543] Lustre: Failing over lustre-MDT0000 [ 3366.938640] Lustre: server umount lustre-MDT0000 complete [ 3370.715798] LustreError: 6503:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1789501018 with bad export cookie 1703680968129135755 [ 3370.724747] Lustre: Failing over lustre-MDT0001 [ 3370.747987] LustreError: 6503:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 3371.172826] Lustre: server umount lustre-MDT0001 complete [ 3392.485382] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3392.489385] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3392.669199] LustreError: 63175:0:(llog.c:1655:llog_backup()) MGC192.168.201.114@tcp: failed to open log lustre-sptlrpc: rc = -108 [ 3392.673856] Lustre: 63175:0:(mgc_request_server.c:770:mgc_llog_local_copy()) MGC192.168.201.114@tcp: failed to copy new config lustre-sptlrpc: rc = -108 [ 3395.525024] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x17a4b0d063ee4bca [ 3401.002381] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug -1 all [ 3401.440666] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug -1 all [ 3401.807017] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1667 to 0x280000401:1761) [ 3401.832339] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1603 to 0x2c0000401:1761) [ 3401.898803] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:36 to 0x2c0000400:65) [ 3401.902389] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:36 to 0x280000400:65) [ 3402.036348] Lustre: 63189:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff8f7687c95c00 x1876424358057728/t8589934617(0) o36->f65e8b81-876a-4aba-ae6f-9448fd994aec@192.168.201.14@tcp:130/0 lens 560/2880 e 0 to 0 dl 1789501130 ref 1 fl Interpret:/202/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 3411.162962] Lustre: DEBUG MARKER: oleg114-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 3412.825456] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3414.820614] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3425.620762] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3428.344090] Lustre: Failing over lustre-MDT0000 [ 3428.930338] Lustre: server umount lustre-MDT0000 complete [ 3432.430618] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3451.703681] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3451.705623] LDISKFS-fs (dm-0): recovery complete [ 3451.713465] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3458.546245] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x17a4b0d063ee54c2 [ 3458.556245] Lustre: MGC192.168.201.114@tcp: Connection restored to 0@lo (at 0@lo) [ 3458.564569] Lustre: Skipped 24 previous similar messages [ 3464.251963] Lustre: 65399:0:(ldlm_lib.c:2119:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3464.261037] Lustre: 65399:0:(ldlm_lib.c:2119:extend_recovery_timer()) Skipped 4 previous similar messages [ 3464.364893] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1667 to 0x280000401:1793) [ 3464.365664] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1603 to 0x2c0000401:1793) [ 3464.479366] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug -1 all [ 3476.711420] Lustre: DEBUG MARKER: oleg114-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3478.422884] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3488.206888] Lustre: DEBUG MARKER: == replay-dual test 22c: c1 lfs mkdir -i 1 d1, M1 drop update [ 3489.584216] Lustre: *** cfs_fail_loc=1701, val=2147483648*** [ 3489.588036] LustreError: 63794:0:(ldlm_lib.c:3382:target_send_reply_msg()) @@@ dropping reply req@ffff8f77b52aa300 x1876424379679872/t107374182411(0) o1000->lustre-MDT0001-mdtlov_UUID@0@lo:148/0 lens 2520/4320 e 0 to 0 dl 1789501148 ref 1 fl Interpret:/200/0 rc 0/0 job:'osp_up0-1.0' uid:0 gid:0 projid:4294967295 [ 3493.344845] Lustre: Failing over lustre-MDT0000 [ 3493.779785] Lustre: server umount lustre-MDT0000 complete [ 3494.887309] 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 [ 3494.912427] Lustre: Skipped 23 previous similar messages [ 3512.614637] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3521.532042] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x17a4b0d063ee5bd7 [ 3526.745877] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug -1 all [ 3527.241826] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1667 to 0x280000401:1825) [ 3527.244751] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1603 to 0x2c0000401:1825) [ 3537.369609] Lustre: DEBUG MARKER: oleg114-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3539.147355] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3549.746810] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3552.406176] Lustre: Failing over lustre-MDT0000 [ 3552.743156] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3552.778282] Lustre: server umount lustre-MDT0000 complete [ 3577.470750] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3577.473476] LDISKFS-fs (dm-0): recovery complete [ 3577.479837] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3584.488842] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x17a4b0d063ee6283 [ 3589.620262] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug -1 all [ 3590.167105] Lustre: 68597:0:(ldlm_lib.c:2119:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3590.183449] Lustre: 68597:0:(ldlm_lib.c:2119:extend_recovery_timer()) Skipped 4 previous similar messages [ 3590.288082] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1667 to 0x280000401:1857) [ 3590.290775] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1603 to 0x2c0000401:1857) [ 3601.300942] Lustre: DEBUG MARKER: oleg114-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3603.236727] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3613.799670] Lustre: DEBUG MARKER: == replay-dual test 22d: c1 lfs mkdir -i 1 d1, M1 drop update [ 3618.842261] Lustre: *** cfs_fail_loc=1701, val=2147483648*** [ 3618.852771] LustreError: 63794:0:(ldlm_lib.c:3382:target_send_reply_msg()) @@@ dropping reply req@ffff8f77a5ae0e00 x1876424379757184/t115964117002(0) o1000->lustre-MDT0001-mdtlov_UUID@0@lo:278/0 lens 2520/4320 e 0 to 0 dl 1789501278 ref 1 fl Interpret:/200/0 rc 0/0 job:'osp_up0-1.0' uid:0 gid:0 projid:4294967295 [ 3622.758592] Lustre: Failing over lustre-MDT0000 [ 3623.420940] Lustre: server umount lustre-MDT0000 complete [ 3628.011067] LustreError: 6502:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1789501276 with bad export cookie 1703680968129143427 [ 3628.028119] Lustre: Failing over lustre-MDT0001 [ 3628.033232] LustreError: 6502:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 3 previous similar messages [ 3628.045848] LustreError: 69835:0:(ldlm_resource.c:1207:ldlm_resource_complain()) lustre-MDT0000-osp-MDT0001: namespace resource [0x2000013a1:0x79:0x0].0xf7117594 (ffff8f7783535700) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 3628.105100] Lustre: lustre-MDT0001: Not available for connect from 192.168.201.14@tcp (stopping) [ 3631.087295] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 3633.135467] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 3633.147162] Lustre: Skipped 4 previous similar messages [ 3634.422314] Lustre: server umount lustre-MDT0001 complete [ 3655.397804] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3655.437484] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3655.832253] LustreError: 70541:0:(llog.c:1655:llog_backup()) MGC192.168.201.114@tcp: failed to open log lustre-sptlrpc: rc = -108 [ 3655.838668] Lustre: 70541:0:(mgc_request_server.c:770:mgc_llog_local_copy()) MGC192.168.201.114@tcp: failed to copy new config lustre-sptlrpc: rc = -108 [ 3679.620919] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug -1 all [ 3680.219340] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug -1 all [ 3680.261519] Lustre: lustre-MDT0000: Recovery over after 0:05, of 3 clients 3 recovered and 0 were evicted. [ 3680.264905] Lustre: Skipped 8 previous similar messages [ 3680.286663] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1603 to 0x2c0000401:1889) [ 3680.290186] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1667 to 0x280000401:1889) [ 3680.421241] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:70 to 0x280000400:97) [ 3680.421271] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:70 to 0x2c0000400:97) [ 3680.615972] Lustre: 70553:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff8f77a5ae5c00 x1876424358149888/t12884901939(0) o36->f65e8b81-876a-4aba-ae6f-9448fd994aec@192.168.201.14@tcp:408/0 lens 560/2880 e 0 to 0 dl 1789501408 ref 1 fl Interpret:/202/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 3690.554385] Lustre: DEBUG MARKER: oleg114-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 3692.168836] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3693.608545] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3703.465893] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3706.059844] Lustre: Failing over lustre-MDT0000 [ 3706.400046] Lustre: server umount lustre-MDT0000 complete [ 3710.951506] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3727.839729] Lustre: 3643:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789501359/real 1789501359] req@ffff8f77bf47dc00 x1876424379799808/t0(0) o400->MGC192.168.201.114@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789501375 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3727.881622] Lustre: 3643:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 17 previous similar messages [ 3729.605707] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3729.608507] LDISKFS-fs (dm-0): recovery complete [ 3729.613615] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3738.098387] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x17a4b0d063ee7266 [ 3738.817787] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 3738.823238] Lustre: Skipped 9 previous similar messages [ 3742.399292] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug -1 all [ 3743.821054] Lustre: 72765:0:(ldlm_lib.c:2119:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3743.833521] Lustre: 72765:0:(ldlm_lib.c:2119:extend_recovery_timer()) Skipped 4 previous similar messages [ 3744.030217] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1603 to 0x2c0000401:1921) [ 3744.032564] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1667 to 0x280000401:1921) [ 3754.100549] Lustre: DEBUG MARKER: oleg114-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3756.876903] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3770.616558] Lustre: DEBUG MARKER: == replay-dual test 23a: c1 rmdir d1, M1 drop reply and fail, client2 mkdir d1 ========================================================== 15:43:36 (1789501416) [ 3772.395629] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 3772.413042] LustreError: 70551:0:(ldlm_lib.c:3382:target_send_reply_msg()) @@@ dropping reply req@ffff8f7785950a80 x1876424358198656/t17179869210(0) o36->f65e8b81-876a-4aba-ae6f-9448fd994aec@192.168.201.14@tcp:500/0 lens 496/456 e 0 to 0 dl 1789501500 ref 1 fl Interpret:/200/0 rc 0/0 job:'rmdir.0' uid:0 gid:0 projid:4294967295 [ 3776.950664] Lustre: Failing over lustre-MDT0001 [ 3777.674913] Lustre: server umount lustre-MDT0001 complete [ 3798.415478] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3803.260020] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug -1 all [ 3804.228207] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:100 to 0x2c0000400:129) [ 3804.249361] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:100 to 0x280000400:129) [ 3804.271457] Lustre: 71344:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff8f7785d35180 x1876424358198656/t17179869210(0) o36->f65e8b81-876a-4aba-ae6f-9448fd994aec@192.168.201.14@tcp:532/0 lens 496/2888 e 0 to 0 dl 1789501532 ref 1 fl Interpret:/202/0 rc 0/0 job:'rmdir.0' uid:0 gid:0 projid:4294967295 [ 3813.141453] Lustre: DEBUG MARKER: oleg114-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 3815.403305] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3825.057879] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3827.415825] Lustre: Failing over lustre-MDT0000 [ 3827.726690] Lustre: server umount lustre-MDT0000 complete [ 3851.172379] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3851.177200] LDISKFS-fs (dm-0): recovery complete [ 3851.190327] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3856.363381] LustreError: 70552:0:(ldlm_lib.c:1199: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. [ 3856.363658] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x17a4b0d063ee7e6e [ 3856.388918] LustreError: 70552:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 344 previous similar messages [ 3862.053621] Lustre: 75939:0:(ldlm_lib.c:2119:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3862.066173] Lustre: 75939:0:(ldlm_lib.c:2119:extend_recovery_timer()) Skipped 4 previous similar messages [ 3862.180468] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug -1 all [ 3862.295496] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1923 to 0x280000401:1953) [ 3862.303375] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1923 to 0x2c0000401:1953) [ 3873.242894] Lustre: DEBUG MARKER: oleg114-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3875.006195] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3885.251647] Lustre: DEBUG MARKER: == replay-dual test 23b: c1 rmdir d1, M1 drop reply and fail M0/M1, c2 mkdir d1 ========================================================== 15:45:32 (1789501532) [ 3886.787608] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 3886.793852] LustreError: 70553:0:(ldlm_lib.c:3382:target_send_reply_msg()) @@@ dropping reply req@ffff8f77abdc4380 x1876424358233600/t21474836483(0) o36->f65e8b81-876a-4aba-ae6f-9448fd994aec@192.168.201.14@tcp:614/0 lens 496/456 e 0 to 0 dl 1789501614 ref 1 fl Interpret:/200/0 rc 0/0 job:'rmdir.0' uid:0 gid:0 projid:4294967295 [ 3890.046204] Lustre: Failing over lustre-MDT0000 [ 3890.279951] Lustre: server umount lustre-MDT0000 complete [ 3892.206625] LustreError: 6504:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1789501540 with bad export cookie 1703680968129150679 [ 3893.394633] Lustre: Failing over lustre-MDT0001 [ 3893.854972] Lustre: server umount lustre-MDT0001 complete [ 3914.246291] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3914.259609] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3914.571272] LustreError: 77833:0:(llog.c:1655:llog_backup()) MGC192.168.201.114@tcp: failed to open log lustre-sptlrpc: rc = -108 [ 3914.577982] Lustre: 77833:0:(mgc_request_server.c:770:mgc_llog_local_copy()) MGC192.168.201.114@tcp: failed to copy new config lustre-sptlrpc: rc = -108 [ 3918.720983] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 3918.732545] Lustre: Skipped 11 previous similar messages [ 3918.775340] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 3918.783033] Lustre: Skipped 11 previous similar messages [ 3924.062939] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug -1 all [ 3924.587102] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug -1 all [ 3925.216836] Lustre: 77841:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff8f778438c380 x1876424358233600/t21474836483(0) o36->f65e8b81-876a-4aba-ae6f-9448fd994aec@192.168.201.14@tcp:653/0 lens 496/2888 e 0 to 0 dl 1789501653 ref 1 fl Interpret:/202/0 rc 0/0 job:'rmdir.0' uid:0 gid:0 projid:4294967295 [ 3925.236946] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:100 to 0x280000400:161) [ 3925.237475] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:100 to 0x2c0000400:161) [ 3932.683299] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1923 to 0x2c0000401:1985) [ 3932.685038] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1923 to 0x280000401:1985) [ 3939.733684] Lustre: DEBUG MARKER: oleg114-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 3941.821690] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3943.732101] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3954.687532] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3957.186898] Lustre: Failing over lustre-MDT0000 [ 3957.533532] Lustre: server umount lustre-MDT0000 complete [ 3958.241986] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3958.251910] LustreError: Skipped 2 previous similar messages [ 3975.651514] LustreError: MGC192.168.201.114@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3975.658489] LustreError: Skipped 8 previous similar messages [ 3982.870630] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3982.876848] LDISKFS-fs (dm-0): recovery complete [ 3982.890760] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3984.966347] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x17a4b0d063ee8de8 [ 3990.581224] Lustre: 80071:0:(ldlm_lib.c:2119:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3990.594653] Lustre: 80071:0:(ldlm_lib.c:2119:extend_recovery_timer()) Skipped 8 previous similar messages [ 3990.854150] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1987 to 0x280000401:2017) [ 3990.854533] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1987 to 0x2c0000401:2017) [ 3991.536664] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug -1 all [ 4002.953711] Lustre: DEBUG MARKER: oleg114-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4004.643521] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4013.984357] Lustre: DEBUG MARKER: == replay-dual test 23c: c1 rmdir d1, M0 drop update reply and fail M0, c2 mkdir d1 ========================================================== 15:47:41 (1789501661) [ 4015.370064] Lustre: *** cfs_fail_loc=1701, val=2147483648*** [ 4015.373267] LustreError: 8445:0:(ldlm_lib.c:3382:target_send_reply_msg()) @@@ dropping reply req@ffff8f7782d2df80 x1876424379992448/t137438953491(0) o1000->lustre-MDT0001-mdtlov_UUID@0@lo:674/0 lens 1984/4320 e 0 to 0 dl 1789501674 ref 1 fl Interpret:/200/0 rc 0/0 job:'osp_up0-1.0' uid:0 gid:0 projid:4294967295 [ 4018.588180] Lustre: Failing over lustre-MDT0000 [ 4018.935530] Lustre: server umount lustre-MDT0000 complete [ 4038.101716] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4053.413781] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug -1 all [ 4053.588249] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1987 to 0x280000401:2049) [ 4053.588394] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1987 to 0x2c0000401:2049) [ 4065.206854] Lustre: DEBUG MARKER: oleg114-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4067.565990] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4079.376477] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4081.918799] Lustre: Failing over lustre-MDT0000 [ 4082.310060] Lustre: server umount lustre-MDT0000 complete [ 4105.747403] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 4105.749323] LDISKFS-fs (dm-0): recovery complete [ 4105.770610] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4109.880517] Lustre: MGC192.168.201.114@tcp: Connection restored to 0@lo (at 0@lo) [ 4109.900286] Lustre: Skipped 48 previous similar messages [ 4115.901790] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2051 to 0x2c0000401:2081) [ 4115.912727] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2051 to 0x280000401:2081) [ 4116.164425] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug -1 all [ 4128.283106] Lustre: DEBUG MARKER: oleg114-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4130.716483] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4142.735855] Lustre: DEBUG MARKER: == replay-dual test 23d: c1 rmdir d1, M0 drop update reply and fail M0/M1, c2 mkdir d1 ========================================================== 15:49:49 (1789501789) [ 4147.414557] Lustre: *** cfs_fail_loc=1701, val=2147483648*** [ 4147.417395] LustreError: 8445:0:(ldlm_lib.c:3382:target_send_reply_msg()) @@@ dropping reply req@ffff8f7785e66d80 x1876424380072960/t146028888081(0) o1000->lustre-MDT0001-mdtlov_UUID@0@lo:51/0 lens 1984/4320 e 0 to 0 dl 1789501806 ref 1 fl Interpret:/200/0 rc 0/0 job:'osp_up0-1.0' uid:0 gid:0 projid:4294967295 [ 4151.086167] Lustre: Failing over lustre-MDT0000 [ 4151.267817] 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 [ 4151.276210] Lustre: Skipped 40 previous similar messages [ 4151.364331] Lustre: server umount lustre-MDT0000 complete [ 4154.606114] Lustre: Failing over lustre-MDT0001 [ 4154.608582] LustreError: 6503:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1789501802 with bad export cookie 1703680968129157847 [ 4154.618354] LustreError: 6503:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 5 previous similar messages [ 4154.624285] LustreError: 84499:0:(ldlm_resource.c:1207:ldlm_resource_complain()) lustre-MDT0000-osp-MDT0001: namespace resource [0x2000013a1:0x81:0x0].0x0 (ffff8f779475d300) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 4154.645980] Lustre: lustre-MDT0001: Not available for connect from 192.168.201.14@tcp (stopping) [ 4159.394449] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 4159.412265] Lustre: Skipped 5 previous similar messages [ 4160.396503] Lustre: server umount lustre-MDT0001 complete [ 4180.649659] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4180.836292] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4180.985830] LustreError: 85193:0:(llog.c:1655:llog_backup()) MGC192.168.201.114@tcp: failed to open log lustre-sptlrpc: rc = -108 [ 4180.993393] Lustre: 85193:0:(mgc_request_server.c:770:mgc_llog_local_copy()) MGC192.168.201.114@tcp: failed to copy new config lustre-sptlrpc: rc = -108 [ 4205.264705] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug -1 all [ 4205.291072] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug -1 all [ 4205.636450] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2051 to 0x280000401:2113) [ 4205.642804] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2051 to 0x2c0000401:2113) [ 4205.911306] Lustre: 85237:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff8f77b9de2300 x1876424358313984/t25769803783(0) o36->f65e8b81-876a-4aba-ae6f-9448fd994aec@192.168.201.14@tcp:179/0 lens 496/2888 e 0 to 0 dl 1789501934 ref 1 fl Interpret:/202/0 rc 0/0 job:'rmdir.0' uid:0 gid:0 projid:4294967295 [ 4205.945122] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:100 to 0x280000400:193) [ 4205.949413] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:100 to 0x2c0000400:193) [ 4217.592805] Lustre: DEBUG MARKER: oleg114-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 4220.070166] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4222.352600] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4235.310357] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4237.787885] Lustre: Failing over lustre-MDT0000 [ 4238.018707] Lustre: server umount lustre-MDT0000 complete [ 4262.374112] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 4262.375643] LDISKFS-fs (dm-0): recovery complete [ 4262.380563] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4267.024406] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x17a4b0d063eeaa51 [ 4267.040098] Lustre: Skipped 1 previous similar message [ 4272.353295] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug -1 all [ 4272.688429] Lustre: 87428:0:(ldlm_lib.c:2119:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 4272.701058] Lustre: 87428:0:(ldlm_lib.c:2119:extend_recovery_timer()) Skipped 17 previous similar messages [ 4272.927955] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2115 to 0x280000401:2145) [ 4272.928944] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2115 to 0x2c0000401:2145) [ 4282.094325] Lustre: DEBUG MARKER: oleg114-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4283.982495] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4294.762814] Lustre: DEBUG MARKER: == replay-dual test 24: reconstruct on non-existing object ========================================================== 15:52:21 (1789501941) [ 4296.193583] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 4296.201184] LustreError: 85214:0:(ldlm_lib.c:3382:target_send_reply_msg()) @@@ dropping reply req@ffff8f77b9de0380 x1876424358358144/t154618822673(0) o36->f65e8b81-876a-4aba-ae6f-9448fd994aec@192.168.201.14@tcp:269/0 lens 488/456 e 0 to 0 dl 1789502024 ref 1 fl Interpret:/200/0 rc 0/0 job:'truncate.0' uid:0 gid:0 projid:4294967295 [ 4381.201724] Lustre: lustre-MDT0000: Client f65e8b81-876a-4aba-ae6f-9448fd994aec (at 192.168.201.14@tcp) reconnecting [ 4381.218198] Lustre: 85214:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff8f77b05b7100 x1876424358358144/t154618822673(0) o36->f65e8b81-876a-4aba-ae6f-9448fd994aec@192.168.201.14@tcp:354/0 lens 488/3152 e 0 to 0 dl 1789502109 ref 1 fl Interpret:/202/0 rc 0/0 job:'truncate.0' uid:0 gid:0 projid:4294967295 [ 4388.518337] Lustre: DEBUG MARKER: == replay-dual test 25: replay|resend ==================== 15:53:55 (1789502035) [ 4393.110551] Lustre: Failing over lustre-OST0000 [ 4393.197305] Lustre: server umount lustre-OST0000 complete [ 4395.494102] LustreError: lustre-OST0000-osc-MDT0001: operation ost_statfs to node 0@lo failed: rc = -107 [ 4395.512374] LustreError: Skipped 1 previous similar message [ 4411.745698] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4413.497944] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 4 clients reconnect [ 4413.509617] Lustre: Skipped 10 previous similar messages [ 4414.221570] Lustre: lustre-OST0000: Recovery over after 0:01, of 4 clients 4 recovered and 0 were evicted. [ 4414.240125] Lustre: Skipped 12 previous similar messages [ 4418.941412] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug -1 all [ 4429.172735] Lustre: DEBUG MARKER: oleg114-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 4431.067585] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4441.905639] Lustre: DEBUG MARKER: == replay-dual test 26: dbench and tar with mds failover ========================================================== 15:54:48 (1789502088) [ 4454.257931] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4458.126429] Lustre: DEBUG MARKER: test_26 fail mds1 1 times [ 4460.486697] Lustre: Failing over lustre-MDT0000 [ 4460.785730] Lustre: lustre-MDT0000: Not available for connect from 192.168.201.14@tcp (stopping) [ 4461.166828] Lustre: server umount lustre-MDT0000 complete [ 4462.529065] LustreError: 85213:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.201.14@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4462.544841] LustreError: 85213:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 238 previous similar messages [ 4478.943114] Lustre: 3643:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789502111/real 1789502111] req@ffff8f77b4a44000 x1876424380272000/t0(0) o400->MGC192.168.201.114@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789502127 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4479.010812] Lustre: 3643:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 16 previous similar messages [ 4485.265607] LDISKFS-fs (dm-0): 4 truncates cleaned up [ 4485.267301] LDISKFS-fs (dm-0): recovery complete [ 4485.286428] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4489.185048] LustreError: 3639:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8f7688db5f80 x1876424380280960/t0(0) o250->MGC192.168.201.114@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 [ 4495.176876] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug -1 all [ 4496.684763] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2171 to 0x2c0000401:2209) [ 4496.685314] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2171 to 0x280000401:2209) [ 4507.482863] Lustre: DEBUG MARKER: oleg114-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4509.776218] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4523.726581] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 4527.862953] Lustre: DEBUG MARKER: test_26 fail mds2 2 times [ 4530.236347] Lustre: Failing over lustre-MDT0001 [ 4530.286954] Lustre: lustre-MDT0001: Not available for connect from 192.168.201.14@tcp (stopping) [ 4530.863356] Lustre: server umount lustre-MDT0001 complete [ 4555.878480] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 4555.882938] LDISKFS-fs (dm-1): recovery complete [ 4555.897429] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4556.783813] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 4556.796896] Lustre: Skipped 9 previous similar messages [ 4556.892103] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 4556.903073] Lustre: Skipped 9 previous similar messages [ 4561.938934] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug -1 all [ 4564.319093] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:288 to 0x2c0000400:321) [ 4564.322807] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:289 to 0x280000400:321) [ 4573.994741] Lustre: DEBUG MARKER: oleg114-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 4575.444441] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4589.256919] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4593.458497] Lustre: DEBUG MARKER: test_26 fail mds1 3 times [ 4596.217965] Lustre: Failing over lustre-MDT0000 [ 4596.270970] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4596.279894] Lustre: Skipped 6 previous similar messages [ 4596.571712] Lustre: server umount lustre-MDT0000 complete [ 4613.586424] LustreError: MGC192.168.201.114@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4613.596927] LustreError: Skipped 5 previous similar messages [ 4622.018920] LDISKFS-fs (dm-0): 3 truncates cleaned up [ 4622.021628] LDISKFS-fs (dm-0): recovery complete [ 4622.037314] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4623.205642] LustreError: 94903:0:(import.c:339:ptlrpc_invalidate_import()) MGS: timeout waiting for callback (1 != 0) [ 4623.210860] LustreError: 94903:0:(import.c:363:ptlrpc_invalidate_import()) @@@ still on sending list req@ffff8f77ba43e680 x1876424380627200/t0(0) o250->MGC192.168.201.114@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 1789502271 ref 1 fl Rpc:NQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4623.223134] LustreError: 94903:0:(import.c:373:ptlrpc_invalidate_import()) MGS: Unregistering RPCs found (0). Network is sluggish? Waiting for them to error out. [ 4629.438110] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug -1 all [ 4630.938800] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2279 to 0x2c0000401:2305) [ 4630.939316] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2280 to 0x280000401:2305) [ 4640.778679] Lustre: DEBUG MARKER: oleg114-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4642.895094] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4696.663521] Lustre: DEBUG MARKER: == replay-dual test 28: lock replay should be ordered: waiting after granted ========================================================== 15:59:03 (1789502343) [ 4711.284703] Lustre: Failing over lustre-OST0000 [ 4711.294609] Lustre: *** cfs_fail_loc=32a, val=0*** [ 4711.298377] LustreError: 15386:0:(client.c:1394:ptlrpc_import_delay_req()) @@@ IMP_CLOSED req@ffff8f77ba166680 x1876424381141760/t0(0) o105->lustre-OST0000@192.168.201.14@tcp:15/16 lens 392/224 e 0 to 0 dl 0 ref 1 fl Rpc:QU/0/ffffffff rc 0/-1 job:'' uid:4294967295 gid:4294967295 projid:4294967295 [ 4711.302635] LustreError: 96297:0:(ldlm_resource.c:1207:ldlm_resource_complain()) filter-lustre-OST0000_UUID: namespace resource [0x280000401:0x923:0x0].0x0 (ffff8f77bf498b00) refcount nonzero (2) after lock cleanup; forcing cleanup. [ 4711.341885] LustreError: 96297:0:(ldlm_resource.c:1207:ldlm_resource_complain()) Skipped 1 previous similar message [ 4711.647870] Lustre: server umount lustre-OST0000 complete [ 4730.953682] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4733.489923] Lustre: *** cfs_fail_loc=32a, val=0*** [ 4733.524642] Lustre: lustre-OST0000-osc-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4733.531765] Lustre: Skipped 29 previous similar messages [ 4738.812376] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug -1 all [ 4749.367866] Lustre: DEBUG MARKER: oleg114-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 4751.232519] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4762.022380] Lustre: DEBUG MARKER: == replay-dual test 29: replay vs update with the same xid ========================================================== 16:00:09 (1789502409) [ 4763.646701] Lustre: DEBUG MARKER: SKIP: replay-dual test_29 needs >= 2 clients [ 4765.481077] Lustre: DEBUG MARKER: == replay-dual test 30: layout lock replay is not blocked on IO ========================================================== 16:00:12 (1789502412) [ 4769.281483] Lustre: Failing over lustre-MDT0000 [ 4769.635593] Lustre: server umount lustre-MDT0000 complete [ 4772.321406] 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 [ 4772.338800] Lustre: Skipped 26 previous similar messages [ 4789.119461] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4797.923392] LustreError: 3639:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8f77b52c4380 x1876424381183360/t0(0) o250->MGC192.168.201.114@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 [ 4803.871094] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug -1 all [ 4803.966689] Lustre: 98267:0:(ldlm_lib.c:2119:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 4803.976235] Lustre: 98267:0:(ldlm_lib.c:2119:extend_recovery_timer()) Skipped 512 previous similar messages [ 4804.141286] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2340 to 0x280000401:2369) [ 4804.141689] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2339 to 0x2c0000401:2369) [ 4814.909749] Lustre: DEBUG MARKER: oleg114-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4816.593586] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4825.586254] Lustre: DEBUG MARKER: == replay-dual test 31: deadlock on file_remove_privs and occupied mod rpc slots ========================================================== 16:01:12 (1789502472) [ 4829.658479] Lustre: Failing over lustre-OST0000 [ 4829.998106] Lustre: server umount lustre-OST0000 complete [ 4849.778385] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4857.362335] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug -1 all [ 4868.583839] Lustre: DEBUG MARKER: oleg114-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 4870.146682] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in IDLE [ 4881.029718] Lustre: DEBUG MARKER: == replay-dual test 32: gap in update llog shouldn't break recovery ========================================================== 16:02:08 (1789502528) [ 4882.138026] Lustre: *** cfs_fail_loc=131d, val=10*** [ 4882.725309] Lustre: *** cfs_fail_loc=131d, val=0*** [ 4882.732790] Lustre: Skipped 9 previous similar messages [ 4883.788465] Lustre: *** cfs_fail_loc=131d, val=4294967280*** [ 4883.793280] Lustre: Skipped 15 previous similar messages [ 4886.883119] Lustre: Failing over lustre-MDT0001 [ 4887.030192] Lustre: lustre-MDT0001: Not available for connect from 192.168.201.14@tcp (stopping) [ 4887.038355] Lustre: Skipped 1 previous similar message [ 4887.233861] Lustre: server umount lustre-MDT0001 complete [ 4891.095868] Lustre: Failing over lustre-MDT0000 [ 4891.516871] Lustre: server umount lustre-MDT0000 complete [ 4899.866869] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4900.633939] Lustre: *** cfs_fail_loc=131d, val=4294967266*** [ 4900.639133] Lustre: Skipped 13 previous similar messages [ 4906.049101] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug -1 all [ 4914.502114] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4914.732425] Lustre: *** cfs_fail_loc=131d, val=4294967262*** [ 4914.737364] Lustre: Skipped 3 previous similar messages [ 4920.472970] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2409 to 0x280000401:2465) [ 4920.479965] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2339 to 0x2c0000401:2401) [ 4920.518855] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:360 to 0x2c0000400:385) [ 4920.521022] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:361 to 0x280000400:385) [ 4920.758792] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug -1 all [ 4933.024928] Lustre: DEBUG MARKER: == replay-dual test 33: Check for OBD_INCOMPAT_MULTI_RPCS in last_rcvd after abort_recovery ========================================================== 16:03:00 (1789502580) [ 4939.754142] Lustre: Failing over lustre-MDT0001 [ 4939.897114] Lustre: server umount lustre-MDT0001 complete [ 4959.666128] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4964.810647] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug -1 all [ 4973.664689] Lustre: DEBUG MARKER: oleg114-client.virtnet: executing wait_import_state_mount REPLAY_WAIT mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 4975.361592] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in REPLAY_WAIT state after 0 sec [ 4976.570809] Lustre: lustre-MDT0001: Aborting client recovery [ 4976.573679] LustreError: 104102:0:(ldlm_lib.c:3038:target_stop_recovery_thread()) lustre-MDT0001: Aborting recovery [ 4976.578586] Lustre: 103468:0:(ldlm_lib.c:2438:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 4976.586897] Lustre: 103468:0:(ldlm_lib.c:2438:target_recovery_overseer()) Skipped 2 previous similar messages [ 4976.595033] Lustre: 103468:0:(genops.c:1600:class_disconnect_stale_exports()) lustre-MDT0001: disconnect stale client db457174-1d3c-4312-bf49-7c70860c49f6@ [ 4976.604231] Lustre: lustre-MDT0001: disconnecting 1 stale clients [ 4976.621584] Lustre: lustre-MDT0001-osd: cancel update llog [0x240000400:0x1:0x0] [ 4976.637417] Lustre: lustre-MDT0000-osp-MDT0001: cancel update llog [0x200000401:0x1:0x0] [ 4976.735267] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:360 to 0x2c0000400:417) [ 4976.736405] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:361 to 0x280000400:417) [ 4982.670989] Lustre: DEBUG MARKER: oleg114-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 4984.466042] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4988.825272] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0001.recovery_status 1475 [ 4996.195730] Lustre: Failing over lustre-MDT0001 [ 4996.527592] Lustre: server umount lustre-MDT0001 complete [ 4997.093172] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 4997.102716] LustreError: Skipped 6 previous similar messages [ 5006.339182] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5011.771360] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug -1 all [ 5011.994059] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:361 to 0x280000400:449) [ 5011.994211] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:360 to 0x2c0000400:449) [ 5021.409360] Lustre: DEBUG MARKER: oleg114-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 5023.946607] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5029.621977] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0001.recovery_status 1475 [ 5038.468228] Lustre: DEBUG MARKER: == replay-dual test complete, duration 4720 sec ========== 16:04:45 (1789502685) [ 5039.940325] Lustre: DEBUG MARKER: === replay-dual: start cleanup 16:04:47 (1789502687) === [ 5050.346664] Lustre: DEBUG MARKER: === replay-dual: finish cleanup 16:04:57 (1789502697) === [ 5052.483241] Lustre: Failing over lustre-MDT0000 [ 5052.801859] Lustre: server umount lustre-MDT0000 complete [ 5063.139913] LustreError: 102218:0:(ldlm_lib.c:1199: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. [ 5063.169606] LustreError: 102218:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 221 previous similar messages [ 5080.910294] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5082.092649] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 5082.104966] Lustre: Skipped 10 previous similar messages [ 5087.682687] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5222.500309] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 5222.504221] Lustre: 107247:0:(genops.c:1600:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client db457174-1d3c-4312-bf49-7c70860c49f6@ [ 5222.528203] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 5222.548500] Lustre: lustre-MDT0000: Recovery over after 2:20, of 3 clients 2 recovered and 1 was evicted. [ 5222.570647] Lustre: Skipped 10 previous similar messages [ 5222.626120] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2339 to 0x2c0000401:2433) [ 5222.627761] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2409 to 0x280000401:2497) [ 5229.029643] Lustre: DEBUG MARKER: oleg114-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5230.566394] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5238.241912] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5238.245476] Lustre: Skipped 2 previous similar messages [ 5242.774695] Lustre: server umount lustre-MDT0000 complete [ 5251.488489] LustreError: 93751:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1789502899 with bad export cookie 1703680968129346084 [ 5251.489121] LustreError: MGC192.168.201.114@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5251.503847] LustreError: 93751:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 5251.521273] LustreError: Skipped 3 previous similar messages [ 5251.729151] Lustre: server umount lustre-MDT0001 complete [ 5270.804805] Lustre: server umount lustre-OST0000 complete [ 5288.362814] Lustre: server umount lustre-OST0001 complete [ 5306.633879] Lustre: DEBUG MARKER: oleg114-server.virtnet: executing unload_modules_local [ 5309.826692] Key type lgssc unregistered [ 5310.089632] LNet: 110186:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 5310.098306] LNetError: 110186:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 5310.119838] LNet: Removed LNI 192.168.201.114@tcp [ 5311.078082] Key type .llcrypt unregistered [ 5311.083716] Key type ._llcrypt unregistered