[ 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 487231469 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2399.998 MHz processor [ 0.000000] last_pfn = 0x146e00 max_arch_pfn = 0x400000000 [ 0.000000] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT [ 0.000000] last_pfn = 0xbffce max_arch_pfn = 0x400000000 [ 0.000000] found SMP MP-table at [mem 0x000f54b0-0x000f54bf] [ 0.000000] RAMDISK: [mem 0xbcc54000-0xbffbffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F52D0 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE247C 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE2318 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 0022D8 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE238C 000090 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE241C 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE2454 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe2318-0xbffe238b] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe2317] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe238c-0xbffe241b] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe241c-0xbffe2453] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe2454-0xbffe247b] [ 0.000000] No NUMA configuration found [ 0.000000] Faking a node at [mem 0x0000000000000000-0x0000000146dfffff] [ 0.000000] NODE_DATA(0) allocated [mem 0x1465a3000-0x1465cdfff] [ 0.000000] Reserving 256MB of memory at 2752MB for crashkernel (System RAM: 4205MB) [ 0.000000] Zone ranges: [ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.000000] DMA32 [mem 0x0000000001000000-0x00000000ffffffff] [ 0.000000] Normal [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Device empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff] [ 0.000000] node 0: [mem 0x0000000000100000-0x00000000bffcdfff] [ 0.000000] node 0: [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Zeroed struct page in unavailable ranges: 4756 pages [ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x0000000146dfffff] [ 0.000000] ACPI: PM-Timer IO Port: 0x608 [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) [ 0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) [ 0.000000] Using ACPI (MADT) for SMP configuration information [ 0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000] TSC deadline timer available [ 0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs [ 0.000000] kvm-guest: KVM setup pv remote TLB flush [ 0.000000] kvm-guest: setup PV sched yield [ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff] [ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff] [ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff] [ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff] [ 0.000000] PM: Registered nosave memory: [mem 0xbffce000-0xbfffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xc0000000-0xfeffbfff] [ 0.000000] PM: Registered nosave memory: [mem 0xfeffc000-0xfeffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xff000000-0xfffbffff] [ 0.000000] PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff] [ 0.000000] [mem 0xc0000000-0xfeffbfff] available for PCI devices [ 0.000000] Booting paravirtualized kernel on KVM [ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns [ 0.000000] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1 [ 0.000000] percpu: Embedded 63 pages/cpu s221184 r8192 d28672 u524288 [ 0.000000] kvm-guest: PV spinlocks enabled [ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1059606 [ 0.000000] Policy zone: Normal [ 0.000000] Kernel command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] Specific versions of hardware are certified with Red Hat Enterprise Linux 8. Please see the list of hardware certified with Red Hat Enterprise Linux 8 at https://catalog.redhat.com. [ 0.000000] audit: disabled (until reboot) [ 0.000000] software IO TLB: area num 4. [ 0.000000] Memory: 2829652K/4306352K available (18435K kernel code, 11221K rwdata, 7248K rodata, 2908K init, 18040K bss, 524580K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] ftrace: allocating 41240 entries in 162 pages [ 0.000000] ftrace: allocated 162 pages with 3 groups [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] rcu: RCU event tracing is enabled. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ 0.000000] rcu: RCU callback double-/use-after-free debug enabled. [ 0.000000] Rude variant of Tasks RCU enabled. [ 0.000000] Tracing variant of Tasks RCU enabled. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 0.000000] NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16 [ 0.000000] random: get_random_bytes called from start_kernel+0x622/0x9a8 with crng_init=0 [ 0.001000] Console: colour *CGA 80x25 [ 0.001000] printk: console [ttyS1] enabled [ 0.001000] ACPI: Core revision 20220331 [ 0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.001014] APIC: Switch to symmetric I/O mode setup [ 0.003218] x2apic enabled [ 0.004008] Switched APIC routing to physical x2apic. [ 0.005017] kvm-guest: setup PV IPIs [ 0.008367] ..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.009021] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.010014] pid_max: default: 32768 minimum: 301 [ 0.011145] LSM: Security Framework initializing [ 0.012056] Yama: becoming mindful. [ 0.013041] SELinux: Initializing. [ 0.014071] *** VALIDATE selinux *** [ 0.022301] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.026782] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.027141] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.028120] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.029109] *** VALIDATE tmpfs *** [ 0.030446] *** VALIDATE proc *** [ 0.032224] *** VALIDATE cgroup *** [ 0.033007] *** VALIDATE cgroup2 *** [ 0.034000] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.034163] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.035009] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.036032] Spectre V2 : User space: Vulnerable [ 0.037008] Speculative Store Bypass: Vulnerable [ 0.040086] debug: unmapping init [mem 0xffffffff99459000-0xffffffff99460fff] [ 0.042809] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.043696] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.044027] ... version: 2 [ 0.045012] ... bit width: 48 [ 0.046023] ... generic registers: 4 [ 0.047012] ... value mask: 0000ffffffffffff [ 0.048014] ... max period: 00007fffffffffff [ 0.049016] ... fixed-purpose events: 3 [ 0.050013] ... event mask: 000000070000000f [ 0.051337] rcu: Hierarchical SRCU implementation. [ 0.053410] smp: Bringing up secondary CPUs ... [ 0.054579] x86: Booting SMP configuration: [ 0.055026] .... node #0, CPUs: #1 #2 #3 [ 0.061703] smp: Brought up 1 node, 4 CPUs [ 0.063019] smpboot: Max logical packages: 1 [ 0.064012] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.121020] node 0 deferred pages initialised in 55ms [ 0.123093] devtmpfs: initialized [ 0.124240] x86/mm: Memory block size: 128MB [ 0.128895] gcov: version magic: 0x41383552 [ 0.130300] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.131159] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.132291] pinctrl core: initialized pinctrl subsystem [ 0.133194] [ 0.133677] ************************************************************* [ 0.134015] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.135012] ** ** [ 0.136015] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.137015] ** ** [ 0.138018] ** This means that this kernel is built to expose internal ** [ 0.139013] ** IOMMU data structures, which may compromise security on ** [ 0.140013] ** your system. ** [ 0.141013] ** ** [ 0.142016] ** If you see this message and you are not debugging the ** [ 0.143013] ** kernel, report this immediately to your vendor! ** [ 0.144012] ** ** [ 0.145064] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.146013] ************************************************************* [ 0.147838] NET: Registered protocol family 16 [ 0.148555] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.149067] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.150083] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.152035] cpuidle: using governor menu [ 0.153948] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.157485] PCI: Using configuration type 1 for base access [ 0.159130] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.170061] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.171018] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.173080] cryptd: max_cpu_qlen set to 1000 [ 0.176250] ACPI: Added _OSI(Module Device) [ 0.177013] ACPI: Added _OSI(Processor Device) [ 0.178011] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.179015] ACPI: Added _OSI(Processor Aggregator Device) [ 0.182516] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.185618] ACPI: Interpreter enabled [ 0.186066] ACPI: PM: (supports S0 S3 S4 S5) [ 0.187015] ACPI: Using IOAPIC for interrupt routing [ 0.188120] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.189399] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.199256] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.200038] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.201016] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.202071] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.204335] acpiphp: Slot [2] registered [ 0.205111] acpiphp: Slot [5] registered [ 0.206120] acpiphp: Slot [6] registered [ 0.207114] acpiphp: Slot [7] registered [ 0.208097] acpiphp: Slot [8] registered [ 0.209121] acpiphp: Slot [9] registered [ 0.210115] acpiphp: Slot [10] registered [ 0.211138] acpiphp: Slot [3] registered [ 0.212122] acpiphp: Slot [4] registered [ 0.213106] acpiphp: Slot [11] registered [ 0.214123] acpiphp: Slot [12] registered [ 0.215113] acpiphp: Slot [13] registered [ 0.216066] acpiphp: Slot [14] registered [ 0.216991] acpiphp: Slot [15] registered [ 0.217071] acpiphp: Slot [16] registered [ 0.218113] acpiphp: Slot [17] registered [ 0.219083] acpiphp: Slot [18] registered [ 0.220092] acpiphp: Slot [19] registered [ 0.221096] acpiphp: Slot [20] registered [ 0.222109] acpiphp: Slot [21] registered [ 0.223160] acpiphp: Slot [22] registered [ 0.224172] acpiphp: Slot [23] registered [ 0.226105] acpiphp: Slot [24] registered [ 0.228105] acpiphp: Slot [25] registered [ 0.230109] acpiphp: Slot [26] registered [ 0.232119] acpiphp: Slot [27] registered [ 0.233142] acpiphp: Slot [28] registered [ 0.235118] acpiphp: Slot [29] registered [ 0.238029] acpiphp: Slot [30] registered [ 0.239128] acpiphp: Slot [31] registered [ 0.241109] PCI host bridge to bus 0000:00 [ 0.242019] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.244126] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.247028] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.250026] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.253025] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.256045] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.258250] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.262065] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.265224] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.276007] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.282008] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.284019] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.287017] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.289020] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.292070] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.294888] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.298048] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.301854] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.308015] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.322027] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.330017] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.335015] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.347019] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.357017] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.381019] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.394102] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.406017] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.418020] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.449019] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.468000] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.481021] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.494018] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.515021] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.535266] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.544019] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.552019] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.571022] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.584873] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.600018] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.612023] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.637018] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 0.654471] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.663016] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.671019] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.688018] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 0.702347] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.704346] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.706361] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.709358] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.712249] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.716273] iommu: Default domain type: Passthrough [ 0.718336] SCSI subsystem initialized [ 0.720134] ACPI: bus type USB registered [ 0.722268] usbcore: registered new interface driver usbfs [ 0.724084] usbcore: registered new interface driver hub [ 0.726077] usbcore: registered new device driver usb [ 0.728141] pps_core: LinuxPPS API ver. 1 registered [ 0.730008] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.732067] PTP clock support registered [ 0.735073] EDAC MC: Ver: 3.0.0 [ 0.736603] PCI: Using ACPI for IRQ routing [ 0.738867] NetLabel: Initializing [ 0.740022] NetLabel: domain hash size = 128 [ 0.741009] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.742062] NetLabel: unlabeled traffic allowed by default [ 0.744116] vgaarb: loaded [ 0.746276] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.748016] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.753471] clocksource: Switched to clocksource kvm-clock [ 0.869888] VFS: Disk quotas dquot_6.6.0 [ 0.871141] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.873143] *** VALIDATE ramfs *** [ 0.874050] *** VALIDATE hugetlbfs *** [ 0.875389] pnp: PnP ACPI init [ 0.877930] pnp: PnP ACPI: found 6 devices [ 0.895358] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.897424] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.898767] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.900148] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.902121] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.903906] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.905671] NET: Registered protocol family 2 [ 0.907582] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.910956] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.913207] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.917173] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.919757] TCP: Hash tables configured (established 65536 bind 65536) [ 0.922224] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.925522] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.928133] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.930551] NET: Registered protocol family 1 [ 0.932706] RPC: Registered named UNIX socket transport module. [ 0.934369] RPC: Registered udp transport module. [ 0.936567] RPC: Registered tcp transport module. [ 0.938381] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.940723] NET: Registered protocol family 44 [ 0.942162] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.944036] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.945832] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.947812] PCI: CLS 0 bytes, default 64 [ 0.950101] Unpacking initramfs... [ 2.367614] debug: unmapping init [mem 0xffff8ef17cc54000-0xffff8ef17ffbffff] [ 2.371827] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.374486] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.377915] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 2.902767] Initialise system trusted keyrings [ 2.904397] Key type blacklist registered [ 2.906490] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.917886] zbud: loaded [ 2.921575] *** VALIDATE nfs *** [ 2.923079] *** VALIDATE nfs4 *** [ 2.924790] pstore: using deflate compression [ 2.929096] Platform Keyring initialized [ 3.044405] NET: Registered protocol family 38 [ 3.046323] Key type asymmetric registered [ 3.048277] Asymmetric key parser 'x509' registered [ 3.050566] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 3.054344] io scheduler mq-deadline registered [ 3.056377] io scheduler kyber registered [ 3.058590] io scheduler bfq registered [ 3.060813] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 3.064714] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 3.068028] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 3.071285] ACPI: Power Button [PWRF] [ 3.076947] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 3.083906] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 3.096951] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 3.104054] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 3.118053] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 3.148350] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.178272] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.183931] Non-volatile memory driver v1.3 [ 3.186161] Linux agpgart interface v0.103 [ 3.224889] virtio_blk virtio1: [vda] 142768 512-byte logical blocks (73.1 MB/69.7 MiB) [ 3.228081] vda: detected capacity change from 0 to 73097216 [ 3.245698] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.249490] vdb: detected capacity change from 0 to 1073741824 [ 3.271597] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.275204] vdc: detected capacity change from 0 to 2621440000 [ 3.299039] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.302511] vdd: detected capacity change from 0 to 2621440000 [ 3.325598] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.329052] vde: detected capacity change from 0 to 4294967296 [ 3.344955] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.348338] vdf: detected capacity change from 0 to 4294967296 [ 3.355561] libphy: Fixed MDIO Bus: probed [ 3.367716] usbcore: registered new interface driver usbserial_generic [ 3.370551] usbserial: USB Serial support registered for generic [ 3.373531] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.379253] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.381483] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.384470] mousedev: PS/2 mouse device common for all mice [ 3.387108] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.389496] rtc_cmos 00:05: RTC can wake from S4 [ 3.391748] rtc_cmos 00:05: registered as rtc0 [ 3.393875] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.397062] intel_pstate: CPU model not supported [ 3.400276] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.401445] hid: raw HID events driver (C) Jiri Kosina [ 3.406898] usbcore: registered new interface driver usbhid [ 3.409285] usbhid: USB HID core driver [ 3.411323] drop_monitor: Initializing network drop monitor service [ 3.411449] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.413589] Initializing XFRM netlink socket [ 3.419958] NET: Registered protocol family 10 [ 3.423519] Segment Routing with IPv6 [ 3.425091] NET: Registered protocol family 17 [ 3.427328] mpls_gso: MPLS GSO support [ 3.433515] RAS: Correctable Errors collector initialized. [ 3.435851] AVX version of gcm_enc/dec engaged. [ 3.437738] AES CTR mode by8 optimization enabled [ 3.516260] sched_clock: Marking stable (3516167958, 0)->(4510774869, -994606911) [ 3.520524] registered taskstats version 1 [ 3.522928] Loading compiled-in X.509 certificates [ 3.525460] zswap: loaded using pool lzo/zbud [ 3.552867] Key type big_key registered [ 3.566378] Key type encrypted registered [ 3.568364] ima: No TPM chip found, activating TPM-bypass! [ 3.571563] ima: Allocated hash algorithm: sha1 [ 3.573431] ima: No architecture policies found [ 3.575482] evm: Initialising EVM extended attributes: [ 3.577649] evm: security.selinux [ 3.579130] evm: security.ima [ 3.580428] evm: security.capability [ 3.581964] evm: HMAC attrs: 0x1 [ 3.584664] rtc_cmos 00:05: setting system clock to 2026-09-11 07:03:11 UTC (1789110191) [ 3.591386] debug: unmapping init [mem 0xffffffff9a403000-0xffffffff9a5fffff] [ 3.594878] debug: unmapping init [mem 0xffffffff99182000-0xffffffff99458fff] [ 3.604327] Write protecting the kernel read-only data: 28672k [ 3.607873] debug: unmapping init [mem 0xffffffff97803000-0xffffffff979fffff] [ 3.610788] debug: unmapping init [mem 0xffffffff98114000-0xffffffff981fffff] [ 3.649238] 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.658098] systemd[1]: Detected virtualization kvm. [ 3.660107] systemd[1]: Detected architecture x86-64. [ 3.662064] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.689516] systemd[1]: No hostname configured. [ 3.690928] systemd[1]: Set hostname to . [ 3.692252] random: systemd: uninitialized urandom read (16 bytes read) [ 3.693871] systemd[1]: Initializing machine ID from random generator. [ 3.747547] random: ln: uninitialized urandom read (6 bytes read) [ 3.838927] random: systemd: uninitialized urandom read (16 bytes read) [ 3.842278] systemd[1]: Listening on Journal Socket (/dev/log). [ OK ] Listening on Journal Socket (/dev/log). [ 3.850055] systemd[1]: Listening on udev Kernel Socket. [ OK ] Listening on udev Kernel Socket. [ 3.855053] systemd[1]: Reached target Local File Systems. [ OK ] Reached target Local File Systems. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Listening on Journal Socket. [ OK ] Listening on udev Control Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Swap. Starting Apply Kernel Variables... [ OK ] Reached target Local Encrypted Volumes. Starting Create Volatile Files and Directories... [ OK ] Reached target Initrd Root Device. [ OK ] Reached target Paths. Starting Setup Virtual Console... [ OK ] Reached target Slices. Starting Journal Service... [ OK ] Started Memstrack Anylazing Service. [ OK ] Reached target Timers. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Started Apply Kernel Variables. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Setup Virtual Console. [ OK ] Started Create list of required sta…vice nodes for the current kernel. Starting Create Static Device Nodes in /dev... Starting dracut cmdline hook... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started Journal Service. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 4.520142] device-mapper: uevent: version 1.0.3 [ 4.521886] device-mapper: ioctl: 4.46.0-ioctl (2022-02-22) initialised: dm-devel@redhat.com [ OK ] Started dracut pre-udev hook. Starting udev Kernel Device Manager... [ OK ] Started udev Kernel Device Manager. Starting dracut pre-trigger hook... [ OK ] Started dracut pre-trigger hook. Starting udev Coldplug all Devices... Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting dracut initqueue hook... [ 5.193290] random: fast init done [ 5.201707] virtio_net virtio0 ens2: renamed from eth0 [ 5.245600] scsi host0: ata_piix [ 5.250976] scsi host1: ata_piix [ 5.252589] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 5.255250] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 9.633497] dracut-initqueue[586]: RTNETLINK answers: File exists [ 10.099418] random: crng init done [ 10.102096] 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.508665] 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 Slices. [ OK ] Stopped target Sockets. [ OK ] Stopped target Paths. [ OK ] Stopped target System Initialization. [ OK ] Stopped target Swap. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. Stopping udev Kernel Device Manager... [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Closed udev Kernel Socket. [ OK ] Closed udev Control Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 11.649491] printk: systemd: 26 output lines suppressed due to ratelimiting [ 11.882780] SELinux: Disabled at runtime. [ 11.941848] 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.949325] systemd[1]: Detected virtualization kvm. [ 11.950822] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 12.456366] systemd[1]: initrd-switch-root.service: Succeeded. [ 12.459965] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 12.465777] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 12.471346] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 12.475169] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 12.483255] systemd[1]: Starting Journal Service... Starting Journal Service... [ 12.486782] systemd[1]: Stopped target Switch Root. [ OK ] Stopped target Switch Root. [ OK ] Listening on udev Kernel Socket. [ OK ] Listening on udev Control Socket. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Created slice system-sshd\x2dkeygen.slice. Mounting Huge Pages File System... Starting Remount Root and Kernel File Systems... [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Reached target RPC Port Mapper. [ OK ] Listening on initctl Compatibility Named Pipe. Mounting Kernel Debug File System... [ OK ] Stopped target Initrd Root File System. Mounting POSIX Message Queue File System... Starting udev Coldplug all Devices... [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Stopped target Initrd File Systems. [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Created slice User and Session Slice. [ OK ] Reached target Slices. [ OK ] Reached target Paths. [ OK ] Reached target rpc_pipefs.target. [ OK ] Created slice system-getty.slice. [ OK ] Listening on Process Core Dump Socket. Activating swap /dev/disk/by-label/SWAP... Starting Apply Kernel Variables... Starting Create list of required st…ce nodes for the current kernel... [ OK ] Reached target Local Encrypted Volumes. [ 12.714446] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS [ OK ] Started Journal Service. [ OK ] Mounted Huge Pages File System. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Mounted Kernel Debug File System. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Started Apply Kernel Variables. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Reached target Swap. Starting Create Static Device Nodes in /dev... Starting Configure read-only root support... Starting Flush Journal to Persistent Storage... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. Starting udev Kernel Device Manager... [ OK ] Reached target Local File Systems (Pre). Mounting /home/green/git/lustre-release... Mounting /mnt... [ OK ] Mounted /mnt. [ OK ] Started udev Coldplug all Devices. [ 13.008152] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 13.335853] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 13.439848] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 13.579286] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 13.589257] EDAC sbridge: Ver: 1.1.2 [ 15.469376] Key type dns_resolver registered [ 15.782694] NFS: Registering the id_resolver key type [ 15.785048] Key type id_resolver registered [ 15.786797] 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 Rebuild Dynamic Linker Cache... Starting Load/Save Random Seed... Starting Create Volatile Files and Directories... [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Load/Save Random Seed. [ OK ] Started Create Volatile Files and Directories. Starting RPC Bind... Starting Update UTMP about System Boot/Shutdown... [ OK ] Started RPC Bind. [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. Starting Login Service... Starting Restore /run/initramfs on shutdown... [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ 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 Dynamic System Tuning Daemon... Starting GSSAPI Proxy 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 Command Scheduler. [ OK ] Started Getty on tty1. [ OK ] Started Serial Getty on ttyS1. [ OK ] Started Serial Getty on ttyS0. [ OK ] Reached target Login Prompts. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting Crash recovery kernel arming... Starting System Logging Service... 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 oleg219-server login: [ 45.128620] libcfs: loading out-of-tree module taints kernel. [ 45.217757] Key type ._llcrypt registered [ 45.228816] Key type .llcrypt registered [ 45.429822] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_hostid [ 71.050021] hrtimer: interrupt took 3506724 ns [ 73.939407] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing load_modules_local [ 76.835466] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 76.882359] alg: No test for adler32 (adler32-zlib) [ 78.205415] Lustre: Lustre: Build Version: 2.17.53_26_gdb05832 [ 80.174767] LNet: Added LNI 192.168.202.119@tcp [8/256/0/180] [ 82.127240] Key type lgssc registered [ 84.478619] Lustre: Echo OBD driver; http://www.lustre.org/ [ 92.101191] alg: No test for zstdfast (zstdfast-lustre-generic) [ 92.120267] alg: No test for zstdfast (zstdfast-lustre-scomp) [ 108.923718] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 161.082033] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing load_modules_local [ 177.410679] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 177.455516] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 178.828737] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 178.849294] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 178.907669] Lustre: lustre-MDT0000: new disk, initializing [ 178.987206] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 178.999555] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 183.839296] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 202.948247] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 203.102204] Lustre: 6572:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 203.135580] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 203.140396] Lustre: Skipped 1 previous similar message [ 203.304296] Lustre: lustre-MDT0001: new disk, initializing [ 203.400455] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 203.449921] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 203.475404] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 209.932257] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 216.107392] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 228.760429] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 229.176742] Lustre: lustre-OST0000: new disk, initializing [ 229.179079] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 229.196535] Lustre: 8476:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 229.308902] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 231.498652] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 231.512966] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 231.598981] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 235.597478] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 251.804036] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 252.040833] Lustre: lustre-OST0001: new disk, initializing [ 252.045664] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 252.052958] Lustre: 9532:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 252.252204] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 260.171551] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 260.187766] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 260.240854] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 261.375682] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 276.589704] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 284.651669] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 291.985960] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing check_logdir /tmp/testlogs/ [ 297.239313] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing yml_node [ 300.778560] Lustre: DEBUG MARKER: Client: 2.17.53.26 [ 303.421495] Lustre: DEBUG MARKER: MDS: 2.17.53.26 [ 306.272750] Lustre: DEBUG MARKER: OSS: 2.17.53.26 [ 308.438242] Lustre: DEBUG MARKER: -----============= acceptance-small: replay-dual ============----- Fri Sep 11 03:08:14 EDT 2026 [ 329.527329] Lustre: DEBUG MARKER: excepting tests: 14b 21b [ 331.395884] Lustre: DEBUG MARKER: skipping tests SLOW=no: 21b [ 333.883365] Lustre: DEBUG MARKER: === replay-dual: start setup 03:08:39 (1789110519) === [ 340.078663] Lustre: DEBUG MARKER: oleg219-client.virtnet: executing check_config_client /mnt/lustre [ 364.474885] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 368.893182] Lustre: 13295:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 373.641385] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug -1 all [ 381.986583] Lustre: DEBUG MARKER: === replay-dual: finish setup 03:09:27 (1789110567) === [ 384.881975] Lustre: DEBUG MARKER: == replay-dual test 0a: expired recovery with lost client ========================================================== 03:09:30 (1789110570) [ 397.408930] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 402.036730] Lustre: Failing over lustre-MDT0000 [ 402.605239] Lustre: server umount lustre-MDT0000 complete [ 403.424412] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 403.429832] 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 [ 403.460916] Lustre: Skipped 1 previous similar message [ 408.574186] LustreError: 6582:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 408.587386] LustreError: 6582:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 7 previous similar messages [ 411.840361] LustreError: 12160:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.202.19@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 411.863621] LustreError: 12160:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 4 previous similar messages [ 413.667150] LustreError: 10140:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 413.717988] LustreError: 10140:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 3 previous similar messages [ 416.954311] LustreError: 6578:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.202.19@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 416.976504] LustreError: 6578:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 1 previous similar message [ 419.279169] Lustre: 3656:0:(client.c:2480:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789110591/real 1789110591] req@ffff8ef0c45f4380 x1876018088508800/t0(0) o400->MGC192.168.202.119@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789110607 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 419.330970] LustreError: MGC192.168.202.119@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 422.071055] LustreError: 6579:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.202.19@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 422.093126] LustreError: 6579:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 9 previous similar messages [ 430.354129] LDISKFS-fs (dm-0): 10 truncates cleaned up [ 430.361831] LDISKFS-fs (dm-0): recovery complete [ 430.385323] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 430.574307] LustreError: 6582:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 430.583054] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xe1aef795fee15744 [ 430.606096] LustreError: 6582:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 17 previous similar messages [ 430.632870] LustreError: 14796:0:(ldlm_resource.c:1180:ldlm_resource_complain()) MGC192.168.202.119@tcp: namespace resource [0x65727473756c:0x5:0x0].0x0 (ffff8ef1c442dc00) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 430.650207] Lustre: MGC192.168.202.119@tcp: Connection restored to 0@lo (at 0@lo) [ 431.010548] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 433.342623] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 436.204745] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 436.772111] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug -1 all [ 538.500509] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 538.510231] Lustre: 14821:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client abbf2ac6-3137-4840-8ca3-60c9942b27eb@192.168.202.19@tcp [ 538.519476] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 538.537977] Lustre: lustre-MDT0000-osp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 538.539850] Lustre: 14821:0:(ldlm_lib.c:2932:target_recovery_thread()) too long recovery - read logs [ 538.549218] Lustre: Skipped 2 previous similar messages [ 538.584295] LustreError: dumping log to /tmp/lustre-log.1789110726.14821 [ 538.799727] Lustre: lustre-MDT0000: Recovery over after 1:45, of 3 clients 2 recovered and 1 was evicted. [ 538.872277] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:28 to 0x280000401:65) [ 538.873547] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:28 to 0x2c0000401:65) [ 565.153180] Lustre: DEBUG MARKER: == replay-dual test 0b: lost client during waiting for next transno ========================================================== 03:12:31 (1789110751) [ 575.832599] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 578.426298] Lustre: Failing over lustre-MDT0000 [ 579.186961] Lustre: server umount lustre-MDT0000 complete [ 579.570592] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 579.578269] 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 [ 579.594612] LustreError: 6582:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 579.689565] Lustre: Skipped 3 previous similar messages [ 595.936407] Lustre: 3654:0:(client.c:2480:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789110767/real 1789110767] req@ffff8ef1f7e68700 x1876018088593280/t0(0) o400->MGC192.168.202.119@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789110783 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 595.987846] LustreError: MGC192.168.202.119@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 605.350683] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 605.356973] LDISKFS-fs (dm-0): recovery complete [ 605.383259] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 614.592247] LustreError: 6577:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.202.19@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 614.628449] LustreError: 6577:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 39 previous similar messages [ 621.555918] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xe1aef795fee172fe [ 621.571106] Lustre: MGC192.168.202.119@tcp: Connection restored to 0@lo (at 0@lo) [ 621.895621] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 621.943051] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 622.803590] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 627.185522] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 627.242546] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug -1 all [ 637.416251] Lustre: lustre-MDT0001: haven't heard from client abbf2ac6-3137-4840-8ca3-60c9942b27eb (at 192.168.202.19@tcp) in 102 seconds. I think it's dead, and I am evicting it. exp ffff8ef0c2d7b800, cur 1789110825 deadline 1789110823 last 1789110723 [ 640.446735] Lustre: lustre-MDT0000: Denying connection for new client 8f2c345e-ab56-4735-8089-b0bb41205c5d (at 192.168.202.19@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:52 [ 645.815572] Lustre: lustre-MDT0000: Denying connection for new client 8f2c345e-ab56-4735-8089-b0bb41205c5d (at 192.168.202.19@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:46 [ 650.935352] Lustre: lustre-MDT0000: Denying connection for new client 8f2c345e-ab56-4735-8089-b0bb41205c5d (at 192.168.202.19@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:41 [ 656.051540] Lustre: lustre-MDT0000: Denying connection for new client 8f2c345e-ab56-4735-8089-b0bb41205c5d (at 192.168.202.19@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:36 [ 661.171122] Lustre: lustre-MDT0000: Denying connection for new client 8f2c345e-ab56-4735-8089-b0bb41205c5d (at 192.168.202.19@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:31 [ 671.435716] Lustre: lustre-MDT0000: Denying connection for new client 8f2c345e-ab56-4735-8089-b0bb41205c5d (at 192.168.202.19@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:21 [ 671.463094] Lustre: Skipped 1 previous similar message [ 691.892228] Lustre: lustre-MDT0000: Denying connection for new client 8f2c345e-ab56-4735-8089-b0bb41205c5d (at 192.168.202.19@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:00 [ 691.917820] Lustre: Skipped 3 previous similar messages [ 692.500185] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 692.502769] Lustre: 16554:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 3bf053b2-a44f-4f08-8d9b-4bbec9a0a764@ [ 692.541546] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 727.739936] Lustre: lustre-MDT0000: Denying connection for new client 8f2c345e-ab56-4735-8089-b0bb41205c5d (at 192.168.202.19@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 1 evicted) to recover in 1:05 [ 727.771264] Lustre: Skipped 6 previous similar messages [ 729.605702] Lustre: lustre-MDT0001: haven't heard from client cf1f53ea-1eb0-4a0f-9846-6030adb39612 (at 192.168.202.19@tcp) in 102 seconds. I think it's dead, and I am evicting it. exp ffff8ef0c317b000, cur 1789110917 deadline 1789110915 last 1789110815 [ 793.500642] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 793.520780] Lustre: 16554:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client cf1f53ea-1eb0-4a0f-9846-6030adb39612@192.168.202.19@tcp [ 793.564343] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 793.572478] Lustre: 16554:0:(ldlm_lib.c:2069:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 793.594882] Lustre: 16554:0:(ldlm_lib.c:2932:target_recovery_thread()) too long recovery - read logs [ 793.597054] Lustre: lustre-MDT0000-osp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 793.611408] LustreError: dumping log to /tmp/lustre-log.1789110981.16554 [ 793.639583] Lustre: Skipped 2 previous similar messages [ 793.759786] Lustre: lustre-MDT0000: Recovery over after 2:51, of 3 clients 1 recovered and 2 were evicted. [ 793.816544] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:67 to 0x2c0000401:97) [ 793.817768] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:28 to 0x280000401:97) [ 805.801455] Lustre: DEBUG MARKER: == replay-dual test 1: |X| simple create ================= 03:16:31 (1789110991) [ 816.776106] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 819.048578] Lustre: Failing over lustre-MDT0000 [ 819.169664] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 819.180350] 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 [ 819.191824] Lustre: Skipped 2 previous similar messages [ 819.220308] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 819.504484] Lustre: server umount lustre-MDT0000 complete [ 820.971735] LustreError: 6577:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.202.19@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 820.991865] LustreError: 6577:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 14 previous similar messages [ 821.730478] 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 [ 821.747365] Lustre: Skipped 1 previous similar message [ 837.088200] Lustre: 3655:0:(client.c:2480:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789111009/real 1789111009] req@ffff8ef20029a680 x1876018088693376/t0(0) o400->MGC192.168.202.119@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789111025 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 837.138664] LustreError: MGC192.168.202.119@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 843.526291] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 843.528619] LDISKFS-fs (dm-0): recovery complete [ 843.534598] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 847.328866] LustreError: 3653:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8ef0c33fc380 x1876018088700800/t0(0) o250->MGC192.168.202.119@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 [ 847.777093] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 847.829381] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 847.941934] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 853.000737] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 853.157474] Lustre: lustre-MDT0000: Recovery over after 0:06, of 3 clients 3 recovered and 0 were evicted. [ 853.229765] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:129) [ 853.231568] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:129) [ 853.350762] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug -1 all [ 862.042816] Lustre: DEBUG MARKER: oleg219-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 864.537094] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 876.001410] Lustre: DEBUG MARKER: == replay-dual test 2: |X| mkdir adir ==================== 03:17:41 (1789111061) [ 886.150373] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 888.751112] Lustre: Failing over lustre-MDT0000 [ 888.802256] 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 [ 888.817094] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 888.836440] Lustre: Skipped 4 previous similar messages [ 888.856009] Lustre: Skipped 3 previous similar messages [ 889.068588] Lustre: server umount lustre-MDT0000 complete [ 909.783250] Lustre: 3655:0:(client.c:2480:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789111081/real 1789111081] req@ffff8ef1f021b800 x1876018088732288/t0(0) o400->MGC192.168.202.119@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789111097 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 909.816223] LustreError: MGC192.168.202.119@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 914.599296] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 914.600962] LDISKFS-fs (dm-0): recovery complete [ 914.611942] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 920.039716] LustreError: 3653:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8ef1d002b800 x1876018088739328/t0(0) o250->MGC192.168.202.119@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 [ 920.579551] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 920.683573] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 921.278777] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 925.735699] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 925.749705] Lustre: Skipped 3 previous similar messages [ 925.868680] Lustre: lustre-MDT0000: Recovery over after 0:04, of 3 clients 3 recovered and 0 were evicted. [ 925.934293] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:161) [ 925.935623] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:161) [ 926.234207] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug -1 all [ 934.704729] Lustre: DEBUG MARKER: oleg219-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 936.864386] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 947.316706] Lustre: DEBUG MARKER: == replay-dual test 3: |X| mkdir adir, mkdir adir/bdir === 03:18:53 (1789111133) [ 957.218600] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 959.910092] Lustre: Failing over lustre-MDT0000 [ 960.289669] Lustre: server umount lustre-MDT0000 complete [ 961.510870] 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 [ 961.542781] Lustre: Skipped 3 previous similar messages [ 961.549272] LustreError: 6577:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 961.564329] LustreError: 6577:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 78 previous similar messages [ 977.896869] Lustre: 3657:0:(client.c:2480:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789111149/real 1789111149] req@ffff8ef20026b100 x1876018088774784/t0(0) o400->MGC192.168.202.119@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789111165 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 977.922394] LustreError: MGC192.168.202.119@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 984.443150] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 984.453878] LDISKFS-fs (dm-0): recovery complete [ 984.478028] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 987.170530] LustreError: 3653:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8ef200268e00 x1876018088783232/t0(0) o250->MGC192.168.202.119@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 [ 987.531326] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 987.580707] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 987.847372] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 991.953513] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug -1 all [ 992.759121] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 992.777830] Lustre: Skipped 3 previous similar messages [ 992.909773] Lustre: lustre-MDT0000: Recovery over after 0:05, of 3 clients 3 recovered and 0 were evicted. [ 992.977699] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:193) [ 992.980504] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:193) [ 1000.824390] Lustre: DEBUG MARKER: oleg219-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1002.536839] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1012.258609] Lustre: DEBUG MARKER: == replay-dual test 4: |X| mkdir adir (-EEXIST), mkdir adir/bdir ========================================================== 03:19:57 (1789111197) [ 1021.002946] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1023.312389] Lustre: Failing over lustre-MDT0000 [ 1023.459836] 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 [ 1023.474994] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1023.475846] Lustre: Skipped 3 previous similar messages [ 1023.492148] Lustre: Skipped 3 previous similar messages [ 1023.614880] Lustre: server umount lustre-MDT0000 complete [ 1044.959154] Lustre: 3655:0:(client.c:2480:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789111216/real 1789111216] req@ffff8ef1eecbb100 x1876018088819712/t0(0) o400->MGC192.168.202.119@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789111232 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1044.978618] LustreError: MGC192.168.202.119@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1047.590591] LDISKFS-fs (dm-0): 4 truncates cleaned up [ 1047.592582] LDISKFS-fs (dm-0): recovery complete [ 1047.618310] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1054.177483] LustreError: 3653:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8ef1f0138700 x1876018088827520/t0(0) o250->MGC192.168.202.119@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 [ 1054.581352] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1055.427875] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 1059.805663] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug -1 all [ 1060.017435] Lustre: lustre-MDT0000: Recovery over after 0:05, of 3 clients 3 recovered and 0 were evicted. [ 1060.055423] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:225) [ 1060.066607] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:225) [ 1069.095399] Lustre: DEBUG MARKER: oleg219-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1071.481131] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1080.912682] Lustre: DEBUG MARKER: == replay-dual test 5: open, unlink |X| close ============ 03:21:06 (1789111266) [ 1088.837387] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1091.046036] Lustre: Failing over lustre-MDT0000 [ 1091.588472] Lustre: server umount lustre-MDT0000 complete [ 1095.650260] 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 [ 1095.672447] Lustre: Skipped 3 previous similar messages [ 1112.036227] Lustre: 3657:0:(client.c:2480:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789111283/real 1789111283] req@ffff8ef1f028ea00 x1876018088858880/t0(0) o400->MGC192.168.202.119@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789111299 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1112.070728] LustreError: MGC192.168.202.119@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1117.986953] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1117.990608] LDISKFS-fs (dm-0): recovery complete [ 1118.001724] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1122.280070] LustreError: 3653:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8ef1ee69ca80 x1876018088868096/t0(0) o250->MGC192.168.202.119@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 [ 1122.749371] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1122.752499] Lustre: Skipped 1 previous similar message [ 1122.782732] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1123.985512] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 1127.943220] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1127.964791] Lustre: Skipped 7 previous similar messages [ 1128.275269] Lustre: lustre-MDT0000: Recovery over after 0:05, of 3 clients 3 recovered and 0 were evicted. [ 1128.390432] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:257) [ 1128.390895] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:257) [ 1130.806846] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug -1 all [ 1140.411386] Lustre: DEBUG MARKER: oleg219-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1142.972961] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1153.448373] Lustre: DEBUG MARKER: == replay-dual test 6: open1, open2, unlink |X| close1 [fail mds1] close2 ========================================================== 03:22:19 (1789111339) [ 1162.711850] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1165.296207] Lustre: Failing over lustre-MDT0000 [ 1165.493604] Lustre: server umount lustre-MDT0000 complete [ 1168.864851] 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 [ 1168.880793] Lustre: Skipped 3 previous similar messages [ 1184.223217] Lustre: 3656:0:(client.c:2480:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789111356/real 1789111356] req@ffff8ef1fc6dc700 x1876018088898304/t0(0) o400->MGC192.168.202.119@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789111372 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1184.259471] LustreError: MGC192.168.202.119@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1191.632546] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1191.634341] LDISKFS-fs (dm-0): recovery complete [ 1191.660557] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1195.706896] Lustre: lustre-MDT0000: Not available for connect from 192.168.202.19@tcp (not set up) [ 1195.720754] Lustre: Skipped 1 previous similar message [ 1196.010256] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1196.765335] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 1201.296231] Lustre: lustre-MDT0000: Recovery over after 0:05, of 3 clients 3 recovered and 0 were evicted. [ 1201.372248] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:289) [ 1201.374226] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:289) [ 1202.217866] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug -1 all [ 1212.760979] Lustre: DEBUG MARKER: oleg219-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1215.074300] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1225.989484] Lustre: DEBUG MARKER: == replay-dual test 8: replay of resent request ========== 03:23:31 (1789111411) [ 1235.919928] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1237.219946] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 1237.224766] LustreError: 12160:0:(ldlm_lib.c:3327:target_send_reply_msg()) @@@ dropping reply req@ffff8ef0c3373100 x1876018057212288/t38654705670(0) o36->8f2c345e-ab56-4735-8089-b0bb41205c5d@192.168.202.19@tcp:16/0 lens 512/448 e 0 to 0 dl 1789111436 ref 1 fl Interpret:/200/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 1252.587288] Lustre: lustre-MDT0000: Client 8f2c345e-ab56-4735-8089-b0bb41205c5d (at 192.168.202.19@tcp) reconnecting [ 1252.634261] Lustre: 6579:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff8ef1fb464700 x1876018057212288/t38654705670(0) o36->8f2c345e-ab56-4735-8089-b0bb41205c5d@192.168.202.19@tcp:31/0 lens 512/2880 e 0 to 0 dl 1789111451 ref 1 fl Interpret:/202/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 1256.485037] Lustre: Failing over lustre-MDT0000 [ 1257.175847] Lustre: server umount lustre-MDT0000 complete [ 1257.448556] LustreError: 6578:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1257.473082] LustreError: 6578:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 161 previous similar messages [ 1273.824086] Lustre: 3656:0:(client.c:2480:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789111445/real 1789111445] req@ffff8ef1f0263480 x1876018088945152/t0(0) o400->MGC192.168.202.119@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789111461 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1273.854635] LustreError: MGC192.168.202.119@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1281.973996] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1281.975916] LDISKFS-fs (dm-0): recovery complete [ 1281.984521] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1283.105890] LustreError: 3653:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8ef1fc596300 x1876018088953728/t0(0) o250->MGC192.168.202.119@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 [ 1283.536511] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1285.306089] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 1287.946869] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug -1 all [ 1288.797616] Lustre: lustre-MDT0000: Recovery over after 0:03, of 3 clients 3 recovered and 0 were evicted. [ 1288.843479] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:321) [ 1288.843707] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:321) [ 1296.914271] Lustre: DEBUG MARKER: oleg219-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1299.202270] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1310.650371] Lustre: DEBUG MARKER: == replay-dual test 9: resending a replayed create ======= 03:24:56 (1789111496) [ 1321.232890] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1324.757498] Lustre: Failing over lustre-MDT0000 [ 1325.027390] LustreError: 30588:0:(ldlm_resource.c:1180:ldlm_resource_complain()) MGS: namespace resource [0x736d61726170:0x3:0x0].0x0 (ffff8ef1fc3ad300) refcount nonzero (2) after lock cleanup; forcing cleanup. [ 1325.034608] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1325.063152] 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 [ 1325.074343] Lustre: Skipped 4 previous similar messages [ 1327.168802] Lustre: server umount lustre-MDT0000 complete [ 1351.832312] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1351.841523] LDISKFS-fs (dm-0): recovery complete [ 1351.859063] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1355.610716] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1360.260197] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug -1 all [ 1360.955713] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 1360.966550] LustreError: 31242:0:(ldlm_lib.c:3327:target_send_reply_msg()) @@@ dropping reply req@ffff8ef1c49e3b80 x1876018057230848/t42949672962(42949672962) o36->8f2c345e-ab56-4735-8089-b0bb41205c5d@192.168.202.19@tcp:135/0 lens 528/448 e 0 to 0 dl 1789111555 ref 1 fl Complete:/204/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 1373.458125] Lustre: lustre-MDT0000: Client 8f2c345e-ab56-4735-8089-b0bb41205c5d (at 192.168.202.19@tcp) reconnected, waiting for 3 clients in recovery for 1:28 [ 1373.654073] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:353) [ 1373.655628] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:353) [ 1379.295489] Lustre: DEBUG MARKER: oleg219-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1381.225505] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1392.582282] Lustre: DEBUG MARKER: == replay-dual test 10: resending a replayed unlink ====== 03:26:18 (1789111578) [ 1402.592826] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1405.925904] Lustre: Failing over lustre-MDT0000 [ 1406.244884] Lustre: server umount lustre-MDT0000 complete [ 1423.328134] Lustre: 3654:0:(client.c:2480:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789111594/real 1789111594] req@ffff8ef1f0139f80 x1876018089026048/t0(0) o400->MGC192.168.202.119@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789111610 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1423.380366] Lustre: 3654:0:(client.c:2480:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 1423.400266] LustreError: MGC192.168.202.119@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1423.418925] LustreError: Skipped 1 previous similar message [ 1431.494241] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1431.496340] LDISKFS-fs (dm-0): recovery complete [ 1431.520040] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1433.595237] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xe1aef795fee1ab44 [ 1433.617499] Lustre: MGC192.168.202.119@tcp: Connection restored to 0@lo (at 0@lo) [ 1433.635167] Lustre: Skipped 15 previous similar messages [ 1433.794545] Lustre: lustre-MDT0000: Not available for connect from 192.168.202.19@tcp (not set up) [ 1433.813727] Lustre: Skipped 1 previous similar message [ 1434.064770] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1434.076500] Lustre: Skipped 3 previous similar messages [ 1435.551749] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 1435.568605] Lustre: Skipped 1 previous similar message [ 1439.270398] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 1439.278596] LustreError: 33190:0:(ldlm_lib.c:3327:target_send_reply_msg()) @@@ dropping reply req@ffff8ef1eecba680 x1876018057251072/t47244640260(47244640260) o36->8f2c345e-ab56-4735-8089-b0bb41205c5d@192.168.202.19@tcp:214/0 lens 528/448 e 0 to 0 dl 1789111634 ref 1 fl Complete:/204/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 1439.483481] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug -1 all [ 1452.257158] Lustre: lustre-MDT0000: Client 8f2c345e-ab56-4735-8089-b0bb41205c5d (at 192.168.202.19@tcp) reconnected, waiting for 3 clients in recovery for 1:27 [ 1452.394337] Lustre: lustre-MDT0000: Recovery over after 0:17, of 3 clients 3 recovered and 0 were evicted. [ 1452.404290] Lustre: Skipped 1 previous similar message [ 1452.461826] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:385) [ 1452.463504] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:385) [ 1457.992462] Lustre: DEBUG MARKER: oleg219-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1459.747508] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1470.806600] Lustre: DEBUG MARKER: == replay-dual test 11: both clients timeout during replay ========================================================== 03:27:36 (1789111656) [ 1479.905535] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1483.407381] Lustre: Failing over lustre-MDT0000 [ 1483.815901] Lustre: server umount lustre-MDT0000 complete [ 1507.836824] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1507.838465] LDISKFS-fs (dm-0): recovery complete [ 1507.843182] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1511.907588] LustreError: 3653:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8ef1c4397b80 x1876018089077120/t0(0) o250->MGC192.168.202.119@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 [ 1512.454231] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1512.467553] Lustre: Skipped 1 previous similar message [ 1517.234632] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug -1 all [ 1517.570188] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 1517.575537] LustreError: 35133:0:(ldlm_lib.c:3327:target_send_reply_msg()) @@@ dropping reply req@ffff8ef1f3bb1880 x1876018057270656/t51539607554(51539607554) o36->8f2c345e-ab56-4735-8089-b0bb41205c5d@192.168.202.19@tcp:292/0 lens 528/448 e 0 to 0 dl 1789111712 ref 1 fl Complete:/204/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 1524.361539] Lustre: DEBUG MARKER: oleg219-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1528.548330] Lustre: lustre-MDT0000: Client 8f2c345e-ab56-4735-8089-b0bb41205c5d (at 192.168.202.19@tcp) reconnected, waiting for 3 clients in recovery for 1:29 [ 1528.713966] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:417) [ 1528.717730] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:417) [ 1531.172655] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 4 sec [ 1539.291715] Lustre: DEBUG MARKER: == replay-dual test 12: open resend timeout ============== 03:28:45 (1789111725) [ 1547.424232] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1550.596075] Lustre: Failing over lustre-MDT0000 [ 1550.750620] Lustre: server umount lustre-MDT0000 complete [ 1571.169850] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1571.175251] LDISKFS-fs (dm-0): recovery complete [ 1571.181530] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1580.046539] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xe1aef795fee1b8a3 [ 1585.821629] Lustre: *** cfs_fail_loc=302, val=2147483648*** [ 1585.997356] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug -1 all [ 1602.293945] Lustre: lustre-MDT0000: Client 8f2c345e-ab56-4735-8089-b0bb41205c5d (at 192.168.202.19@tcp) reconnected, waiting for 3 clients in recovery for 1:24 [ 1602.496614] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:449) [ 1602.500982] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:449) [ 1615.823383] Lustre: DEBUG MARKER: == replay-dual test 13: close resend timeout ============= 03:30:01 (1789111801) [ 1626.127519] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1629.365653] Lustre: Failing over lustre-MDT0000 [ 1629.751486] Lustre: server umount lustre-MDT0000 complete [ 1631.715767] 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 [ 1631.739177] Lustre: Skipped 16 previous similar messages [ 1653.329819] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1653.331683] LDISKFS-fs (dm-0): recovery complete [ 1653.342829] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1658.353736] LustreError: 3653:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8ef1fb465c00 x1876018089156736/t0(0) o250->MGC192.168.202.119@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 [ 1662.919784] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug -1 all [ 1664.062666] Lustre: *** cfs_fail_loc=115, val=2147483648*** [ 1679.580488] Lustre: lustre-MDT0000: Client 8f2c345e-ab56-4735-8089-b0bb41205c5d (at 192.168.202.19@tcp) reconnected, waiting for 3 clients in recovery for 1:24 [ 1679.730789] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:481) [ 1679.731427] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:481) [ 1687.520381] Lustre: DEBUG MARKER: SKIP: replay-dual test_14b skipping ALWAYS excluded test 14b [ 1689.258932] Lustre: DEBUG MARKER: == replay-dual test 15a: timeout waiting for lost client during replay, 1 client completes ========================================================== 03:31:15 (1789111875) [ 1697.517262] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1700.733562] Lustre: Failing over lustre-MDT0000 [ 1701.092820] Lustre: server umount lustre-MDT0000 complete [ 1720.287439] Lustre: 3655:0:(client.c:2480:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789111892/real 1789111892] req@ffff8ef1f3bb2a00 x1876018089185152/t0(0) o400->MGC192.168.202.119@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789111908 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1720.314977] Lustre: 3655:0:(client.c:2480:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 1720.326954] LustreError: MGC192.168.202.119@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1720.345858] LustreError: Skipped 3 previous similar messages [ 1724.911216] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1724.913640] LDISKFS-fs (dm-0): recovery complete [ 1724.919294] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1730.537683] LustreError: 3653:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8ef1f0269500 x1876018089193472/t0(0) o250->MGC192.168.202.119@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 [ 1730.741788] Lustre: lustre-MDT0000: Not available for connect from 192.168.202.19@tcp (not set up) [ 1731.941079] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 1731.954054] Lustre: Skipped 3 previous similar messages [ 1736.010705] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug -1 all [ 1801.500210] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 1801.503724] Lustre: 40711:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 6bcc6586-fc95-4bc6-a260-b89a57434b6a@ [ 1801.517519] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 1802.208492] Lustre: lustre-MDT0000: Recovery over after 1:11, of 3 clients 2 recovered and 1 was evicted. [ 1802.219343] Lustre: Skipped 3 previous similar messages [ 1802.278546] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:494 to 0x2c0000401:513) [ 1802.281957] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:495 to 0x280000401:513) [ 1806.775973] Lustre: DEBUG MARKER: oleg219-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1808.484553] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1820.889274] Lustre: DEBUG MARKER: == replay-dual test 15c: remove multiple OST orphans ===== 03:33:26 (1789112006) [ 1829.128891] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1935.405736] Lustre: Failing over lustre-MDT0000 [ 1935.553550] Lustre: lustre-MDT0000: Not available for connect from 192.168.202.19@tcp (stopping) [ 1935.914870] Lustre: server umount lustre-MDT0000 complete [ 1938.914614] LustreError: 6578:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1938.931903] LustreError: 6578:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 272 previous similar messages [ 1959.988654] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1959.992307] LDISKFS-fs (dm-0): recovery complete [ 1960.005386] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1964.890455] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1964.901908] Lustre: Skipped 4 previous similar messages [ 1964.976639] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1964.993954] Lustre: Skipped 3 previous similar messages [ 1969.345440] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug -1 all [ 1970.154698] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 1970.161032] Lustre: Skipped 21 previous similar messages [ 2037.500174] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 2037.529629] Lustre: 42614:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client f7edac17-dcbd-477e-95fc-a7092c799817@ [ 2037.561936] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 2037.714416] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:495 to 0x280000401:1537) [ 2037.719704] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:494 to 0x2c0000401:1537) [ 2042.683370] Lustre: DEBUG MARKER: oleg219-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2044.790837] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2055.112894] Lustre: DEBUG MARKER: == replay-dual test 16: fail MDS during recovery (3571) == 03:37:20 (1789112240) [ 2064.327249] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2067.783742] Lustre: Failing over lustre-MDT0000 [ 2068.314626] Lustre: server umount lustre-MDT0000 complete [ 2068.454608] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 2089.817373] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2089.819851] LDISKFS-fs (dm-0): recovery complete [ 2089.825750] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2098.249992] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xe1aef795fee3cdf3 [ 2103.911848] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug -1 all [ 2128.014274] Lustre: Failing over lustre-MDT0000 [ 2128.041968] LustreError: 44945:0:(ldlm_lib.c:2985:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 2128.053770] Lustre: 44475:0:(ldlm_lib.c:2388:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 2128.066627] Lustre: 44475:0:(ldlm_lib.c:1898:abort_req_replay_queue()) @@@ aborted: req@ffff8ef1f7fcc000 x1876018059728000/t0(73014444033) o36->8f2c345e-ab56-4735-8089-b0bb41205c5d@192.168.202.19@tcp:147/0 lens 528/0 e 2 to 0 dl 1789112322 ref 1 fl Complete:/204/ffffffff rc 0/-1 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 2128.089895] Lustre: lustre-MDT0000-osd: cancel update llog [0x200000400:0x1:0x0] [ 2128.110255] Lustre: lustre-MDT0001-osp-MDT0000: cancel update llog [0x240000401:0x1:0x0] [ 2128.111073] Lustre: lustre-MDT0000: Not available for connect from 192.168.202.19@tcp (stopping) [ 2128.125765] LustreError: 44475:0:(client.c:1380:ptlrpc_import_delay_req()) @@@ IMP_CLOSED req@ffff8ef1c4394e00 x1876018089391488/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 [ 2128.141148] LustreError: 44475:0:(fid_request.c:213:seq_client_alloc_seq()) cli-cli-lustre-MDT0001-osp-MDT0000: Cannot allocate new meta-sequence: rc = -5 [ 2128.148195] LustreError: 44475:0:(fid_request.c:316:seq_client_alloc_fid()) cli-cli-lustre-MDT0001-osp-MDT0000: Can't allocate new sequence: rc = -5 [ 2128.473647] Lustre: server umount lustre-MDT0000 complete [ 2149.983915] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2161.486115] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug -1 all [ 2228.500187] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 2228.506951] Lustre: 45401:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 142156fa-f52b-4acd-827d-a60f0a94f2af@ [ 2228.514655] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 2229.606095] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1551 to 0x280000401:1569) [ 2229.610606] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1550 to 0x2c0000401:1569) [ 2235.839564] Lustre: DEBUG MARKER: oleg219-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2238.139555] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2251.007583] Lustre: DEBUG MARKER: == replay-dual test 17: fail OST during recovery (3571) == 03:40:36 (1789112436) [ 2262.383831] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 2265.006361] Lustre: Failing over lustre-OST0000 [ 2265.196754] Lustre: server umount lustre-OST0000 complete [ 2265.572729] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 2265.592553] Lustre: lustre-OST0000-osc-MDT0000: Connection to lustre-OST0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 2265.627419] Lustre: Skipped 17 previous similar messages [ 2290.093226] LDISKFS-fs (dm-2): 3 truncates cleaned up [ 2290.096511] LDISKFS-fs (dm-2): recovery complete [ 2290.103784] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2291.502318] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 4 clients reconnect [ 2291.516528] Lustre: Skipped 3 previous similar messages [ 2296.405775] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug -1 all [ 2321.791858] Lustre: Failing over lustre-OST0000 [ 2321.803489] LustreError: 47786:0:(ldlm_lib.c:2985:target_stop_recovery_thread()) lustre-OST0000: Aborting recovery [ 2321.814634] Lustre: 47239:0:(ldlm_lib.c:2388:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 2321.820987] Lustre: 47239:0:(ldlm_lib.c:2388:target_recovery_overseer()) Skipped 2 previous similar messages [ 2321.833280] LustreError: 47239:0:(ofd_obd.c:1324:ofd_iocontrol()) lustre-OST0000: iocontrol from 'tgt_recover_0' cmd=c00866c1 _IOWR('f', 193, 8) unrecognized: rc = -25 [ 2321.852166] Lustre: lustre-OST0000: Recovery over after 0:30, of 4 clients 0 recovered and 4 were evicted. [ 2321.862116] Lustre: Skipped 3 previous similar messages [ 2322.082991] Lustre: server umount lustre-OST0000 complete [ 2332.128225] Lustre: 3653:0:(client.c:2480:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789112479/real 1789112479] req@ffff8ef1f026aa00 x1876018089473280/t0(0) o400->lustre-OST0000-osc-MDT0001@0@lo:28/4 lens 224/224 e 2 to 1 dl 1789112520 ref 1 fl Rpc:XQr/2c0/ffffffff rc 0/-1 job:'ldlm_lock_repla.0' uid:0 gid:0 projid:4294967295 [ 2332.161761] Lustre: 3653:0:(client.c:2480:ptlrpc_expire_one_request()) Skipped 4 previous similar messages [ 2343.440343] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2351.402826] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug -1 all [ 2415.500230] Lustre: lustre-OST0000: recovery is timed out, evict stale exports [ 2415.508954] Lustre: 48225:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-OST0000: disconnect stale client 552ec255-0952-4213-93f7-7dadc5868926@ [ 2415.523131] Lustre: lustre-OST0000: disconnecting 1 stale clients [ 2421.316127] Lustre: DEBUG MARKER: oleg219-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 2423.562166] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 2434.615988] Lustre: DEBUG MARKER: == replay-dual test 18: ldlm_handle_enqueue succeeds on evicted export (3822) ========================================================== 03:43:40 (1789112620) [ 2439.766215] LustreError: 6579:0:(ldlm_lockd.c:1361:ldlm_handle_enqueue()) cfs_fail_timeout id 30b sleeping for 40000ms [ 2479.807391] LustreError: 6579:0:(ldlm_lockd.c:1361:ldlm_handle_enqueue()) cfs_fail_timeout id 30b awake [ 2494.739205] Lustre: DEBUG MARKER: == replay-dual test 19: resend of open request =========== 03:44:40 (1789112680) [ 2502.780852] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2504.142638] Lustre: *** cfs_fail_loc=157, val=2147483648*** [ 2504.144517] LustreError: 15185:0:(ldlm_lib.c:3327:target_send_reply_msg()) @@@ dropping reply req@ffff8ef1f01b5880 x1876018059855232/t0(0) o101->8f2c345e-ab56-4735-8089-b0bb41205c5d@192.168.202.19@tcp:599/0 lens 576/688 e 0 to 0 dl 1789112774 ref 1 fl Interpret:/600/0 rc 0/0 job:'createmany.0' uid:0 gid:0 projid:0 [ 2591.412817] Lustre: lustre-MDT0000: Client 8f2c345e-ab56-4735-8089-b0bb41205c5d (at 192.168.202.19@tcp) reconnecting [ 2595.479925] Lustre: Failing over lustre-MDT0000 [ 2595.857245] Lustre: server umount lustre-MDT0000 complete [ 2596.541288] LustreError: 6579:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.202.19@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 2596.553049] LustreError: 6579:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 117 previous similar messages [ 2612.197546] LustreError: MGC192.168.202.119@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2612.207738] LustreError: Skipped 3 previous similar messages [ 2621.360717] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2621.362963] LDISKFS-fs (dm-0): recovery complete [ 2621.372201] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2622.441199] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xe1aef795fee3ec3f [ 2622.466625] Lustre: MGC192.168.202.119@tcp: Connection restored to 0@lo (at 0@lo) [ 2622.488029] Lustre: Skipped 13 previous similar messages [ 2622.927132] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 2622.943708] Lustre: Skipped 4 previous similar messages [ 2623.009977] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 2623.024370] Lustre: Skipped 4 previous similar messages [ 2628.140155] Lustre: 50762:0:(ldlm_lib.c:2069:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 2628.361323] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1584 to 0x280000401:1601) [ 2628.368330] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1584 to 0x2c0000401:1601) [ 2628.663399] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug -1 all [ 2637.891803] Lustre: DEBUG MARKER: oleg219-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2639.921921] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2650.104252] Lustre: DEBUG MARKER: == replay-dual test 20: recovery time is not increasing == 03:47:15 (1789112835) [ 2658.047617] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2660.630782] Lustre: Failing over lustre-MDT0000 [ 2661.004388] Lustre: server umount lustre-MDT0000 complete [ 2685.042552] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2685.052525] LDISKFS-fs (dm-0): recovery complete [ 2685.065672] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2689.518095] LustreError: 3653:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8ef0c306d180 x1876018089659264/t0(0) o250->MGC192.168.202.119@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 [ 2694.513548] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug -1 all [ 2832.506825] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 2832.518911] Lustre: 52591:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client a982af31-e3d7-46a2-8ed9-824a70571728@ [ 2832.534190] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 2832.601351] Lustre: 52591:0:(ldlm_lib.c:2069:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 2832.617908] Lustre: 52591:0:(ldlm_lib.c:2069:extend_recovery_timer()) Skipped 6 previous similar messages [ 2832.773901] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1584 to 0x2c0000401:1633) [ 2832.775661] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1603 to 0x280000401:1633) [ 2838.365748] Lustre: DEBUG MARKER: oleg219-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2840.721351] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2852.842394] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2855.365813] Lustre: Failing over lustre-MDT0000 [ 2856.049934] Lustre: server umount lustre-MDT0000 complete [ 2858.469465] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 2879.406107] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2879.410490] LDISKFS-fs (dm-0): recovery complete [ 2879.431774] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2884.576956] LustreError: 3653:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8ef1fd97a300 x1876018089739392/t0(0) o250->MGC192.168.202.119@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 [ 2889.715981] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug -1 all [ 3026.500113] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 3026.509798] Lustre: 54259:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client fe71f9cf-a6f5-4936-b74a-eb244e97a688@ [ 3026.518356] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 3026.590847] Lustre: 54259:0:(ldlm_lib.c:2069:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3026.604127] Lustre: 54259:0:(ldlm_lib.c:2069:extend_recovery_timer()) Skipped 4 previous similar messages [ 3026.776280] Lustre: lustre-MDT0000: Recovery over after 2:21, of 3 clients 2 recovered and 1 was evicted. [ 3026.788125] Lustre: Skipped 3 previous similar messages [ 3026.837638] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1584 to 0x2c0000401:1665) [ 3026.850553] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1635 to 0x280000401:1665) [ 3032.310610] Lustre: DEBUG MARKER: oleg219-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3034.359975] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3044.315211] Lustre: DEBUG MARKER: == replay-dual test 21a: commit on sharing =============== 03:53:50 (1789113230) [ 3053.311664] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3055.928150] Lustre: Failing over lustre-MDT0000 [ 3056.269502] Lustre: server umount lustre-MDT0000 complete [ 3057.633706] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3057.644378] 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 [ 3057.658424] Lustre: Skipped 13 previous similar messages [ 3075.551140] Lustre: 3656:0:(client.c:2480:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789113247/real 1789113247] req@ffff8ef1fc762a00 x1876018089817088/t0(0) o400->MGC192.168.202.119@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789113263 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3075.588628] Lustre: 3656:0:(client.c:2480:ptlrpc_expire_one_request()) Skipped 4 previous similar messages [ 3079.652877] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3079.658714] LDISKFS-fs (dm-0): recovery complete [ 3079.668646] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3085.793498] LustreError: 3653:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8ef0c7bc6680 x1876018089825536/t0(0) o250->MGC192.168.202.119@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 [ 3086.409978] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 3086.415902] Lustre: Skipped 4 previous similar messages [ 3091.064312] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug -1 all [ 3226.500138] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 3226.517604] Lustre: 56175:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 94028c94-95d0-466d-8a54-9e2d70b3b050@ [ 3226.547057] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 3226.620416] Lustre: 56175:0:(ldlm_lib.c:2069:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3226.645819] Lustre: 56175:0:(ldlm_lib.c:2069:extend_recovery_timer()) Skipped 4 previous similar messages [ 3226.685142] Lustre: lustre-MDT0000-osp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 3226.700979] Lustre: Skipped 15 previous similar messages [ 3226.729529] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1667 to 0x280000401:1697) [ 3226.731043] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1584 to 0x2c0000401:1697) [ 3237.091870] Lustre: DEBUG MARKER: SKIP: replay-dual test_21b skipping SLOW test 21b [ 3238.932753] Lustre: DEBUG MARKER: == replay-dual test 22a: c1 lfs mkdir -i 1 dir1, M1 drop reply [ 3240.520309] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 3240.523925] LustreError: 6577:0:(ldlm_lib.c:3327:target_send_reply_msg()) @@@ dropping reply req@ffff8ef1ee6e0380 x1876018059975808/t4294967346(0) o36->8f2c345e-ab56-4735-8089-b0bb41205c5d@192.168.202.19@tcp:579/0 lens 560/448 e 0 to 0 dl 1789113509 ref 1 fl Interpret:/200/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 3243.653277] Lustre: Failing over lustre-MDT0001 [ 3243.951680] Lustre: server umount lustre-MDT0001 complete [ 3245.025822] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 3245.061282] LustreError: 49953:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3245.071183] LustreError: 49953:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 131 previous similar messages [ 3263.116310] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3263.510709] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 3263.513307] Lustre: Skipped 3 previous similar messages [ 3263.568485] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 3263.579405] Lustre: Skipped 3 previous similar messages [ 3268.446044] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug -1 all [ 3268.759711] Lustre: 10140:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff8ef1f8335f80 x1876018059975808/t4294967346(0) o36->8f2c345e-ab56-4735-8089-b0bb41205c5d@192.168.202.19@tcp:607/0 lens 560/2880 e 0 to 0 dl 1789113537 ref 1 fl Interpret:/202/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 3278.353030] Lustre: DEBUG MARKER: oleg219-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 3280.639708] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3292.156537] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3294.970929] Lustre: Failing over lustre-MDT0000 [ 3295.378966] Lustre: server umount lustre-MDT0000 complete [ 3299.305177] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3315.679697] LustreError: MGC192.168.202.119@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3315.702742] LustreError: Skipped 3 previous similar messages [ 3318.790472] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3318.794069] LDISKFS-fs (dm-0): recovery complete [ 3318.802912] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3325.939447] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xe1aef795fee406e8 [ 3330.201981] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug -1 all [ 3331.618385] Lustre: 59117:0:(ldlm_lib.c:2069:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3331.711761] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1667 to 0x280000401:1729) [ 3331.715852] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1584 to 0x2c0000401:1729) [ 3338.219953] Lustre: DEBUG MARKER: oleg219-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3340.204074] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3350.189153] Lustre: DEBUG MARKER: == replay-dual test 22b: c1 lfs mkdir -i 1 d1, M1 drop reply [ 3351.961913] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 3351.974239] LustreError: 6577:0:(ldlm_lib.c:3327:target_send_reply_msg()) @@@ dropping reply req@ffff8ef1ef42b800 x1876018060016896/t8589934617(0) o36->8f2c345e-ab56-4735-8089-b0bb41205c5d@192.168.202.19@tcp:690/0 lens 560/448 e 0 to 0 dl 1789113620 ref 1 fl Interpret:/200/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 3354.920693] Lustre: Failing over lustre-MDT0000 [ 3355.193786] Lustre: server umount lustre-MDT0000 complete [ 3359.309380] LustreError: 8486:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1789113547 with bad export cookie 16262207528079984360 [ 3359.315741] Lustre: Failing over lustre-MDT0001 [ 3359.329374] LustreError: 8486:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 3359.390583] LustreError: 60146:0:(client.c:1380:ptlrpc_import_delay_req()) @@@ IMP_CLOSED req@ffff8ef1f013a680 x1876018089969792/t0(0) o1000->lustre-MDT0000-osp-MDT0001@0@lo:24/4 lens 304/4320 e 0 to 0 dl 0 ref 2 fl Rpc:QU/200/ffffffff rc 0/-1 job:'umount.0' uid:0 gid:0 projid:4294967295 [ 3359.432550] LustreError: 60146:0:(osp_object.c:617:osp_attr_get()) lustre-MDT0000-osp-MDT0001: osp_attr_get update error [0x200000401:0x1:0x0]: rc = -5 [ 3360.041884] Lustre: server umount lustre-MDT0001 complete [ 3379.966247] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3379.968706] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3380.261852] LustreError: 60859:0:(llog.c:1646:llog_backup()) MGC192.168.202.119@tcp: failed to open log lustre-sptlrpc: rc = -108 [ 3380.271159] Lustre: 60859:0:(mgc_request_server.c:768:mgc_llog_local_copy()) MGC192.168.202.119@tcp: failed to copy new config lustre-sptlrpc: rc = -108 [ 3391.147912] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug -1 all [ 3391.259616] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug -1 all [ 3391.653261] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:36 to 0x280000400:65) [ 3391.658640] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:36 to 0x2c0000400:65) [ 3391.676714] Lustre: 60866:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff8ef1fb96ce00 x1876018060016896/t8589934617(0) o36->8f2c345e-ab56-4735-8089-b0bb41205c5d@192.168.202.19@tcp:730/0 lens 560/2880 e 0 to 0 dl 1789113660 ref 1 fl Interpret:/202/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 3398.181760] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1584 to 0x2c0000401:1761) [ 3398.186099] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1667 to 0x280000401:1761) [ 3403.789555] Lustre: DEBUG MARKER: oleg219-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 3405.806643] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3407.887439] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3420.628774] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3423.228344] Lustre: Failing over lustre-MDT0000 [ 3423.674580] Lustre: server umount lustre-MDT0000 complete [ 3423.717911] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3448.233359] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3448.235592] LDISKFS-fs (dm-0): recovery complete [ 3448.243664] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3458.622029] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug -1 all [ 3459.119038] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1584 to 0x2c0000401:1793) [ 3459.121259] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1667 to 0x280000401:1793) [ 3467.936815] Lustre: DEBUG MARKER: oleg219-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3470.301357] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3481.739824] Lustre: DEBUG MARKER: == replay-dual test 22c: c1 lfs mkdir -i 1 d1, M1 drop update [ 3483.260943] Lustre: *** cfs_fail_loc=1701, val=2147483648*** [ 3483.267241] LustreError: 61413:0:(ldlm_lib.c:3327:target_send_reply_msg()) @@@ dropping reply req@ffff8ef20029b100 x1876018090043520/t107374182411(0) o1000->lustre-MDT0001-mdtlov_UUID@0@lo:752/0 lens 2520/4320 e 0 to 0 dl 1789113682 ref 1 fl Interpret:/200/0 rc 0/0 job:'osp_up0-1.0' uid:0 gid:0 projid:4294967295 [ 3486.893607] Lustre: Failing over lustre-MDT0000 [ 3487.157903] Lustre: server umount lustre-MDT0000 complete [ 3489.762236] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3507.121783] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3516.390075] LustreError: 3653:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8ef1eef1aa00 x1876018090055040/t0(0) o250->MGC192.168.202.119@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 [ 3522.119955] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1667 to 0x280000401:1825) [ 3522.120514] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1584 to 0x2c0000401:1825) [ 3522.467730] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug -1 all [ 3531.661650] Lustre: DEBUG MARKER: oleg219-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3533.467529] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3544.862563] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3547.703177] Lustre: Failing over lustre-MDT0000 [ 3547.846954] Lustre: lustre-MDT0000: Not available for connect from 192.168.202.19@tcp (stopping) [ 3548.083288] Lustre: server umount lustre-MDT0000 complete [ 3572.515499] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3572.517361] LDISKFS-fs (dm-0): recovery complete [ 3572.526554] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3579.445484] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xe1aef795fee4247e [ 3585.072029] Lustre: 65934:0:(ldlm_lib.c:2069:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3585.095023] Lustre: 65934:0:(ldlm_lib.c:2069:extend_recovery_timer()) Skipped 4 previous similar messages [ 3585.292252] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1667 to 0x280000401:1857) [ 3585.294176] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1584 to 0x2c0000401:1857) [ 3585.536172] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug -1 all [ 3594.597973] Lustre: DEBUG MARKER: oleg219-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3596.670330] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3607.497838] Lustre: DEBUG MARKER: == replay-dual test 22d: c1 lfs mkdir -i 1 d1, M1 drop update [ 3612.189347] Lustre: *** cfs_fail_loc=1701, val=2147483648*** [ 3612.191958] LustreError: 8470:0:(ldlm_lib.c:3327:target_send_reply_msg()) @@@ dropping reply req@ffff8ef0c5142a00 x1876018090121984/t115964117002(0) o1000->lustre-MDT0001-mdtlov_UUID@0@lo:126/0 lens 2520/4320 e 0 to 0 dl 1789113811 ref 1 fl Interpret:/200/0 rc 0/0 job:'osp_up0-1.0' uid:0 gid:0 projid:4294967295 [ 3616.222656] Lustre: Failing over lustre-MDT0000 [ 3616.239795] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -19 [ 3616.248712] LustreError: Skipped 1 previous similar message [ 3616.268406] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3616.270215] Lustre: Skipped 1 previous similar message [ 3616.789651] Lustre: server umount lustre-MDT0000 complete [ 3621.498485] LustreError: 8486:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1789113809 with bad export cookie 16262207528079991934 [ 3621.509121] Lustre: Failing over lustre-MDT0001 [ 3621.519306] LustreError: 8486:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 3621.545729] LustreError: 67059:0:(ldlm_resource.c:1180:ldlm_resource_complain()) lustre-MDT0000-osp-MDT0001: namespace resource [0x2000013a1:0x79:0x0].0xf7117594 (ffff8ef1ee652800) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 3627.464794] Lustre: server umount lustre-MDT0001 complete [ 3648.021451] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3648.071362] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3648.363843] LustreError: 67776:0:(llog.c:1646:llog_backup()) MGC192.168.202.119@tcp: failed to open log lustre-sptlrpc: rc = -108 [ 3648.369226] Lustre: 67776:0:(mgc_request_server.c:768:mgc_llog_local_copy()) MGC192.168.202.119@tcp: failed to copy new config lustre-sptlrpc: rc = -108 [ 3667.941087] LustreError: 3653:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8ef1fc596300 x1876018090132096/t0(0) o250->MGC192.168.202.119@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 [ 3673.406339] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug -1 all [ 3673.527301] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug -1 all [ 3674.109754] Lustre: lustre-MDT0000: Recovery over after 0:05, of 3 clients 3 recovered and 0 were evicted. [ 3674.122482] Lustre: Skipped 8 previous similar messages [ 3674.226190] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1667 to 0x280000401:1889) [ 3674.226203] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1584 to 0x2c0000401:1889) [ 3674.358510] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:70 to 0x2c0000400:97) [ 3674.359156] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:70 to 0x280000400:97) [ 3674.519629] Lustre: 67784:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff8ef1f016df80 x1876018060109184/t12884901939(0) o36->8f2c345e-ab56-4735-8089-b0bb41205c5d@192.168.202.19@tcp:257/0 lens 560/2880 e 0 to 0 dl 1789113942 ref 1 fl Interpret:/202/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 3683.599702] Lustre: DEBUG MARKER: oleg219-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 3685.484498] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3687.329890] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3699.229571] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3702.250169] Lustre: Failing over lustre-MDT0000 [ 3702.618208] Lustre: server umount lustre-MDT0000 complete [ 3704.810814] 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 [ 3704.857043] Lustre: Skipped 37 previous similar messages [ 3720.159147] Lustre: 3654:0:(client.c:2480:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789113892/real 1789113892] req@ffff8ef1d811df80 x1876018090164480/t0(0) o400->MGC192.168.202.119@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789113908 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3720.201206] Lustre: 3654:0:(client.c:2480:ptlrpc_expire_one_request()) Skipped 17 previous similar messages [ 3727.642836] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3727.649686] LDISKFS-fs (dm-0): recovery complete [ 3727.667807] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3731.508336] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xe1aef795fee43499 [ 3732.287380] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 3732.293344] Lustre: Skipped 9 previous similar messages [ 3737.063708] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug -1 all [ 3737.146775] Lustre: 69866:0:(ldlm_lib.c:2069:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3737.168653] Lustre: 69866:0:(ldlm_lib.c:2069:extend_recovery_timer()) Skipped 4 previous similar messages [ 3737.395473] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1667 to 0x280000401:1921) [ 3737.410020] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1584 to 0x2c0000401:1921) [ 3746.320214] Lustre: DEBUG MARKER: oleg219-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3748.486285] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3757.865911] Lustre: DEBUG MARKER: == replay-dual test 23a: c1 rmdir d1, M1 drop reply and fail, client2 mkdir d1 ========================================================== 04:05:44 (1789113944) [ 3759.117425] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 3759.124095] LustreError: 67786:0:(ldlm_lib.c:3327:target_send_reply_msg()) @@@ dropping reply req@ffff8ef0c87a3b80 x1876018060157056/t17179869210(0) o36->8f2c345e-ab56-4735-8089-b0bb41205c5d@192.168.202.19@tcp:342/0 lens 496/456 e 0 to 0 dl 1789114027 ref 1 fl Interpret:/200/0 rc 0/0 job:'rmdir.0' uid:0 gid:0 projid:4294967295 [ 3763.313997] Lustre: Failing over lustre-MDT0001 [ 3763.579579] Lustre: server umount lustre-MDT0001 complete [ 3767.778579] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 3767.792627] LustreError: Skipped 1 previous similar message [ 3782.282800] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3787.710652] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug -1 all [ 3788.371508] Lustre: 67786:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff8ef1fbd11500 x1876018060157056/t17179869210(0) o36->8f2c345e-ab56-4735-8089-b0bb41205c5d@192.168.202.19@tcp:371/0 lens 496/2888 e 0 to 0 dl 1789114056 ref 1 fl Interpret:/202/0 rc 0/0 job:'rmdir.0' uid:0 gid:0 projid:4294967295 [ 3788.390840] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:100 to 0x280000400:129) [ 3788.391070] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:100 to 0x2c0000400:129) [ 3795.881227] Lustre: DEBUG MARKER: oleg219-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 3798.119715] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3808.618338] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3811.013076] Lustre: Failing over lustre-MDT0000 [ 3811.292955] Lustre: server umount lustre-MDT0000 complete [ 3834.835190] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3834.837540] LDISKFS-fs (dm-0): recovery complete [ 3834.844580] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3839.469764] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xe1aef795fee440a8 [ 3839.492088] Lustre: MGC192.168.202.119@tcp: Connection restored to 0@lo (at 0@lo) [ 3839.497077] Lustre: Skipped 41 previous similar messages [ 3839.685395] Lustre: lustre-MDT0000: Not available for connect from 192.168.202.19@tcp (not set up) [ 3839.699216] Lustre: Skipped 11 previous similar messages [ 3844.915671] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug -1 all [ 3845.161280] Lustre: 72810:0:(ldlm_lib.c:2069:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3845.175726] Lustre: 72810:0:(ldlm_lib.c:2069:extend_recovery_timer()) Skipped 4 previous similar messages [ 3845.334975] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1923 to 0x2c0000401:1953) [ 3845.343519] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1923 to 0x280000401:1953) [ 3855.216479] Lustre: DEBUG MARKER: oleg219-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3857.451938] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3867.649626] Lustre: DEBUG MARKER: == replay-dual test 23b: c1 rmdir d1, M1 drop reply and fail M0/M1, c2 mkdir d1 ========================================================== 04:07:33 (1789114053) [ 3869.365636] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 3869.386312] LustreError: 67814:0:(ldlm_lib.c:3327:target_send_reply_msg()) @@@ dropping reply req@ffff8ef0c413f800 x1876018060192384/t21474836483(0) o36->8f2c345e-ab56-4735-8089-b0bb41205c5d@192.168.202.19@tcp:452/0 lens 496/456 e 0 to 0 dl 1789114137 ref 1 fl Interpret:/200/0 rc 0/0 job:'rmdir.0' uid:0 gid:0 projid:4294967295 [ 3873.603618] Lustre: Failing over lustre-MDT0000 [ 3873.681856] LustreError: 6563:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1789114061 with bad export cookie 16262207528079999263 [ 3873.703316] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3873.881606] Lustre: server umount lustre-MDT0000 complete [ 3875.819782] LustreError: 61413:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3875.858454] LustreError: 61413:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 337 previous similar messages [ 3878.524333] LustreError: 6562:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1789114066 with bad export cookie 16262207528079999144 [ 3878.532597] Lustre: Failing over lustre-MDT0001 [ 3878.556394] LustreError: 6562:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 3879.044432] Lustre: server umount lustre-MDT0001 complete [ 3899.804360] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3900.247381] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3904.149070] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3904.157739] Lustre: Skipped 11 previous similar messages [ 3904.223212] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 3904.241758] Lustre: Skipped 11 previous similar messages [ 3909.899244] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug -1 all [ 3910.633434] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug -1 all [ 3911.378770] Lustre: 74610:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff8ef1fb916d80 x1876018060192384/t21474836483(0) o36->8f2c345e-ab56-4735-8089-b0bb41205c5d@192.168.202.19@tcp:494/0 lens 496/2888 e 0 to 0 dl 1789114179 ref 1 fl Interpret:/202/0 rc 0/0 job:'rmdir.0' uid:0 gid:0 projid:4294967295 [ 3911.387352] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:100 to 0x280000400:161) [ 3911.416420] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:100 to 0x2c0000400:161) [ 3916.682478] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1923 to 0x280000401:1985) [ 3916.695532] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1923 to 0x2c0000401:1985) [ 3921.163379] Lustre: DEBUG MARKER: oleg219-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 3922.970694] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3924.744797] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3935.575569] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3937.832914] Lustre: Failing over lustre-MDT0000 [ 3938.151265] Lustre: server umount lustre-MDT0000 complete [ 3957.711352] LustreError: MGC192.168.202.119@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3957.723740] LustreError: Skipped 8 previous similar messages [ 3960.011154] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3960.013049] LDISKFS-fs (dm-0): recovery complete [ 3960.028663] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3973.715268] Lustre: 76685:0:(ldlm_lib.c:2069:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3973.742325] Lustre: 76685:0:(ldlm_lib.c:2069:extend_recovery_timer()) Skipped 8 previous similar messages [ 3974.098448] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1987 to 0x2c0000401:2017) [ 3974.099298] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1987 to 0x280000401:2017) [ 3974.310212] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug -1 all [ 3983.935686] Lustre: DEBUG MARKER: oleg219-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3985.989929] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3995.665622] Lustre: DEBUG MARKER: == replay-dual test 23c: c1 rmdir d1, M0 drop update reply and fail M0, c2 mkdir d1 ========================================================== 04:09:41 (1789114181) [ 3997.430317] Lustre: *** cfs_fail_loc=1701, val=2147483648*** [ 3997.433604] LustreError: 61413:0:(ldlm_lib.c:3327:target_send_reply_msg()) @@@ dropping reply req@ffff8ef1fd979180 x1876018090348800/t137438953491(0) o1000->lustre-MDT0001-mdtlov_UUID@0@lo:511/0 lens 1984/4320 e 0 to 0 dl 1789114196 ref 1 fl Interpret:/200/0 rc 0/0 job:'osp_up0-1.0' uid:0 gid:0 projid:4294967295 [ 4001.393273] Lustre: Failing over lustre-MDT0000 [ 4001.736785] Lustre: server umount lustre-MDT0000 complete [ 4021.259889] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4030.944462] LustreError: 3653:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8ef1f0368e00 x1876018090360704/t0(0) o250->MGC192.168.202.119@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 [ 4031.178218] Lustre: lustre-MDT0000: Not available for connect from 192.168.202.19@tcp (not set up) [ 4031.194407] Lustre: Skipped 1 previous similar message [ 4036.713628] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug -1 all [ 4036.729868] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1987 to 0x280000401:2049) [ 4036.729868] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1987 to 0x2c0000401:2049) [ 4046.532632] Lustre: DEBUG MARKER: oleg219-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4048.965139] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4060.692424] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4063.516366] Lustre: Failing over lustre-MDT0000 [ 4063.816973] Lustre: server umount lustre-MDT0000 complete [ 4087.939201] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 4087.946994] LDISKFS-fs (dm-0): recovery complete [ 4087.980343] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4098.811040] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug -1 all [ 4099.862911] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2051 to 0x280000401:2081) [ 4099.863550] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2051 to 0x2c0000401:2081) [ 4108.056253] Lustre: DEBUG MARKER: oleg219-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4110.345365] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4121.934230] Lustre: DEBUG MARKER: == replay-dual test 23d: c1 rmdir d1, M0 drop update reply and fail M0/M1, c2 mkdir d1 ========================================================== 04:11:47 (1789114307) [ 4126.908798] Lustre: *** cfs_fail_loc=1701, val=2147483648*** [ 4126.912168] LustreError: 8470:0:(ldlm_lib.c:3327:target_send_reply_msg()) @@@ dropping reply req@ffff8ef1fb914700 x1876018090429440/t146028888081(0) o1000->lustre-MDT0001-mdtlov_UUID@0@lo:640/0 lens 1984/4320 e 0 to 0 dl 1789114325 ref 1 fl Interpret:/200/0 rc 0/0 job:'osp_up0-1.0' uid:0 gid:0 projid:4294967295 [ 4130.912716] Lustre: Failing over lustre-MDT0000 [ 4131.351846] Lustre: server umount lustre-MDT0000 complete [ 4134.921806] LustreError: 6562:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1789114322 with bad export cookie 16262207528080006501 [ 4134.945164] Lustre: Failing over lustre-MDT0001 [ 4134.952105] LustreError: 80777:0:(ldlm_resource.c:1180:ldlm_resource_complain()) lustre-MDT0000-osp-MDT0001: namespace resource [0x2000013a1:0x81:0x0].0x0 (ffff8ef1c5209c00) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 4141.524819] Lustre: server umount lustre-MDT0001 complete [ 4162.629735] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4162.824853] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4163.130722] LustreError: 81474:0:(llog.c:1646:llog_backup()) MGC192.168.202.119@tcp: failed to open log lustre-sptlrpc: rc = -108 [ 4163.139827] Lustre: 81474:0:(mgc_request_server.c:768:mgc_llog_local_copy()) MGC192.168.202.119@tcp: failed to copy new config lustre-sptlrpc: rc = -108 [ 4185.274879] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug -1 all [ 4185.511460] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug -1 all [ 4185.674307] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2051 to 0x280000401:2113) [ 4185.676457] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2051 to 0x2c0000401:2113) [ 4185.851541] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:100 to 0x280000400:193) [ 4185.852344] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:100 to 0x2c0000400:193) [ 4185.885570] Lustre: 81618:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff8ef1fb467100 x1876018060275968/t25769803783(0) o36->8f2c345e-ab56-4735-8089-b0bb41205c5d@192.168.202.19@tcp:13/0 lens 496/2888 e 0 to 0 dl 1789114453 ref 1 fl Interpret:/202/0 rc 0/0 job:'rmdir.0' uid:0 gid:0 projid:4294967295 [ 4193.455566] Lustre: DEBUG MARKER: oleg219-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 4195.344578] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4197.542988] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4208.276996] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4210.687956] Lustre: Failing over lustre-MDT0000 [ 4211.155403] Lustre: server umount lustre-MDT0000 complete [ 4211.178652] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4211.197740] LustreError: Skipped 2 previous similar messages [ 4234.506513] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 4234.509222] LDISKFS-fs (dm-0): recovery complete [ 4234.514969] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4243.495029] Lustre: 83572:0:(ldlm_lib.c:2069:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 4243.520781] Lustre: 83572:0:(ldlm_lib.c:2069:extend_recovery_timer()) Skipped 17 previous similar messages [ 4243.816806] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2115 to 0x2c0000401:2145) [ 4243.820486] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2115 to 0x280000401:2145) [ 4244.132871] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug -1 all [ 4254.506473] Lustre: DEBUG MARKER: oleg219-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4257.244959] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4268.792506] Lustre: DEBUG MARKER: == replay-dual test 24: reconstruct on non-existing object ========================================================== 04:14:14 (1789114454) [ 4270.085161] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 4270.093039] LustreError: 81490:0:(ldlm_lib.c:3327:target_send_reply_msg()) @@@ dropping reply req@ffff8ef1f016d500 x1876018060319616/t154618822673(0) o36->8f2c345e-ab56-4735-8089-b0bb41205c5d@192.168.202.19@tcp:97/0 lens 488/456 e 0 to 0 dl 1789114537 ref 1 fl Interpret:/200/0 rc 0/0 job:'truncate.0' uid:0 gid:0 projid:4294967295 [ 4354.842320] Lustre: lustre-MDT0000: Client 8f2c345e-ab56-4735-8089-b0bb41205c5d (at 192.168.202.19@tcp) reconnecting [ 4354.878349] Lustre: 81492:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff8ef1e9b34a80 x1876018060319616/t154618822673(0) o36->8f2c345e-ab56-4735-8089-b0bb41205c5d@192.168.202.19@tcp:182/0 lens 488/3152 e 0 to 0 dl 1789114622 ref 1 fl Interpret:/202/0 rc 0/0 job:'truncate.0' uid:0 gid:0 projid:4294967295 [ 4363.054340] Lustre: DEBUG MARKER: == replay-dual test 25: replay|resend ==================== 04:15:49 (1789114549) [ 4364.903530] Lustre: *** cfs_fail_loc=304, val=0*** [ 4367.382986] Lustre: Failing over lustre-OST0000 [ 4367.529890] Lustre: server umount lustre-OST0000 complete [ 4370.403876] Lustre: lustre-OST0000-osc-MDT0001: Connection to lustre-OST0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 4370.413827] Lustre: Skipped 33 previous similar messages [ 4387.311505] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4388.978856] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 4 clients reconnect [ 4388.989449] Lustre: Skipped 10 previous similar messages [ 4389.307825] Lustre: lustre-OST0000: Recovery over after 0:01, of 4 clients 4 recovered and 0 were evicted. [ 4389.329308] Lustre: Skipped 12 previous similar messages [ 4395.629469] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug -1 all [ 4404.144057] Lustre: DEBUG MARKER: oleg219-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 4405.776602] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4417.701722] Lustre: DEBUG MARKER: == replay-dual test 26: dbench and tar with mds failover ========================================================== 04:16:43 (1789114603) [ 4430.738160] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4434.807564] Lustre: DEBUG MARKER: test_26 fail mds1 1 times [ 4436.916987] Lustre: Failing over lustre-MDT0000 [ 4436.955414] Lustre: lustre-MDT0000: Not available for connect from 192.168.202.19@tcp (stopping) [ 4436.964734] Lustre: Skipped 8 previous similar messages [ 4437.345792] Lustre: server umount lustre-MDT0000 complete [ 4454.367505] Lustre: 3656:0:(client.c:2480:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789114626/real 1789114626] req@ffff8ef1e9b3ce00 x1876018090630656/t0(0) o400->MGC192.168.202.119@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789114642 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4454.407157] Lustre: 3656:0:(client.c:2480:ptlrpc_expire_one_request()) Skipped 22 previous similar messages [ 4462.671878] LDISKFS-fs (dm-0): 4 truncates cleaned up [ 4462.676930] LDISKFS-fs (dm-0): recovery complete [ 4462.682402] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4464.863175] LustreError: 87239:0:(import.c:339:ptlrpc_invalidate_import()) MGS: timeout waiting for callback (1 != 0) [ 4464.875963] LustreError: 87239:0:(import.c:363:ptlrpc_invalidate_import()) @@@ still on sending list req@ffff8ef1f3883800 x1876018090637056/t0(0) o250->MGC192.168.202.119@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 1789114652 ref 1 fl Rpc:NQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4464.898880] LustreError: 87239:0:(import.c:373:ptlrpc_invalidate_import()) MGS: Unregistering RPCs found (0). Network is sluggish? Waiting for them to error out. [ 4465.647802] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xe1aef795fee4b1c0 [ 4465.663583] Lustre: MGC192.168.202.119@tcp: Connection restored to 0@lo (at 0@lo) [ 4465.682554] Lustre: Skipped 34 previous similar messages [ 4472.155866] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug -1 all [ 4473.798090] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2171 to 0x280000401:2209) [ 4473.799521] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2170 to 0x2c0000401:2209) [ 4483.867816] Lustre: DEBUG MARKER: oleg219-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4486.333789] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4505.560779] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 4510.625269] Lustre: DEBUG MARKER: test_26 fail mds2 2 times [ 4513.933344] Lustre: Failing over lustre-MDT0001 [ 4514.362240] LustreError: 84427:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0001: not available for connect from 192.168.202.19@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4514.398701] LustreError: 84427:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 266 previous similar messages [ 4514.457144] Lustre: server umount lustre-MDT0001 complete [ 4539.571446] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 4539.577045] LDISKFS-fs (dm-1): recovery complete [ 4539.597752] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4540.042666] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 4540.048924] Lustre: Skipped 9 previous similar messages [ 4540.126848] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 4540.139156] Lustre: Skipped 9 previous similar messages [ 4545.005464] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug -1 all [ 4545.607075] Lustre: 88949:0:(ldlm_lib.c:2069:extend_recovery_timer()) lustre-MDT0001: extended recovery timer reached hard limit: 180, extend: 1 [ 4545.623529] Lustre: 88949:0:(ldlm_lib.c:2069:extend_recovery_timer()) Skipped 182 previous similar messages [ 4548.015381] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:269 to 0x2c0000400:289) [ 4548.015548] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:270 to 0x280000400:289) [ 4555.318739] Lustre: DEBUG MARKER: oleg219-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 4557.668428] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4571.283697] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4575.815362] Lustre: DEBUG MARKER: test_26 fail mds1 3 times [ 4578.243539] Lustre: Failing over lustre-MDT0000 [ 4584.304924] Lustre: server umount lustre-MDT0000 complete [ 4602.850847] LustreError: MGC192.168.202.119@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4602.861384] LustreError: Skipped 5 previous similar messages [ 4608.132778] LDISKFS-fs (dm-0): 3 truncates cleaned up [ 4608.136297] LDISKFS-fs (dm-0): recovery complete [ 4608.145129] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4613.090661] LustreError: 3653:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8ef0c720ea00 x1876018091003392/t0(0) o250->MGC192.168.202.119@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 [ 4613.136459] LustreError: 3653:0:(client.c:1390:ptlrpc_import_delay_req()) Skipped 1 previous similar message [ 4617.662919] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug -1 all [ 4620.758062] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2299 to 0x280000401:2337) [ 4620.778600] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2299 to 0x2c0000401:2337) [ 4627.339184] Lustre: DEBUG MARKER: oleg219-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4629.355685] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4674.512851] Lustre: DEBUG MARKER: == replay-dual test 28: lock replay should be ordered: waiting after granted ========================================================== 04:21:00 (1789114860) [ 4694.457127] Lustre: Failing over lustre-OST0000 [ 4695.537081] Lustre: lustre-OST0000: Not available for connect from 0@lo (stopping) [ 4695.548417] Lustre: Skipped 11 previous similar messages [ 4696.746474] Lustre: server umount lustre-OST0000 complete [ 4715.235459] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4717.311761] Lustre: *** cfs_fail_loc=32a, val=0*** [ 4722.719738] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug -1 all [ 4730.643985] Lustre: DEBUG MARKER: oleg219-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 4732.396598] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4743.421576] Lustre: DEBUG MARKER: == replay-dual test 29: replay vs update with the same xid ========================================================== 04:22:09 (1789114929) [ 4745.310564] Lustre: DEBUG MARKER: SKIP: replay-dual test_29 needs >= 2 clients [ 4747.693476] Lustre: DEBUG MARKER: == replay-dual test 30: layout lock replay is not blocked on IO ========================================================== 04:22:13 (1789114933) [ 4751.402877] Lustre: Failing over lustre-MDT0000 [ 4751.837466] Lustre: server umount lustre-MDT0000 complete [ 4753.893270] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4753.908849] LustreError: Skipped 4 previous similar messages [ 4772.401946] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4778.143169] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2362 to 0x280000401:2401) [ 4778.147273] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2361 to 0x2c0000401:2401) [ 4778.530021] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug -1 all [ 4786.853105] Lustre: DEBUG MARKER: oleg219-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4788.685979] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4797.743231] Lustre: DEBUG MARKER: == replay-dual test 31: deadlock on file_remove_privs and occupied mod rpc slots ========================================================== 04:23:03 (1789114983) [ 4801.657449] Lustre: Failing over lustre-OST0000 [ 4801.925533] Lustre: server umount lustre-OST0000 complete [ 4821.428242] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4827.574882] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug -1 all [ 4835.674642] Lustre: DEBUG MARKER: oleg219-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 4837.533946] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL [ 4847.304586] Lustre: DEBUG MARKER: == replay-dual test 32: gap in update llog shouldn't break recovery ========================================================== 04:23:53 (1789115033) [ 4848.503911] Lustre: *** cfs_fail_loc=131d, val=10*** [ 4849.042478] Lustre: *** cfs_fail_loc=131d, val=4*** [ 4849.045523] Lustre: Skipped 5 previous similar messages [ 4850.107599] Lustre: *** cfs_fail_loc=131d, val=4294967286*** [ 4850.111682] Lustre: Skipped 13 previous similar messages [ 4852.688130] Lustre: Failing over lustre-MDT0001 [ 4852.966947] Lustre: server umount lustre-MDT0001 complete [ 4856.344239] Lustre: Failing over lustre-MDT0000 [ 4856.886564] Lustre: server umount lustre-MDT0000 complete [ 4864.618838] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4865.305515] Lustre: *** cfs_fail_loc=131d, val=4294967266*** [ 4865.308768] Lustre: Skipped 19 previous similar messages [ 4870.729942] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug -1 all [ 4878.837790] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4879.114469] Lustre: *** cfs_fail_loc=131d, val=4294967262*** [ 4879.124798] Lustre: Skipped 3 previous similar messages [ 4885.086808] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:323 to 0x280000400:353) [ 4885.087920] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:323 to 0x2c0000400:353) [ 4885.120489] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2441 to 0x280000401:2497) [ 4885.120524] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2361 to 0x2c0000401:2433) [ 4885.316927] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug -1 all [ 4897.908408] Lustre: DEBUG MARKER: == replay-dual test 33: Check for OBD_INCOMPAT_MULTI_RPCS in last_rcvd after abort_recovery ========================================================== 04:24:43 (1789115083) [ 4905.606575] Lustre: Failing over lustre-MDT0001 [ 4905.911655] Lustre: server umount lustre-MDT0001 complete [ 4927.510077] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4932.686627] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug -1 all [ 4938.278969] Lustre: DEBUG MARKER: oleg219-client.virtnet: executing wait_import_state_mount REPLAY_WAIT mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 4940.118200] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in REPLAY_WAIT state after 0 sec [ 4941.015330] Lustre: lustre-MDT0001: Aborting client recovery [ 4941.022050] LustreError: 99324:0:(ldlm_lib.c:2985:target_stop_recovery_thread()) lustre-MDT0001: Aborting recovery [ 4941.030979] Lustre: 98803:0:(ldlm_lib.c:2388:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 4941.038196] Lustre: 98803:0:(ldlm_lib.c:2388:target_recovery_overseer()) Skipped 2 previous similar messages [ 4941.044957] Lustre: 98803:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0001: disconnect stale client 2413649b-d177-48e7-ac3f-19590ba404a6@ [ 4941.053367] Lustre: lustre-MDT0001: disconnecting 1 stale clients [ 4941.069324] Lustre: lustre-MDT0001-osd: cancel update llog [0x240000400:0x1:0x0] [ 4941.078468] Lustre: lustre-MDT0000-osp-MDT0001: cancel update llog [0x200000401:0x1:0x0] [ 4941.141934] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:323 to 0x2c0000400:385) [ 4941.149890] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:323 to 0x280000400:385) [ 4944.681803] Lustre: DEBUG MARKER: oleg219-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 4946.305501] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4949.656956] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0001.recovery_status 1475 [ 4956.946456] Lustre: Failing over lustre-MDT0001 [ 4957.345557] Lustre: server umount lustre-MDT0001 complete [ 4966.746166] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4971.982817] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug -1 all [ 4972.629288] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:323 to 0x2c0000400:417) [ 4972.630070] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:323 to 0x280000400:417) [ 4978.930520] Lustre: DEBUG MARKER: oleg219-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 4981.091837] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4985.551454] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0001.recovery_status 1475 [ 4993.848786] Lustre: DEBUG MARKER: == replay-dual test complete, duration 4683 sec ========== 04:26:19 (1789115179) [ 4995.956538] Lustre: DEBUG MARKER: === replay-dual: start cleanup 04:26:21 (1789115181) === [ 5010.418724] Lustre: DEBUG MARKER: === replay-dual: finish cleanup 04:26:36 (1789115196) === [ 5012.857761] Lustre: Failing over lustre-MDT0000 [ 5012.896854] 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 [ 5012.919533] Lustre: Skipped 31 previous similar messages [ 5013.176726] Lustre: server umount lustre-MDT0000 complete [ 5041.061667] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5042.760949] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 5042.774511] Lustre: Skipped 10 previous similar messages [ 5046.965918] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5182.500949] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 5182.510729] Lustre: 102247:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 2413649b-d177-48e7-ac3f-19590ba404a6@ [ 5182.520831] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 5182.538551] Lustre: lustre-MDT0000: Recovery over after 2:20, of 3 clients 2 recovered and 1 was evicted. [ 5182.540362] Lustre: Skipped 10 previous similar messages [ 5182.542512] Lustre: lustre-MDT0000-osp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 5182.544228] Lustre: Skipped 34 previous similar messages [ 5182.566499] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2361 to 0x2c0000401:2465) [ 5182.566499] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2441 to 0x280000401:2529) [ 5187.444599] Lustre: DEBUG MARKER: oleg219-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 5189.112485] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5202.305787] Lustre: server umount lustre-MDT0000 complete [ 5205.480898] LustreError: 96890:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 5205.500868] LustreError: 96890:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 182 previous similar messages [ 5211.314836] LustreError: 6562:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1789115399 with bad export cookie 16262207528080181529 [ 5211.319600] LustreError: MGC192.168.202.119@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5211.331767] LustreError: 6562:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 5211.357926] LustreError: Skipped 3 previous similar messages [ 5211.846197] Lustre: server umount lustre-MDT0001 complete [ 5231.052192] Lustre: server umount lustre-OST0000 complete [ 5247.793984] Lustre: server umount lustre-OST0001 complete [ 5264.904431] Lustre: DEBUG MARKER: oleg219-server.virtnet: executing unload_modules_local [ 5266.669936] Key type lgssc unregistered [ 5266.809291] LNet: 105054:0:(lib-ptl.c:967:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 5266.811767] LNetError: 105054:0:(acceptor.c:246:lnet_acceptor_remove_socket()) Interface ens2 not found [ 5266.821556] LNet: Removed LNI 192.168.202.119@tcp [ 5267.198390] Key type .llcrypt unregistered [ 5267.199692] Key type ._llcrypt unregistered