[ 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 3.0.0 present. [ 0.000000] DMI: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.16.3-2.fc40 04/01/2014 [ 0.000000] Hypervisor detected: KVM [ 0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00 [ 0.000000] kvm-clock: using sched offset of 498155457 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 0x000f53f0-0x000f53ff] [ 0.000000] RAMDISK: [mem 0xbcc54000-0xbffbffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F5200 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE1D87 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE1C23 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 001BE3 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE1C97 000090 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE1D27 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE1D5F 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe1c23-0xbffe1c96] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe1c22] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe1c97-0xbffe1d26] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe1d27-0xbffe1d5e] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe1d5f-0xbffe1d86] [ 0.000000] No NUMA configuration found [ 0.000000] Faking a node at [mem 0x0000000000000000-0x0000000146dfffff] [ 0.000000] NODE_DATA(0) allocated [mem 0x1465a3000-0x1465cdfff] [ 0.000000] Reserving 256MB of memory at 2752MB for crashkernel (System RAM: 4205MB) [ 0.000000] Zone ranges: [ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.000000] DMA32 [mem 0x0000000001000000-0x00000000ffffffff] [ 0.000000] Normal [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Device empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff] [ 0.000000] node 0: [mem 0x0000000000100000-0x00000000bffcdfff] [ 0.000000] node 0: [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Zeroed struct page in unavailable ranges: 4756 pages [ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x0000000146dfffff] [ 0.000000] ACPI: PM-Timer IO Port: 0x608 [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) [ 0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) [ 0.000000] Using ACPI (MADT) for SMP configuration information [ 0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000] TSC deadline timer available [ 0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs [ 0.000000] kvm-guest: KVM setup pv remote TLB flush [ 0.000000] kvm-guest: setup PV sched yield [ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff] [ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff] [ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff] [ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff] [ 0.000000] PM: Registered nosave memory: [mem 0xbffce000-0xbfffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xc0000000-0xfeffbfff] [ 0.000000] PM: Registered nosave memory: [mem 0xfeffc000-0xfeffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xff000000-0xfffbffff] [ 0.000000] PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff] [ 0.000000] [mem 0xc0000000-0xfeffbfff] available for PCI devices [ 0.000000] Booting paravirtualized kernel on KVM [ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns [ 0.000000] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1 [ 0.000000] percpu: Embedded 63 pages/cpu s221184 r8192 d28672 u524288 [ 0.000000] kvm-guest: PV spinlocks enabled [ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1059606 [ 0.000000] Policy zone: Normal [ 0.000000] Kernel command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] Specific versions of hardware are certified with Red Hat Enterprise Linux 8. Please see the list of hardware certified with Red Hat Enterprise Linux 8 at https://catalog.redhat.com. [ 0.000000] audit: disabled (until reboot) [ 0.000000] software IO TLB: area num 4. [ 0.000000] Memory: 2895240K/4306352K available (18435K kernel code, 11221K rwdata, 7248K rodata, 2908K init, 18040K bss, 524580K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] ftrace: allocating 41240 entries in 162 pages [ 0.000000] ftrace: allocated 162 pages with 3 groups [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] rcu: RCU event tracing is enabled. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ 0.000000] rcu: RCU callback double-/use-after-free debug enabled. [ 0.000000] Rude variant of Tasks RCU enabled. [ 0.000000] Tracing variant of Tasks RCU enabled. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 0.000000] NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16 [ 0.000000] random: get_random_bytes called from start_kernel+0x622/0x9a8 with crng_init=0 [ 0.001000] Console: colour *CGA 80x25 [ 0.001000] printk: console [ttyS1] enabled [ 0.001000] ACPI: Core revision 20220331 [ 0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.001012] APIC: Switch to symmetric I/O mode setup [ 0.002383] x2apic enabled [ 0.003009] Switched APIC routing to physical x2apic. [ 0.004015] kvm-guest: setup PV IPIs [ 0.007000] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.007000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.007036] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.008013] pid_max: default: 32768 minimum: 301 [ 0.009137] LSM: Security Framework initializing [ 0.010061] Yama: becoming mindful. [ 0.011043] SELinux: Initializing. [ 0.012000] *** VALIDATE selinux *** [ 0.018024] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.022659] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.023154] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.025092] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.026132] *** VALIDATE tmpfs *** [ 0.028277] *** VALIDATE proc *** [ 0.029254] *** VALIDATE cgroup *** [ 0.030015] *** VALIDATE cgroup2 *** [ 0.031445] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.033092] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.034012] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.035030] Spectre V2 : User space: Vulnerable [ 0.036010] Speculative Store Bypass: Vulnerable [ 0.039150] debug: unmapping init [mem 0xffffffffaca59000-0xffffffffaca60fff] [ 0.042177] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.043728] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.044025] ... version: 2 [ 0.045016] ... bit width: 48 [ 0.046016] ... generic registers: 4 [ 0.047015] ... value mask: 0000ffffffffffff [ 0.048017] ... max period: 00007fffffffffff [ 0.049015] ... fixed-purpose events: 3 [ 0.050014] ... event mask: 000000070000000f [ 0.051301] rcu: Hierarchical SRCU implementation. [ 0.053546] smp: Bringing up secondary CPUs ... [ 0.054575] x86: Booting SMP configuration: [ 0.055031] .... node #0, CPUs: #1 #2 #3 [ 0.058587] smp: Brought up 1 node, 4 CPUs [ 0.060014] smpboot: Max logical packages: 1 [ 0.061021] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.238000] node 0 deferred pages initialised in 175ms [ 0.243240] devtmpfs: initialized [ 0.244178] x86/mm: Memory block size: 128MB [ 0.246771] gcov: version magic: 0x41383552 [ 0.250162] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.253083] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.256301] pinctrl core: initialized pinctrl subsystem [ 0.258173] [ 0.258697] ************************************************************* [ 0.261016] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.263012] ** ** [ 0.265011] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.267014] ** ** [ 0.269013] ** This means that this kernel is built to expose internal ** [ 0.272014] ** IOMMU data structures, which may compromise security on ** [ 0.274015] ** your system. ** [ 0.277028] ** ** [ 0.279015] ** If you see this message and you are not debugging the ** [ 0.281020] ** kernel, report this immediately to your vendor! ** [ 0.284014] ** ** [ 0.286013] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.288015] ************************************************************* [ 0.291842] NET: Registered protocol family 16 [ 0.294579] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.297082] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.300109] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.305078] cpuidle: using governor menu [ 0.306716] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.310623] PCI: Using configuration type 1 for base access [ 0.313134] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.321141] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.324073] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.329244] cryptd: max_cpu_qlen set to 1000 [ 0.334393] ACPI: Added _OSI(Module Device) [ 0.335018] ACPI: Added _OSI(Processor Device) [ 0.335851] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.337019] ACPI: Added _OSI(Processor Aggregator Device) [ 0.339552] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.344380] ACPI: Interpreter enabled [ 0.345070] ACPI: PM: (supports S0 S3 S4 S5) [ 0.345985] ACPI: Using IOAPIC for interrupt routing [ 0.347211] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.350460] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.359371] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.363091] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.368031] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.375142] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.386479] acpiphp: Slot [2] registered [ 0.390241] acpiphp: Slot [5] registered [ 0.392178] acpiphp: Slot [6] registered [ 0.393162] acpiphp: Slot [7] registered [ 0.395150] acpiphp: Slot [8] registered [ 0.396166] acpiphp: Slot [9] registered [ 0.398156] acpiphp: Slot [10] registered [ 0.399171] acpiphp: Slot [3] registered [ 0.401110] acpiphp: Slot [4] registered [ 0.403109] acpiphp: Slot [11] registered [ 0.404111] acpiphp: Slot [12] registered [ 0.406104] acpiphp: Slot [13] registered [ 0.407107] acpiphp: Slot [14] registered [ 0.409156] acpiphp: Slot [15] registered [ 0.410126] acpiphp: Slot [16] registered [ 0.412105] acpiphp: Slot [17] registered [ 0.413081] acpiphp: Slot [18] registered [ 0.414097] acpiphp: Slot [19] registered [ 0.416118] acpiphp: Slot [20] registered [ 0.417115] acpiphp: Slot [21] registered [ 0.419130] acpiphp: Slot [22] registered [ 0.421111] acpiphp: Slot [23] registered [ 0.422092] acpiphp: Slot [24] registered [ 0.423100] acpiphp: Slot [25] registered [ 0.425107] acpiphp: Slot [26] registered [ 0.426100] acpiphp: Slot [27] registered [ 0.427106] acpiphp: Slot [28] registered [ 0.428088] acpiphp: Slot [29] registered [ 0.429000] acpiphp: Slot [30] registered [ 0.429000] acpiphp: Slot [31] registered [ 0.429000] PCI host bridge to bus 0000:00 [ 0.429000] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.432025] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.434022] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.437047] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.440025] pci_bus 0000:00: root bus resource [mem 0x380000000000-0x38007fffffff window] [ 0.443026] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.445334] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.450207] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.454175] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.463018] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.468491] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.471023] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.474024] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.476019] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.478597] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.481789] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.484044] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.487776] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.490868] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.501019] pci 0000:00:02.0: reg 0x20: [mem 0x380000000000-0x380000003fff 64bit pref] [ 0.506015] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.514102] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.520019] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.527017] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.543024] pci 0000:00:05.0: reg 0x20: [mem 0x380000004000-0x380000007fff 64bit pref] [ 0.553000] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.561019] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.568019] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.585020] pci 0000:00:06.0: reg 0x20: [mem 0x380000008000-0x38000000bfff 64bit pref] [ 0.596094] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.603021] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.609022] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.624024] pci 0000:00:07.0: reg 0x20: [mem 0x38000000c000-0x38000000ffff 64bit pref] [ 0.638267] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.644019] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.650016] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.665027] pci 0000:00:08.0: reg 0x20: [mem 0x380000010000-0x380000013fff 64bit pref] [ 0.673000] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.677000] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.681017] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.696017] pci 0000:00:09.0: reg 0x20: [mem 0x380000014000-0x380000017fff 64bit pref] [ 0.704202] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.711019] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.718015] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.733018] pci 0000:00:0a.0: reg 0x20: [mem 0x380000018000-0x38000001bfff 64bit pref] [ 0.743970] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.747435] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.749390] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.752421] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.755284] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.760140] iommu: Default domain type: Passthrough [ 0.762515] SCSI subsystem initialized [ 0.764146] ACPI: bus type USB registered [ 0.766112] usbcore: registered new interface driver usbfs [ 0.768114] usbcore: registered new interface driver hub [ 0.770086] usbcore: registered new device driver usb [ 0.772187] pps_core: LinuxPPS API ver. 1 registered [ 0.774010] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.777065] PTP clock support registered [ 0.779149] EDAC MC: Ver: 3.0.0 [ 0.781151] PCI: Using ACPI for IRQ routing [ 0.784028] NetLabel: Initializing [ 0.785011] NetLabel: domain hash size = 128 [ 0.787013] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.789096] NetLabel: unlabeled traffic allowed by default [ 0.792044] vgaarb: loaded [ 0.793337] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.795015] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.800183] clocksource: Switched to clocksource kvm-clock [ 0.907418] VFS: Disk quotas dquot_6.6.0 [ 0.908679] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.911117] *** VALIDATE ramfs *** [ 0.912314] *** VALIDATE hugetlbfs *** [ 0.913960] pnp: PnP ACPI init [ 0.916337] pnp: PnP ACPI: found 6 devices [ 0.931440] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.935112] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.937506] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.939974] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.942780] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.945630] pci_bus 0000:00: resource 8 [mem 0x380000000000-0x38007fffffff window] [ 0.948865] NET: Registered protocol family 2 [ 0.951585] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.956861] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.961168] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.968767] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.972668] TCP: Hash tables configured (established 65536 bind 65536) [ 0.975724] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.979628] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.982727] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.986198] NET: Registered protocol family 1 [ 0.990101] RPC: Registered named UNIX socket transport module. [ 0.992561] RPC: Registered udp transport module. [ 0.994305] RPC: Registered tcp transport module. [ 0.996119] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.998358] NET: Registered protocol family 44 [ 0.999922] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 1.002486] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 1.005590] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 1.008322] PCI: CLS 0 bytes, default 64 [ 1.010232] Unpacking initramfs... [ 2.421430] debug: unmapping init [mem 0xffffa066fcc54000-0xffffa066fffbffff] [ 2.425623] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.428045] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.431016] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 2.932613] Initialise system trusted keyrings [ 2.934424] Key type blacklist registered [ 2.937768] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.946785] zbud: loaded [ 2.949764] *** VALIDATE nfs *** [ 2.951047] *** VALIDATE nfs4 *** [ 2.952765] pstore: using deflate compression [ 2.956476] Platform Keyring initialized [ 3.075098] NET: Registered protocol family 38 [ 3.076636] Key type asymmetric registered [ 3.078176] Asymmetric key parser 'x509' registered [ 3.079544] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 3.082508] io scheduler mq-deadline registered [ 3.084141] io scheduler kyber registered [ 3.086080] io scheduler bfq registered [ 3.087775] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 3.090600] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 3.093622] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 3.095748] ACPI: Power Button [PWRF] [ 3.185410] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 3.277363] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 3.465799] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 3.559446] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 3.740920] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 3.769509] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.800020] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.805478] Non-volatile memory driver v1.3 [ 3.807127] Linux agpgart interface v0.103 [ 3.852959] virtio_blk virtio1: [vda] 133640 512-byte logical blocks (68.4 MB/65.3 MiB) [ 3.856827] vda: detected capacity change from 0 to 68423680 [ 3.872934] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.875930] vdb: detected capacity change from 0 to 1073741824 [ 3.892387] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.895398] vdc: detected capacity change from 0 to 2621440000 [ 3.913788] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.916842] vdd: detected capacity change from 0 to 2621440000 [ 3.934236] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.937025] vde: detected capacity change from 0 to 4294967296 [ 3.952286] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.955302] vdf: detected capacity change from 0 to 4294967296 [ 3.962123] libphy: Fixed MDIO Bus: probed [ 3.968210] usbcore: registered new interface driver usbserial_generic [ 3.970621] usbserial: USB Serial support registered for generic [ 3.972668] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.977607] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.980309] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.982994] mousedev: PS/2 mouse device common for all mice [ 3.986097] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.989518] rtc_cmos 00:05: RTC can wake from S4 [ 3.992648] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.995260] rtc_cmos 00:05: registered as rtc0 [ 3.998976] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.999089] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 4.005508] intel_pstate: CPU model not supported [ 4.008323] hid: raw HID events driver (C) Jiri Kosina [ 4.010642] usbcore: registered new interface driver usbhid [ 4.013081] usbhid: USB HID core driver [ 4.014302] drop_monitor: Initializing network drop monitor service [ 4.016693] Initializing XFRM netlink socket [ 4.018939] NET: Registered protocol family 10 [ 4.022137] Segment Routing with IPv6 [ 4.023716] NET: Registered protocol family 17 [ 4.025751] mpls_gso: MPLS GSO support [ 4.032164] RAS: Correctable Errors collector initialized. [ 4.034101] AVX version of gcm_enc/dec engaged. [ 4.035733] AES CTR mode by8 optimization enabled [ 4.114547] sched_clock: Marking stable (4114517603, 0)->(5067912920, -953395317) [ 4.118702] registered taskstats version 1 [ 4.120750] Loading compiled-in X.509 certificates [ 4.122947] zswap: loaded using pool lzo/zbud [ 4.147702] Key type big_key registered [ 4.161223] Key type encrypted registered [ 4.162766] ima: No TPM chip found, activating TPM-bypass! [ 4.164917] ima: Allocated hash algorithm: sha1 [ 4.166696] ima: No architecture policies found [ 4.168518] evm: Initialising EVM extended attributes: [ 4.170464] evm: security.selinux [ 4.171769] evm: security.ima [ 4.172887] evm: security.capability [ 4.174296] evm: HMAC attrs: 0x1 [ 4.176774] rtc_cmos 00:05: setting system clock to 2025-11-14 20:42:16 UTC (1763152936) [ 4.183547] debug: unmapping init [mem 0xffffffffada03000-0xffffffffadbfffff] [ 4.186746] debug: unmapping init [mem 0xffffffffac782000-0xffffffffaca58fff] [ 4.207093] Write protecting the kernel read-only data: 28672k [ 4.211896] debug: unmapping init [mem 0xffffffffaae03000-0xffffffffaaffffff] [ 4.214910] debug: unmapping init [mem 0xffffffffab714000-0xffffffffab7fffff] [ 4.261815] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 4.269960] systemd[1]: Detected virtualization kvm. [ 4.271952] systemd[1]: Detected architecture x86-64. [ 4.273770] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 4.308760] systemd[1]: No hostname configured. [ 4.310635] systemd[1]: Set hostname to . [ 4.312518] random: systemd: uninitialized urandom read (16 bytes read) [ 4.314904] systemd[1]: Initializing machine ID from random generator. [ 4.348566] random: ln: uninitialized urandom read (6 bytes read) [ 4.467135] random: systemd: uninitialized urandom read (16 bytes read) [ 4.469680] systemd[1]: Reached target Slices. [ OK ] Reached target Slices. [ 4.473976] systemd[1]: Reached target Initrd Root Device. [ OK ] Reached target Initrd Root Device. [ 4.479625] systemd[1]: Listening on Journal Socket. [ OK ] Listening on Journal Socket. [ OK ] Listening on Journal Socket (/dev/log). [ OK ] Started Memstrack Anylazing Service. [ OK ] Reached target Swap. [ OK ] Reached target Local File Systems. Starting Create Volatile Files and Directories... [ OK ] Listening on udev Control Socket. Starting Setup Virtual Console... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Paths. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Reached target Timers. [ OK ] Reached target Local Encrypted Volumes. Starting Journal Service... [ OK ] Listening on udev Kernel Socket. [ OK ] Reached target Sockets. Starting 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. [ OK ] Started Apply Kernel Variables. 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... [ 5.106708] device-mapper: uevent: version 1.0.3 [ 5.109907] device-mapper: ioctl: 4.46.0-ioctl (2022-02-22) initialised: dm-devel@redhat.com [ OK ] Started dracut pre-udev hook. [ 5.370114] random: fast init done 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.871908] virtio_net virtio0 ens2: renamed from eth0 [ 5.897608] scsi host0: ata_piix [ 5.911845] scsi host1: ata_piix [ 5.915497] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 5.920747] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 10.273379] dracut-initqueue[592]: RTNETLINK answers: File exists [ 10.680847] random: crng init done [ 10.682243] 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. [ 11.071946] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped target Timers. [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Slices. [ OK ] Stopped target System Initialization. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped target Swap. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. [ OK ] Stopped target Local Encrypted Volumes. Stopping udev Kernel Device Manager... [ OK ] Stopped target Paths. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped target Sockets. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Closed udev Control Socket. [ OK ] Closed udev Kernel Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 12.166990] printk: systemd: 26 output lines suppressed due to ratelimiting [ 12.411660] SELinux: Disabled at runtime. [ 12.469548] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 12.478628] systemd[1]: Detected virtualization kvm. [ 12.480453] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 12.969595] systemd[1]: initrd-switch-root.service: Succeeded. [ 12.974177] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 12.980560] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 12.987355] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 12.991984] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 13.000794] systemd[1]: Starting Journal Service... Starting Journal Service... [ 13.017652] systemd[1]: Listening on Process Core Dump Socket. [ OK ] Listening on Process Core Dump Socket. [ OK ] Stopped target Switch Root. [ OK ] Listening on udev Kernel Socket. Mounting POSIX Message Queue File System... [ OK ] Reached target rpc_pipefs.target. [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Listening on udev Control Socket. Mounting Huge Pages File System... [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Listening on RPCbind Server Activation Socket. Starting Remount Root and Kernel File Systems... Starting Create list of required st…ce nodes for the current kernel... [ OK ] Created slice system-getty.slice. Starting Apply Kernel Variables... [ OK ] Reached target RPC Port Mapper. Mounting Kernel Debug File System... Starting udev Coldplug all Devices... [ OK ] Created slice User and Session Slice. [ OK ] Reached target Slices. [ OK ] Created slice system-serial\x2dgetty.slice. [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Stopped target Initrd Root File System. Activating swap /dev/disk/by-label/SWAP... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. [ OK ] Stopped target Initrd File Systems. [ OK ] Started Journal Service. [ 13.184085] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS [ OK ] Mounted POSIX Message Queue File System. [ OK ] Mounted Huge Pages File System. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Apply Kernel Variables. [ OK ] Mounted Kernel Debug File System. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Reached target Swap. Starting Configure read-only root support... Starting Create Static Device Nodes in /dev... Starting Flush Journal to Persistent Storage... [ OK ] Started 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.478208] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 13.722333] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 13.755412] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 13.854590] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 13.874630] EDAC sbridge: Ver: 1.1.2 [ 15.292559] Key type dns_resolver registered [ 15.597791] NFS: Registering the id_resolver key type [ 15.599886] Key type id_resolver registered [ 15.601149] Key type id_legacy registered [ OK ] Started Configure read-only root support. [ OK ] Reached target Local File Systems. Starting Create Volatile Files and Directories... Starting Mark the need to relabel after reboot... Starting Rebuild Dynamic Linker Cache... Starting Load/Save Random Seed... [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Load/Save Random Seed. [ OK ] Started Create Volatile Files and Directories. Starting Update UTMP about System Boot/Shutdown... Starting RPC Bind... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Started dnf makecache --timer. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Reached target Basic System. [ OK ] Started D-Bus System Message Bus. Starting Restore /run/initramfs on shutdown... Starting Network Manager... Starting Login Service... [ OK ] Reached target sshd-keygen.target. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Started irqbalance daemon. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ 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 OpenSSH server daemon... Starting GSSAPI Proxy Daemon... Starting Hostname Service... [ OK ] Started OpenSSH server daemon. [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... [ OK ] Started Permit User Sessions. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Getty on tty1. [ OK ] Started Serial Getty on ttyS1. [ OK ] Reached target Login Prompts. [ OK ] Started Command Scheduler. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting 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 oleg110-server login: [ 41.269414] libcfs: loading out-of-tree module taints kernel. [ 41.283659] Key type ._llcrypt registered [ 41.285268] Key type .llcrypt registered [ 41.338307] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_hostid [ 49.461108] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing load_modules_local [ 50.213213] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 50.220570] alg: No test for adler32 (adler32-zlib) [ 51.280627] Lustre: Lustre: Build Version: 2.16.61_2_g297829f [ 51.629036] LNet: Added LNI 192.168.201.110@tcp [8/256/0/180] [ 53.263224] Key type lgssc registered [ 54.010938] Lustre: Echo OBD driver; http://www.lustre.org/ [ 66.606524] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 67.990989] LDISKFS-fs (vdc): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 75.107156] LDISKFS-fs (vdd): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 81.277172] LDISKFS-fs (vde): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 85.843583] LDISKFS-fs (vdf): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 95.006607] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing load_modules_local [ 97.562847] hrtimer: interrupt took 3835342 ns [ 103.756289] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 103.794275] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 103.812171] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 104.978440] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 105.018532] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 105.091326] Lustre: lustre-MDT0000: new disk, initializing [ 105.175110] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 105.189912] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 107.528909] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 116.556534] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 116.615852] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 116.678223] Lustre: 6489:0:(mgs_llog.c:1346:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 116.729863] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 116.732881] Lustre: Skipped 1 previous similar message [ 116.832883] Lustre: lustre-MDT0001: new disk, initializing [ 116.937943] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 116.969178] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 116.979825] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 119.889276] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 123.484757] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 129.449048] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 129.504423] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 129.680234] Lustre: lustre-OST0000: new disk, initializing [ 129.684665] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 129.734549] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 131.139594] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 131.145198] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 131.199513] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 133.182859] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 142.987217] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 143.042113] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 143.127745] Lustre: lustre-OST0001: new disk, initializing [ 143.135708] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 143.193328] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 147.093522] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 151.072747] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 151.079509] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 151.106608] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 155.545851] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 165.143560] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 173.677949] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing check_logdir /tmp/testlogs/ [ 176.606963] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing yml_node [ 179.186142] Lustre: DEBUG MARKER: Client: 2.16.61.2 [ 181.049285] Lustre: DEBUG MARKER: MDS: 2.16.61.2 [ 182.746985] Lustre: DEBUG MARKER: OSS: 2.16.61.2 [ 184.025221] Lustre: DEBUG MARKER: -----============= acceptance-small: replay-dual ============----- Fri Nov 14 15:45:15 EST 2025 [ 196.460197] Lustre: DEBUG MARKER: excepting tests: 14b 21b [ 197.466242] Lustre: DEBUG MARKER: skipping tests SLOW=no: 21b [ 198.464878] Lustre: DEBUG MARKER: === replay-dual: start setup 15:45:30 (1763153130) === [ 200.997678] Lustre: DEBUG MARKER: oleg110-client.virtnet: executing check_config_client /mnt/lustre [ 214.744412] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 217.183152] Lustre: 13212:0:(mgs_llog.c:1346:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 219.554365] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 223.472916] Lustre: DEBUG MARKER: === replay-dual: finish setup 15:45:55 (1763153155) === [ 224.631635] Lustre: DEBUG MARKER: == replay-dual test 0a: expired recovery with lost client ========================================================== 15:45:56 (1763153156) [ 229.846481] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 232.970735] Lustre: Failing over lustre-MDT0000 [ 233.212491] LustreError: 14084:0:(obd_class.h:479:obd_check_dev()) Device 28 not setup [ 233.287074] Lustre: server umount lustre-MDT0000 complete [ 234.718045] LustreError: 13506:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.201.10@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 234.733453] LustreError: 13506:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 2 previous similar messages [ 234.983666] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 234.991814] 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 [ 238.050318] LustreError: 6499: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. [ 238.055282] Lustre: lustre-MDT0000-lwp-OST0001: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 238.082740] LustreError: 6499:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 2 previous similar messages [ 238.103748] Lustre: Skipped 1 previous similar message [ 239.816259] LustreError: 6494:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.201.10@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 239.829537] LustreError: 6494:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 2 previous similar messages [ 243.172695] LustreError: 6499: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. [ 243.180545] LustreError: 6499:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 3 previous similar messages [ 248.296368] LustreError: 6499: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. [ 248.314707] LustreError: 6499:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 5 previous similar messages [ 251.495635] LDISKFS-fs (dm-0): 10 truncates cleaned up [ 251.497796] LDISKFS-fs (dm-0): recovery complete [ 251.508093] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 251.533887] LustreError: MGC192.168.201.110@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 251.729731] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 254.281856] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 255.247283] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 257.007370] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 359.001115] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 359.009085] Lustre: 14735:0:(genops.c:1618:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 26fcc11f-e2ac-45f6-9a2c-1cdf2824d5a9@192.168.201.10@tcp [ 359.015558] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 359.036105] Lustre: lustre-MDT0000-osp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 359.038544] Lustre: Skipped 2 previous similar messages [ 359.044812] Lustre: 14735:0:(ldlm_lib.c:2929:target_recovery_thread()) too long recovery - read logs [ 359.049051] LustreError: dumping log to /tmp/lustre-log.1763153291.14735 [ 359.163323] Lustre: lustre-MDT0000: Recovery over after 1:44, of 3 clients 2 recovered and 1 was evicted. [ 359.232868] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:28 to 0x280000401:65) [ 359.233064] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:28 to 0x2c0000401:65) [ 381.114570] Lustre: DEBUG MARKER: == replay-dual test 0b: lost client during waiting for next transno ========================================================== 15:48:32 (1763153312) [ 388.114552] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 389.788318] Lustre: Failing over lustre-MDT0000 [ 389.939276] LustreError: 15808:0:(obd_class.h:479:obd_check_dev()) Device 22 not setup [ 389.941877] LustreError: 15808:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 389.998663] Lustre: server umount lustre-MDT0000 complete [ 390.115925] Lustre: lustre-MDT0000-lwp-MDT0001: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 390.116287] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 390.120201] LustreError: 7793: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. [ 390.120215] LustreError: 7793:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 4 previous similar messages [ 390.122087] Lustre: Skipped 2 previous similar messages [ 405.970435] Lustre: 3634:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763153322/real 1763153322] req@ffffa0674712b480 x1848799902474624/t0(0) o400->MGC192.168.201.110@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1763153338 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 405.987768] LustreError: MGC192.168.201.110@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 407.756644] LustreError: 6495:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.201.10@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 407.769880] LustreError: 6495:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 22 previous similar messages [ 409.447238] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 409.448904] LDISKFS-fs (dm-0): recovery complete [ 409.455094] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 416.224824] LustreError: 3630:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffffa06649154380 x1848799902483328/t0(0) o250->MGC192.168.201.110@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 [ 416.426303] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 417.994118] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 419.015787] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 421.876114] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 430.992363] Lustre: lustre-MDT0000: Denying connection for new client fc015d71-c2ff-431f-8a0c-eef82c7bc048 (at 192.168.201.10@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:56 [ 436.423124] Lustre: lustre-MDT0000: Denying connection for new client fc015d71-c2ff-431f-8a0c-eef82c7bc048 (at 192.168.201.10@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:50 [ 441.545366] Lustre: lustre-MDT0000: Denying connection for new client fc015d71-c2ff-431f-8a0c-eef82c7bc048 (at 192.168.201.10@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:45 [ 446.664929] Lustre: lustre-MDT0000: Denying connection for new client fc015d71-c2ff-431f-8a0c-eef82c7bc048 (at 192.168.201.10@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:40 [ 451.785458] Lustre: lustre-MDT0000: Denying connection for new client fc015d71-c2ff-431f-8a0c-eef82c7bc048 (at 192.168.201.10@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:35 [ 456.909731] Lustre: lustre-MDT0001: haven't heard from client 26fcc11f-e2ac-45f6-9a2c-1cdf2824d5a9 (at 192.168.201.10@tcp) in 102 seconds. I think it's dead, and I am evicting it. exp ffffa06648c5c800, cur 1763153389 deadline 1763153387 last 1763153287 [ 462.030217] Lustre: lustre-MDT0000: Denying connection for new client fc015d71-c2ff-431f-8a0c-eef82c7bc048 (at 192.168.201.10@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:24 [ 462.046544] Lustre: Skipped 1 previous similar message [ 482.526204] Lustre: lustre-MDT0000: Denying connection for new client fc015d71-c2ff-431f-8a0c-eef82c7bc048 (at 192.168.201.10@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:04 [ 482.534028] Lustre: Skipped 3 previous similar messages [ 487.001430] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 487.004134] Lustre: 16460:0:(genops.c:1618:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 4c181a68-c86e-4454-88f7-0454befd21cc@ [ 487.016275] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 518.349658] Lustre: lustre-MDT0000: Denying connection for new client fc015d71-c2ff-431f-8a0c-eef82c7bc048 (at 192.168.201.10@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 1 evicted) to recover in 1:09 [ 518.361096] Lustre: Skipped 6 previous similar messages [ 519.143220] Lustre: lustre-MDT0001: haven't heard from client 2d9b308d-fc24-48b3-8eac-f5097f215d37 (at 192.168.201.10@tcp) in 101 seconds. I think it's dead, and I am evicting it. exp ffffa06642ca2800, cur 1763153451 deadline 1763153450 last 1763153350 [ 584.909786] Lustre: lustre-MDT0000: Denying connection for new client fc015d71-c2ff-431f-8a0c-eef82c7bc048 (at 192.168.201.10@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 1 evicted) to recover in 0:03 [ 584.921434] Lustre: Skipped 12 previous similar messages [ 588.000185] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 588.002868] Lustre: 16460:0:(genops.c:1618:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 2d9b308d-fc24-48b3-8eac-f5097f215d37@192.168.201.10@tcp [ 588.009896] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 588.016331] Lustre: 16460:0:(ldlm_lib.c:2067:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 588.029791] Lustre: 16460:0:(ldlm_lib.c:2929:target_recovery_thread()) too long recovery - read logs [ 588.030629] Lustre: lustre-MDT0000-osp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 588.036333] LustreError: dumping log to /tmp/lustre-log.1763153520.16460 [ 588.039576] Lustre: Skipped 2 previous similar messages [ 588.114108] Lustre: lustre-MDT0000: Recovery over after 2:51, of 3 clients 1 recovered and 2 were evicted. [ 588.137853] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:28 to 0x2c0000401:97) [ 588.137864] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:28 to 0x280000401:97) [ 594.360836] Lustre: DEBUG MARKER: == replay-dual test 1: |X| simple create ================= 15:52:06 (1763153526) [ 599.395796] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 600.711045] Lustre: Failing over lustre-MDT0000 [ 600.818294] Lustre: lustre-MDT0000: Not available for connect from 192.168.201.10@tcp (stopping) [ 600.855102] LustreError: 17533:0:(obd_class.h:479:obd_check_dev()) Device 22 not setup [ 600.857941] LustreError: 17533:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 600.903612] LustreError: 17533:0:(ldlm_resource.c:981:ldlm_resource_complain()) MGS: namespace resource [0x736d61726170:0x3:0x0].0x0 (ffffa0675a34ec00) refcount nonzero (2) after lock cleanup; forcing cleanup. [ 600.998674] Lustre: server umount lustre-MDT0000 complete [ 601.064184] 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 [ 601.068844] LustreError: 6494: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. [ 601.072465] Lustre: Skipped 3 previous similar messages [ 601.085866] LustreError: 6494:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 9 previous similar messages [ 617.444335] Lustre: 3634:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763153533/real 1763153533] req@ffffa06648fdb480 x1848799902562432/t0(0) o400->MGC192.168.201.110@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1763153549 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 617.463834] LustreError: MGC192.168.201.110@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 620.550762] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 620.554916] LDISKFS-fs (dm-0): recovery complete [ 620.563402] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 627.702782] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xad36bedce0daa7cc [ 627.714633] Lustre: MGC192.168.201.110@tcp: Connection restored to 0@lo (at 0@lo) [ 627.984907] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 628.038190] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 629.234779] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 631.089948] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 633.447925] Lustre: lustre-MDT0000: Recovery over after 0:04, of 3 clients 3 recovered and 0 were evicted. [ 633.488388] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:129) [ 633.489267] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:129) [ 636.903961] Lustre: DEBUG MARKER: oleg110-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 638.127632] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 643.932389] Lustre: DEBUG MARKER: == replay-dual test 2: |X| mkdir adir ==================== 15:52:55 (1763153575) [ 648.425882] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 649.557466] Lustre: Failing over lustre-MDT0000 [ 649.695788] LustreError: 19356:0:(obd_class.h:479:obd_check_dev()) Device 22 not setup [ 649.698171] LustreError: 19356:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 649.763932] Lustre: server umount lustre-MDT0000 complete [ 653.796352] 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 [ 653.820080] Lustre: Skipped 5 previous similar messages [ 665.293176] LustreError: 6494:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.201.10@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 665.308156] LustreError: 6494:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 56 previous similar messages [ 667.462184] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 667.467997] LDISKFS-fs (dm-0): recovery complete [ 667.476168] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 667.598793] LustreError: MGC192.168.201.110@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 667.812137] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 667.848700] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 670.344415] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 670.929472] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 673.272705] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 673.280158] Lustre: Skipped 4 previous similar messages [ 673.326375] Lustre: lustre-MDT0000: Recovery over after 0:03, of 3 clients 3 recovered and 0 were evicted. [ 673.361710] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:161) [ 673.362599] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:161) [ 677.595257] Lustre: DEBUG MARKER: oleg110-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 679.070480] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 687.218891] Lustre: DEBUG MARKER: == replay-dual test 3: |X| mkdir adir, mkdir adir/bdir === 15:53:38 (1763153618) [ 693.903830] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 695.761839] Lustre: Failing over lustre-MDT0000 [ 695.942797] LustreError: 21183:0:(obd_class.h:479:obd_check_dev()) Device 22 not setup [ 695.949436] LustreError: 21183:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 696.098332] Lustre: server umount lustre-MDT0000 complete [ 698.849473] 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 [ 698.867588] Lustre: Skipped 3 previous similar messages [ 715.231830] Lustre: 3631:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763153631/real 1763153631] req@ffffa0677e6e7b80 x1848799902626432/t0(0) o400->MGC192.168.201.110@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1763153647 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 715.246715] LustreError: MGC192.168.201.110@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 717.364268] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 717.375254] LDISKFS-fs (dm-0): recovery complete [ 717.390270] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 725.484425] LustreError: 3630:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffffa0676b060e00 x1848799902635648/t0(0) o250->MGC192.168.201.110@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 [ 725.896048] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 726.735985] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 729.154748] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 731.117991] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 731.121017] Lustre: Skipped 3 previous similar messages [ 731.190719] Lustre: lustre-MDT0000: Recovery over after 0:05, of 3 clients 3 recovered and 0 were evicted. [ 731.227050] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:193) [ 731.227779] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:193) [ 734.878521] Lustre: DEBUG MARKER: oleg110-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 736.262748] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 742.966260] Lustre: DEBUG MARKER: == replay-dual test 4: |X| mkdir adir (-EEXIST), mkdir adir/bdir ========================================================== 15:54:34 (1763153674) [ 748.483437] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 749.928983] Lustre: Failing over lustre-MDT0000 [ 750.094625] LustreError: 23009:0:(obd_class.h:479:obd_check_dev()) Device 22 not setup [ 750.097818] LustreError: 23009:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 750.157431] Lustre: server umount lustre-MDT0000 complete [ 751.588897] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 751.591288] Lustre: lustre-MDT0000-lwp-MDT0001: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 751.616353] Lustre: Skipped 2 previous similar messages [ 766.944223] Lustre: 3633:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763153683/real 1763153683] req@ffffa0664910ea00 x1848799902663936/t0(0) o400->MGC192.168.201.110@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1763153699 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 766.968865] LustreError: MGC192.168.201.110@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 769.155750] LDISKFS-fs (dm-0): 4 truncates cleaned up [ 769.158387] LDISKFS-fs (dm-0): recovery complete [ 769.168770] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 777.442048] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 777.451399] Lustre: Skipped 1 previous similar message [ 777.494491] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 777.933147] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 780.628158] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 782.829281] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 782.841824] Lustre: Skipped 3 previous similar messages [ 782.938108] Lustre: lustre-MDT0000: Recovery over after 0:05, of 3 clients 3 recovered and 0 were evicted. [ 782.980708] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:225) [ 782.986810] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:225) [ 786.582245] Lustre: DEBUG MARKER: oleg110-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 787.790234] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 794.051574] Lustre: DEBUG MARKER: == replay-dual test 5: open, unlink |X| close ============ 15:55:25 (1763153725) [ 798.877115] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 800.177019] Lustre: Failing over lustre-MDT0000 [ 800.314140] LustreError: 24831:0:(obd_class.h:479:obd_check_dev()) Device 22 not setup [ 800.333276] LustreError: 24831:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 800.389541] Lustre: server umount lustre-MDT0000 complete [ 803.299858] 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 [ 803.301116] LustreError: 16837: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. [ 803.305650] Lustre: Skipped 4 previous similar messages [ 803.313488] LustreError: 16837:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 82 previous similar messages [ 819.428781] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 819.430804] LDISKFS-fs (dm-0): recovery complete [ 819.445065] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 819.554607] LustreError: MGC192.168.201.110@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 819.809055] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 819.944660] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 822.681532] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 824.921219] Lustre: lustre-MDT0000: Recovery over after 0:05, of 3 clients 3 recovered and 0 were evicted. [ 824.953762] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:257) [ 824.956736] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:257) [ 828.014828] Lustre: DEBUG MARKER: oleg110-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 828.972769] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 834.572693] Lustre: DEBUG MARKER: == replay-dual test 6: open1, open2, unlink |X| close1 [fail mds1] close2 ========================================================== 15:56:06 (1763153766) [ 839.261651] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 840.387564] Lustre: Failing over lustre-MDT0000 [ 840.416748] Lustre: lustre-MDT0000: Not available for connect from 192.168.201.10@tcp (stopping) [ 840.422645] Lustre: Skipped 2 previous similar messages [ 840.485138] LustreError: 26655:0:(obd_class.h:479:obd_check_dev()) Device 22 not setup [ 840.487371] LustreError: 26655:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 840.550237] Lustre: server umount lustre-MDT0000 complete [ 840.673044] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 858.045855] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 858.047936] LDISKFS-fs (dm-0): recovery complete [ 858.065209] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 858.139189] LustreError: MGC192.168.201.110@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 858.441524] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 860.882964] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 861.046379] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 863.721307] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 863.739018] Lustre: Skipped 7 previous similar messages [ 863.815790] Lustre: lustre-MDT0000: Recovery over after 0:03, of 3 clients 3 recovered and 0 were evicted. [ 863.845735] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:289) [ 863.849624] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:289) [ 866.577803] Lustre: DEBUG MARKER: oleg110-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 867.876508] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 874.588381] Lustre: DEBUG MARKER: == replay-dual test 8: replay of resent request ========== 15:56:46 (1763153806) [ 880.047861] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 880.718401] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 880.721782] LustreError: 6496:0:(ldlm_lib.c:3324:target_send_reply_msg()) @@@ dropping reply req@ffffa0676b284380 x1848799894170880/t38654705670(0) o36->fc015d71-c2ff-431f-8a0c-eef82c7bc048@192.168.201.10@tcp:59/0 lens 512/448 e 0 to 0 dl 1763153824 ref 1 fl Interpret:/200/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 897.239336] Lustre: lustre-MDT0000: Client fc015d71-c2ff-431f-8a0c-eef82c7bc048 (at 192.168.201.10@tcp) reconnecting [ 897.253931] Lustre: 16837:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffffa0677eb04380 x1848799894170880/t38654705670(0) o36->fc015d71-c2ff-431f-8a0c-eef82c7bc048@192.168.201.10@tcp:75/0 lens 512/2880 e 0 to 0 dl 1763153840 ref 1 fl Interpret:/202/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 899.688617] Lustre: Failing over lustre-MDT0000 [ 899.865253] Lustre: server umount lustre-MDT0000 complete [ 904.673548] Lustre: lustre-MDT0000-lwp-MDT0001: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 904.678921] Lustre: Skipped 6 previous similar messages [ 904.683402] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 919.462800] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 919.465406] LDISKFS-fs (dm-0): recovery complete [ 919.476303] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 919.829284] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 919.835477] Lustre: Skipped 2 previous similar messages [ 919.882777] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 923.710256] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 925.261978] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:321) [ 925.261978] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:321) [ 930.215700] Lustre: DEBUG MARKER: oleg110-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 931.859354] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 939.080960] Lustre: DEBUG MARKER: == replay-dual test 9: resending a replayed create ======= 15:57:50 (1763153870) [ 946.858615] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 949.766827] Lustre: Failing over lustre-MDT0000 [ 949.926802] LustreError: 30468:0:(obd_class.h:479:obd_check_dev()) Device 22 not setup [ 949.929942] LustreError: 30468:0:(obd_class.h:479:obd_check_dev()) Skipped 15 previous similar messages [ 950.019140] Lustre: server umount lustre-MDT0000 complete [ 950.757566] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 967.136207] Lustre: 3631:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763153883/real 1763153883] req@ffffa06747105180 x1848799902793088/t0(0) o400->MGC192.168.201.110@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1763153899 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 967.150662] LustreError: MGC192.168.201.110@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 967.158040] LustreError: Skipped 1 previous similar message [ 968.935902] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 968.938584] LDISKFS-fs (dm-0): recovery complete [ 968.945459] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 977.376383] LustreError: 3630:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffffa06776ff1f80 x1848799902801664/t0(0) o250->MGC192.168.201.110@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 [ 977.757015] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 979.618283] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 979.621278] Lustre: Skipped 1 previous similar message [ 980.750920] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 983.053809] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 983.060364] LustreError: 31121:0:(ldlm_lib.c:3324:target_send_reply_msg()) @@@ dropping reply req@ffffa0674712aa00 x1848799894187648/t42949672962(42949672962) o36->fc015d71-c2ff-431f-8a0c-eef82c7bc048@192.168.201.10@tcp:157/0 lens 528/448 e 0 to 0 dl 1763153922 ref 1 fl Complete:/204/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 996.126763] Lustre: lustre-MDT0000: Client fc015d71-c2ff-431f-8a0c-eef82c7bc048 (at 192.168.201.10@tcp) reconnected, waiting for 3 clients in recovery for 1:27 [ 996.222575] Lustre: lustre-MDT0000-osp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 996.225482] Lustre: Skipped 10 previous similar messages [ 996.228593] Lustre: lustre-MDT0000: Recovery over after 0:17, of 3 clients 3 recovered and 0 were evicted. [ 996.241832] Lustre: Skipped 1 previous similar message [ 996.266729] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:353) [ 996.271070] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:353) [ 999.235455] Lustre: DEBUG MARKER: oleg110-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1000.727032] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1007.746504] Lustre: DEBUG MARKER: == replay-dual test 10: resending a replayed unlink ====== 15:58:59 (1763153939) [ 1012.995124] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1015.038141] Lustre: Failing over lustre-MDT0000 [ 1015.271437] Lustre: server umount lustre-MDT0000 complete [ 1016.800362] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1035.241295] Lustre: 3632:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763153951/real 1763153951] req@ffffa0677ea47800 x1848799902831488/t0(0) o400->MGC192.168.201.110@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1763153967 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1036.305229] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1036.307340] LDISKFS-fs (dm-0): recovery complete [ 1036.316592] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1045.474381] LustreError: 3630:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffffa06747bed880 x1848799902839936/t0(0) o250->MGC192.168.201.110@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 [ 1045.818726] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1049.228805] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 1051.146391] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 1051.153648] LustreError: 33068:0:(ldlm_lib.c:3324:target_send_reply_msg()) @@@ dropping reply req@ffffa0676b1fdc00 x1848799894206592/t47244640260(47244640260) o36->fc015d71-c2ff-431f-8a0c-eef82c7bc048@192.168.201.10@tcp:225/0 lens 528/448 e 0 to 0 dl 1763153990 ref 1 fl Complete:/204/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 1062.639140] Lustre: lustre-MDT0000: Client fc015d71-c2ff-431f-8a0c-eef82c7bc048 (at 192.168.201.10@tcp) reconnected, waiting for 3 clients in recovery for 1:29 [ 1062.719619] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:385) [ 1062.720143] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:385) [ 1065.996496] Lustre: DEBUG MARKER: oleg110-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1067.001485] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1073.813243] Lustre: DEBUG MARKER: == replay-dual test 11: both clients timeout during replay ========================================================== 16:00:05 (1763154005) [ 1079.820061] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1082.213655] Lustre: Failing over lustre-MDT0000 [ 1082.324678] LustreError: 34360:0:(obd_class.h:479:obd_check_dev()) Device 22 not setup [ 1082.327891] LustreError: 34360:0:(obd_class.h:479:obd_check_dev()) Skipped 15 previous similar messages [ 1082.437587] Lustre: server umount lustre-MDT0000 complete [ 1083.115066] LustreError: 13506:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.201.10@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1083.124983] LustreError: 13506:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 144 previous similar messages [ 1083.360179] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1083.363916] 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 [ 1083.371195] Lustre: Skipped 9 previous similar messages [ 1101.740720] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1101.742891] LDISKFS-fs (dm-0): recovery complete [ 1101.750874] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1101.837696] LustreError: MGC192.168.201.110@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1101.842897] LustreError: Skipped 1 previous similar message [ 1105.266720] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 1107.474624] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 1107.476903] LustreError: 35013:0:(ldlm_lib.c:3324:target_send_reply_msg()) @@@ dropping reply req@ffffa0676b0ec700 x1848799894225792/t51539607554(51539607554) o36->fc015d71-c2ff-431f-8a0c-eef82c7bc048@192.168.201.10@tcp:281/0 lens 528/448 e 0 to 0 dl 1763154046 ref 1 fl Complete:/204/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 1109.967496] Lustre: DEBUG MARKER: oleg110-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1119.894600] Lustre: lustre-MDT0000: Client fc015d71-c2ff-431f-8a0c-eef82c7bc048 (at 192.168.201.10@tcp) reconnected, waiting for 3 clients in recovery for 1:28 [ 1120.049963] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:417) [ 1120.050574] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:417) [ 1122.556650] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 10 sec [ 1129.148032] Lustre: DEBUG MARKER: == replay-dual test 12: open resend timeout ============== 16:01:00 (1763154060) [ 1136.516632] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1139.555224] Lustre: Failing over lustre-MDT0000 [ 1139.879841] Lustre: server umount lustre-MDT0000 complete [ 1158.752268] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1158.756243] LDISKFS-fs (dm-0): recovery complete [ 1158.769047] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1159.880769] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 1159.886131] Lustre: Skipped 2 previous similar messages [ 1162.521309] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 1164.363421] Lustre: *** cfs_fail_loc=302, val=2147483648*** [ 1179.872880] Lustre: lustre-MDT0000: Client fc015d71-c2ff-431f-8a0c-eef82c7bc048 (at 192.168.201.10@tcp) reconnected, waiting for 3 clients in recovery for 1:25 [ 1179.937575] Lustre: lustre-MDT0000: Recovery over after 0:20, of 3 clients 3 recovered and 0 were evicted. [ 1179.950440] Lustre: Skipped 2 previous similar messages [ 1179.975728] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:449) [ 1179.977518] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:449) [ 1185.376545] Lustre: DEBUG MARKER: == replay-dual test 13: close resend timeout ============= 16:01:56 (1763154116) [ 1191.173080] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1193.086429] Lustre: Failing over lustre-MDT0000 [ 1193.276724] Lustre: server umount lustre-MDT0000 complete [ 1211.360102] Lustre: 3632:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763154127/real 1763154127] req@ffffa066490ab800 x1848799902937344/t0(0) o400->MGC192.168.201.110@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1763154143 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1212.820635] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1212.822445] LDISKFS-fs (dm-0): recovery complete [ 1212.830503] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1221.831526] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1221.834183] Lustre: Skipped 4 previous similar messages [ 1221.927413] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1221.943947] Lustre: Skipped 2 previous similar messages [ 1225.041970] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 1227.373685] Lustre: *** cfs_fail_loc=115, val=2147483648*** [ 1242.851657] Lustre: lustre-MDT0000: Client fc015d71-c2ff-431f-8a0c-eef82c7bc048 (at 192.168.201.10@tcp) reconnected, waiting for 3 clients in recovery for 1:25 [ 1242.948420] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:481) [ 1242.951923] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:481) [ 1247.783883] Lustre: DEBUG MARKER: SKIP: replay-dual test_14b skipping ALWAYS excluded test 14b [ 1248.949860] Lustre: DEBUG MARKER: == replay-dual test 15a: timeout waiting for lost client during replay, 1 client completes ========================================================== 16:03:00 (1763154180) [ 1254.570810] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1257.290570] Lustre: Failing over lustre-MDT0000 [ 1257.547718] Lustre: server umount lustre-MDT0000 complete [ 1277.013733] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1277.016253] LDISKFS-fs (dm-0): recovery complete [ 1277.021894] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1280.336754] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 1282.549962] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1282.556304] Lustre: Skipped 16 previous similar messages [ 1348.000096] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 1348.004705] Lustre: 40557:0:(genops.c:1618:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 5410d90d-2593-4ef2-a326-32ca15943ce2@ [ 1348.016097] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 1348.604551] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:494 to 0x280000401:513) [ 1348.605115] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:495 to 0x2c0000401:513) [ 1351.337870] Lustre: DEBUG MARKER: oleg110-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1352.539308] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1360.481439] Lustre: DEBUG MARKER: == replay-dual test 15c: remove multiple OST orphans ===== 16:04:51 (1763154291) [ 1366.827637] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1474.677482] Lustre: Failing over lustre-MDT0000 [ 1475.102288] LustreError: 41807:0:(obd_class.h:479:obd_check_dev()) Device 22 not setup [ 1475.122782] LustreError: 41807:0:(obd_class.h:479:obd_check_dev()) Skipped 31 previous similar messages [ 1475.225766] Lustre: server umount lustre-MDT0000 complete [ 1476.581768] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1476.600349] LustreError: Skipped 1 previous similar message [ 1476.611409] 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 [ 1476.647787] Lustre: Skipped 15 previous similar messages [ 1493.471118] Lustre: 3633:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763154409/real 1763154409] req@ffffa06760640a80 x1848799903079424/t0(0) o400->MGC192.168.201.110@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1763154425 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1493.519657] LustreError: MGC192.168.201.110@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1493.531704] LustreError: Skipped 3 previous similar messages [ 1498.620481] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1498.622567] LDISKFS-fs (dm-0): recovery complete [ 1498.640374] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1503.000059] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1503.002495] Lustre: Skipped 1 previous similar message [ 1503.965797] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 1503.982416] Lustre: Skipped 2 previous similar messages [ 1506.963883] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 1573.000591] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 1573.003256] Lustre: 42459:0:(genops.c:1618:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 28c8e258-d0d4-4e34-81b3-a0ac83a8a35c@ [ 1573.024728] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 1573.118312] Lustre: lustre-MDT0000: Recovery over after 1:10, of 3 clients 2 recovered and 1 was evicted. [ 1573.129247] Lustre: Skipped 2 previous similar messages [ 1573.176930] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:495 to 0x2c0000401:1537) [ 1573.177164] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:494 to 0x280000401:1537) [ 1577.131571] Lustre: DEBUG MARKER: oleg110-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1578.574641] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1585.788332] Lustre: DEBUG MARKER: == replay-dual test 16: fail MDS during recovery (3571) == 16:08:37 (1763154517) [ 1592.189566] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1594.958572] Lustre: Failing over lustre-MDT0000 [ 1595.182859] Lustre: server umount lustre-MDT0000 complete [ 1595.383016] LustreError: 6500: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. [ 1595.412232] LustreError: 6500:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 136 previous similar messages [ 1611.743364] Lustre: 3632:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763154527/real 1763154527] req@ffffa0676b1fe680 x1848799903136384/t0(0) o400->MGC192.168.201.110@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1763154543 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1617.196302] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1617.199145] LDISKFS-fs (dm-0): recovery complete [ 1617.212632] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1621.988113] LustreError: 3630:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffffa0677ebff100 x1848799903144576/t0(0) o250->MGC192.168.201.110@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 [ 1625.297814] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 1649.395971] Lustre: Failing over lustre-MDT0000 [ 1649.408484] LustreError: 44782:0:(ldlm_lib.c:2982:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 1649.418123] Lustre: 44323:0:(ldlm_lib.c:2385:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 1649.424560] Lustre: 44323:0:(ldlm_lib.c:1897:abort_req_replay_queue()) @@@ aborted: req@ffffa06747168a80 x1848799896666240/t0(73014444033) o36->fc015d71-c2ff-431f-8a0c-eef82c7bc048@192.168.201.10@tcp:70/0 lens 528/0 e 2 to 0 dl 1763154590 ref 1 fl Complete:/204/ffffffff rc 0/-1 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 1649.445817] Lustre: lustre-MDT0000-osd: cancel update llog [0x200000400:0x1:0x0] [ 1649.459056] Lustre: lustre-MDT0000: Not available for connect from 192.168.201.10@tcp (stopping) [ 1649.481134] Lustre: lustre-MDT0001-osp-MDT0000: cancel update llog [0x240000401:0x1:0x0] [ 1649.489251] LustreError: 44323:0:(client.c:1380:ptlrpc_import_delay_req()) @@@ IMP_CLOSED req@ffffa0664b20ea00 x1848799903167488/t0(0) o1000->lustre-MDT0001-osp-MDT0000@0@lo:24/4 lens 336/33016 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 [ 1649.503638] LustreError: 44323:0:(llog_osd.c:1177:llog_osd_next_block()) lustre-MDT0001-osp-MDT0000: can't read llog block from log [0x240000401:0x1:0x0] offset 32768: rc = -5 [ 1649.518576] LustreError: 44323:0:(llog.c:867:llog_process_thread()) lustre-MDT0001-osp-MDT0000 retry remote llog process [ 1649.532521] LustreError: 44323:0:(fid_request.c:213:seq_client_alloc_seq()) cli-cli-lustre-MDT0001-osp-MDT0000: Cannot allocate new meta-sequence: rc = -5 [ 1649.542674] LustreError: 44323:0:(fid_request.c:316:seq_client_alloc_fid()) cli-cli-lustre-MDT0001-osp-MDT0000: Can't allocate new sequence: rc = -5 [ 1649.949743] Lustre: server umount lustre-MDT0000 complete [ 1666.927503] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1670.322865] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 1738.000631] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 1738.006085] Lustre: 45239:0:(genops.c:1618:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 2a640870-aa78-4331-ac10-087ddd391b43@ [ 1738.027969] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 1738.624767] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1551 to 0x2c0000401:1569) [ 1738.625029] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1550 to 0x280000401:1569) [ 1741.703486] Lustre: DEBUG MARKER: oleg110-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1742.780874] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1750.731171] Lustre: DEBUG MARKER: == replay-dual test 17: fail OST during recovery (3571) == 16:11:22 (1763154682) [ 1757.680794] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 1759.395853] Lustre: Failing over lustre-OST0000 [ 1759.489292] Lustre: server umount lustre-OST0000 complete [ 1759.713538] LustreError: lustre-OST0000-osc-MDT0001: operation ost_statfs to node 0@lo failed: rc = -107 [ 1779.686563] LDISKFS-fs (dm-2): 3 truncates cleaned up [ 1779.691721] LDISKFS-fs (dm-2): recovery complete [ 1779.707072] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 1779.892827] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 1779.896538] Lustre: Skipped 4 previous similar messages [ 1784.668049] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 1808.657971] Lustre: Failing over lustre-OST0000 [ 1808.665780] LustreError: 47628:0:(ldlm_lib.c:2982:target_stop_recovery_thread()) lustre-OST0000: Aborting recovery [ 1808.671882] Lustre: 47076:0:(ldlm_lib.c:2385:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 1808.678272] Lustre: 47076:0:(ldlm_lib.c:2385:target_recovery_overseer()) Skipped 2 previous similar messages [ 1808.683980] LustreError: 47076:0:(ofd_obd.c:1293:ofd_iocontrol()) lustre-OST0000: iocontrol from 'tgt_recover_0' cmd=c00866c1 _IOWR('f', 193, 8) unrecognized: rc = -25 [ 1808.786171] Lustre: server umount lustre-OST0000 complete [ 1821.151333] Lustre: 3630:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763154713/real 1763154713] req@ffffa0676b1fc700 x1848799903239808/t0(0) o400->lustre-OST0000-osc-MDT0001@0@lo:28/4 lens 224/224 e 2 to 1 dl 1763154753 ref 1 fl Rpc:XQr/2c0/ffffffff rc 0/-1 job:'ldlm_lock_repla.0' uid:0 gid:0 projid:4294967295 [ 1821.177322] Lustre: 3630:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 1825.624751] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 1830.164926] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 1897.000766] Lustre: lustre-OST0000: recovery is timed out, evict stale exports [ 1897.008514] Lustre: 48067:0:(genops.c:1618:class_disconnect_stale_exports()) lustre-OST0000: disconnect stale client 1ba7c1c4-2f18-426f-902a-9a63392bf6ec@ [ 1897.020789] Lustre: lustre-OST0000: disconnecting 1 stale clients [ 1897.062575] Lustre: lustre-OST0000-osc-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1897.075617] Lustre: Skipped 14 previous similar messages [ 1901.097705] Lustre: DEBUG MARKER: oleg110-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 1902.637548] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 1911.513931] Lustre: DEBUG MARKER: == replay-dual test 18: ldlm_handle_enqueue succeeds on evicted export (3822) ========================================================== 16:14:02 (1763154842) [ 1915.796165] LustreError: 6496:0:(ldlm_lockd.c:1360:ldlm_handle_enqueue()) cfs_fail_timeout id 30b sleeping for 40000ms [ 1955.818171] LustreError: 6496:0:(ldlm_lockd.c:1360:ldlm_handle_enqueue()) cfs_fail_timeout id 30b awake [ 1969.301775] Lustre: DEBUG MARKER: == replay-dual test 19: resend of open request =========== 16:15:00 (1763154900) [ 1977.134909] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1978.429738] Lustre: *** cfs_fail_loc=157, val=2147483648*** [ 1978.433782] LustreError: 6494:0:(ldlm_lib.c:3324:target_send_reply_msg()) @@@ dropping reply req@ffffa0676b19ed80 x1848799896787328/t0(0) o101->fc015d71-c2ff-431f-8a0c-eef82c7bc048@192.168.201.10@tcp:471/0 lens 576/688 e 0 to 0 dl 1763154991 ref 1 fl Interpret:/600/0 rc 0/0 job:'createmany.0' uid:0 gid:0 projid:0 [ 2064.721385] Lustre: lustre-MDT0000: Client fc015d71-c2ff-431f-8a0c-eef82c7bc048 (at 192.168.201.10@tcp) reconnecting [ 2068.270117] Lustre: Failing over lustre-MDT0000 [ 2068.451705] 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 [ 2068.463694] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2068.475932] Lustre: Skipped 14 previous similar messages [ 2068.482265] Lustre: Skipped 1 previous similar message [ 2068.511454] LustreError: 49971:0:(obd_class.h:479:obd_check_dev()) Device 22 not setup [ 2068.521623] LustreError: 49971:0:(obd_class.h:479:obd_check_dev()) Skipped 31 previous similar messages [ 2068.641297] Lustre: server umount lustre-MDT0000 complete [ 2088.927148] Lustre: 3631:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763155005/real 1763155005] req@ffffa0676b06df80 x1848799903376128/t0(0) o400->MGC192.168.201.110@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1763155021 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2088.994665] Lustre: 3631:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 2089.030487] LustreError: MGC192.168.201.110@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2089.046376] LustreError: Skipped 2 previous similar messages [ 2091.261790] LDISKFS-fs (dm-0): 4 truncates cleaned up [ 2091.263522] LDISKFS-fs (dm-0): recovery complete [ 2091.286854] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2099.684883] LustreError: 3630:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffffa0676b0a5c00 x1848799903384192/t0(0) o250->MGC192.168.201.110@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 [ 2100.135477] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 2100.138952] Lustre: Skipped 4 previous similar messages [ 2100.937952] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 2100.956380] Lustre: Skipped 4 previous similar messages [ 2103.512788] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 2105.345373] Lustre: 50623:0:(ldlm_lib.c:2067:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 2105.442130] Lustre: lustre-MDT0000: Recovery over after 0:05, of 3 clients 3 recovered and 0 were evicted. [ 2105.451064] Lustre: Skipped 4 previous similar messages [ 2105.471320] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1584 to 0x280000401:1601) [ 2105.473039] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1584 to 0x2c0000401:1601) [ 2110.008159] Lustre: DEBUG MARKER: oleg110-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2111.343870] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2119.914056] Lustre: DEBUG MARKER: == replay-dual test 20: recovery time is not increasing == 16:17:30 (1763155050) [ 2126.942496] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2128.972265] Lustre: Failing over lustre-MDT0000 [ 2129.157617] Lustre: server umount lustre-MDT0000 complete [ 2152.903957] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2152.908100] LDISKFS-fs (dm-0): recovery complete [ 2152.918706] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2157.537562] LustreError: 3630:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffffa067772b6a00 x1848799903418752/t0(0) o250->MGC192.168.201.110@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 [ 2161.842990] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 2298.000187] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 2298.002506] Lustre: 52449:0:(genops.c:1618:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client bbc32a46-7e7a-4d13-808d-85118c9f95f8@ [ 2298.032059] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 2298.080313] Lustre: 52449:0:(ldlm_lib.c:2067:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 2298.084954] Lustre: 52449:0:(ldlm_lib.c:2067:extend_recovery_timer()) Skipped 5 previous similar messages [ 2298.249436] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1584 to 0x2c0000401:1633) [ 2298.250426] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1603 to 0x280000401:1633) [ 2302.093394] Lustre: DEBUG MARKER: oleg110-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2304.054389] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2313.760414] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2316.473618] Lustre: Failing over lustre-MDT0000 [ 2316.500928] Lustre: lustre-MDT0000: Not available for connect from 192.168.201.10@tcp (stopping) [ 2316.768702] Lustre: server umount lustre-MDT0000 complete [ 2316.772786] LustreError: 13506: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. [ 2316.801168] LustreError: 13506:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 136 previous similar messages [ 2337.727296] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2337.729398] LDISKFS-fs (dm-0): recovery complete [ 2337.749973] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2338.005850] Lustre: lustre-MDT0000: Not available for connect from 192.168.201.10@tcp (not set up) [ 2341.794281] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 2479.000261] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 2479.009057] Lustre: 54121:0:(genops.c:1618:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 6177363d-f00c-4de7-ab75-ef4840638c10@ [ 2479.025165] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 2479.066647] Lustre: 54121:0:(ldlm_lib.c:2067:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 2479.086468] Lustre: 54121:0:(ldlm_lib.c:2067:extend_recovery_timer()) Skipped 4 previous similar messages [ 2479.219642] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1635 to 0x280000401:1665) [ 2479.221175] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1584 to 0x2c0000401:1665) [ 2482.564717] Lustre: DEBUG MARKER: oleg110-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2484.124521] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2491.454383] Lustre: DEBUG MARKER: == replay-dual test 21a: commit on sharing =============== 16:23:42 (1763155422) [ 2497.756985] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2499.153597] Lustre: Failing over lustre-MDT0000 [ 2499.331570] Lustre: server umount lustre-MDT0000 complete [ 2499.554073] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 2519.619399] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2519.622335] LDISKFS-fs (dm-0): recovery complete [ 2519.633087] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2527.910550] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 2527.916062] Lustre: Skipped 4 previous similar messages [ 2531.721173] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 2533.377589] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 2533.400823] Lustre: Skipped 13 previous similar messages [ 2668.000719] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 2668.003946] Lustre: 56034:0:(genops.c:1618:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 6e7a1f9d-e87b-4e3f-aa04-cdb96197fd62@ [ 2668.011112] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 2668.055813] Lustre: 56034:0:(ldlm_lib.c:2067:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 2668.061820] Lustre: 56034:0:(ldlm_lib.c:2067:extend_recovery_timer()) Skipped 4 previous similar messages [ 2668.109650] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1584 to 0x2c0000401:1697) [ 2668.110766] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1667 to 0x280000401:1697) [ 2677.235725] Lustre: DEBUG MARKER: SKIP: replay-dual test_21b skipping SLOW test 21b [ 2679.110617] Lustre: DEBUG MARKER: == replay-dual test 22a: c1 lfs mkdir -i 1 dir1, M1 drop reply [ 2680.146359] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 2680.149255] LustreError: 6494:0:(ldlm_lib.c:3324:target_send_reply_msg()) @@@ dropping reply req@ffffa06777740380 x1848799896902528/t4294967345(0) o36->fc015d71-c2ff-431f-8a0c-eef82c7bc048@192.168.201.10@tcp:417/0 lens 560/448 e 0 to 0 dl 1763155692 ref 1 fl Interpret:/200/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 2683.120053] Lustre: Failing over lustre-MDT0001 [ 2683.303779] LustreError: 56904:0:(obd_class.h:479:obd_check_dev()) Device 27 not setup [ 2683.306340] LustreError: 56904:0:(obd_class.h:479:obd_check_dev()) Skipped 31 previous similar messages [ 2683.445387] Lustre: server umount lustre-MDT0001 complete [ 2686.947607] Lustre: lustre-MDT0001-osp-MDT0000: Connection to lustre-MDT0001 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 2686.953443] Lustre: Skipped 14 previous similar messages [ 2701.095366] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 2701.599938] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 2701.613034] Lustre: Skipped 3 previous similar messages [ 2703.219718] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 2703.225702] Lustre: Skipped 3 previous similar messages [ 2705.953855] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 2706.969938] Lustre: lustre-MDT0001: Recovery over after 0:03, of 3 clients 3 recovered and 0 were evicted. [ 2706.984985] Lustre: Skipped 3 previous similar messages [ 2707.023978] Lustre: 16837:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffffa0676b3b8000 x1848799896902528/t4294967345(0) o36->fc015d71-c2ff-431f-8a0c-eef82c7bc048@192.168.201.10@tcp:444/0 lens 560/2880 e 0 to 0 dl 1763155719 ref 1 fl Interpret:/202/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 2712.996692] Lustre: DEBUG MARKER: oleg110-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 2714.775573] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2723.844814] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2726.106624] Lustre: Failing over lustre-MDT0000 [ 2726.513975] Lustre: server umount lustre-MDT0000 complete [ 2742.756195] Lustre: 3633:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763155659/real 1763155659] req@ffffa06747107b80 x1848799903670656/t0(0) o400->MGC192.168.201.110@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1763155675 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2742.791839] Lustre: 3633:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 2742.811150] LustreError: MGC192.168.201.110@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2742.830544] LustreError: Skipped 3 previous similar messages [ 2748.146086] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2748.149668] LDISKFS-fs (dm-0): recovery complete [ 2748.179976] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2753.005166] LustreError: 3630:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffffa0664e0dfb80 x1848799903678976/t0(0) o250->MGC192.168.201.110@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 [ 2756.370310] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 2758.669068] Lustre: 58974:0:(ldlm_lib.c:2067:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 2758.745619] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1667 to 0x280000401:1729) [ 2758.752094] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1584 to 0x2c0000401:1729) [ 2762.494952] Lustre: DEBUG MARKER: oleg110-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2763.878287] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2770.699600] Lustre: DEBUG MARKER: == replay-dual test 22b: c1 lfs mkdir -i 1 d1, M1 drop reply [ 2771.598837] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 2771.606690] LustreError: 6495:0:(ldlm_lib.c:3324:target_send_reply_msg()) @@@ dropping reply req@ffffa0677e5df800 x1848799896937728/t8589934617(0) o36->fc015d71-c2ff-431f-8a0c-eef82c7bc048@192.168.201.10@tcp:508/0 lens 560/448 e 0 to 0 dl 1763155783 ref 1 fl Interpret:/200/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 2774.176153] Lustre: Failing over lustre-MDT0000 [ 2774.453230] Lustre: server umount lustre-MDT0000 complete [ 2777.065221] LustreError: 6480:0:(ldlm_lockd.c:2563:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1763155709 with bad export cookie 12481373273178584113 [ 2777.143704] Lustre: Failing over lustre-MDT0001 [ 2777.161295] LustreError: 60002:0:(client.c:1380:ptlrpc_import_delay_req()) @@@ IMP_CLOSED req@ffffa06748c8e300 x1848799903705728/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 [ 2777.170667] LustreError: 60002:0:(client.c:1380:ptlrpc_import_delay_req()) Skipped 1 previous similar message [ 2777.175744] LustreError: 60002:0:(osp_object.c:617:osp_attr_get()) lustre-MDT0000-osp-MDT0001: osp_attr_get update error [0x200000401:0x1:0x0]: rc = -5 [ 2777.382874] Lustre: server umount lustre-MDT0001 complete [ 2795.703486] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2795.740454] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 2796.009965] LustreError: 60708:0:(llog.c:1616:llog_backup()) MGC192.168.201.110@tcp: failed to open log lustre-sptlrpc: rc = -108 [ 2796.013437] Lustre: 60708:0:(mgc_request_server.c:732:mgc_llog_local_copy()) MGC192.168.201.110@tcp: failed to copy new config lustre-sptlrpc: rc = -108 [ 2801.702905] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xad36bedce0dd3b46 [ 2806.462729] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 2807.036681] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 2808.503092] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:36 to 0x280000400:65) [ 2808.503892] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:36 to 0x2c0000400:65) [ 2808.535847] Lustre: 60721:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffffa0664e0df480 x1848799896937728/t8589934617(0) o36->fc015d71-c2ff-431f-8a0c-eef82c7bc048@192.168.201.10@tcp:545/0 lens 560/2880 e 0 to 0 dl 1763155820 ref 1 fl Interpret:/202/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 2814.701846] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1584 to 0x2c0000401:1761) [ 2814.707403] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1667 to 0x280000401:1761) [ 2818.026392] Lustre: DEBUG MARKER: oleg110-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 2819.582600] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2820.658407] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2827.540751] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2829.347654] Lustre: Failing over lustre-MDT0000 [ 2829.588127] Lustre: server umount lustre-MDT0000 complete [ 2851.446512] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2851.448569] LDISKFS-fs (dm-0): recovery complete [ 2851.464284] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2860.006029] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xad36bedce0dd4430 [ 2864.917149] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 2865.696480] Lustre: 62806:0:(ldlm_lib.c:2067:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 2865.715625] Lustre: 62806:0:(ldlm_lib.c:2067:extend_recovery_timer()) Skipped 4 previous similar messages [ 2865.878231] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1667 to 0x280000401:1793) [ 2865.885211] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1584 to 0x2c0000401:1793) [ 2872.912696] Lustre: DEBUG MARKER: oleg110-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2874.874238] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2883.130366] Lustre: DEBUG MARKER: == replay-dual test 22c: c1 lfs mkdir -i 1 d1, M1 drop update [ 2884.181799] Lustre: *** cfs_fail_loc=1701, val=2147483648*** [ 2884.186181] LustreError: 8391:0:(ldlm_lib.c:3324:target_send_reply_msg()) @@@ dropping reply req@ffffa0677e85fb80 x1848799903775616/t107374182411(0) o1000->lustre-MDT0001-mdtlov_UUID@0@lo:552/0 lens 2520/4320 e 0 to 0 dl 1763155827 ref 1 fl Interpret:/200/0 rc 0/0 job:'osp_up0-1.0' uid:0 gid:0 projid:4294967295 [ 2887.296458] Lustre: Failing over lustre-MDT0000 [ 2887.550384] Lustre: server umount lustre-MDT0000 complete [ 2906.296313] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2911.329665] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 2912.366670] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1584 to 0x2c0000401:1825) [ 2912.371886] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1667 to 0x280000401:1825) [ 2920.040234] Lustre: DEBUG MARKER: oleg110-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2921.714599] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2932.432718] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2935.075087] Lustre: Failing over lustre-MDT0000 [ 2935.436114] Lustre: server umount lustre-MDT0000 complete [ 2937.556667] LustreError: 60723:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.201.10@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 2937.585086] LustreError: 60723:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 187 previous similar messages [ 2956.418620] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2956.420468] LDISKFS-fs (dm-0): recovery complete [ 2956.429741] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2964.454595] LustreError: 3630:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffffa0677f604a80 x1848799903818240/t0(0) o250->MGC192.168.201.110@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 [ 2968.622349] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 2970.136189] Lustre: 65767:0:(ldlm_lib.c:2067:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 2970.140787] Lustre: 65767:0:(ldlm_lib.c:2067:extend_recovery_timer()) Skipped 4 previous similar messages [ 2970.248806] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1667 to 0x280000401:1857) [ 2970.248807] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1584 to 0x2c0000401:1857) [ 2975.607608] Lustre: DEBUG MARKER: oleg110-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2977.259611] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2985.357883] Lustre: DEBUG MARKER: == replay-dual test 22d: c1 lfs mkdir -i 1 d1, M1 drop update [ 2989.623550] Lustre: *** cfs_fail_loc=1701, val=2147483648*** [ 2989.625734] LustreError: 61423:0:(ldlm_lib.c:3324:target_send_reply_msg()) @@@ dropping reply req@ffffa0677ecb3100 x1848799903843584/t115964117002(0) o1000->lustre-MDT0001-mdtlov_UUID@0@lo:657/0 lens 2520/4320 e 0 to 0 dl 1763155932 ref 1 fl Interpret:/200/0 rc 0/0 job:'osp_up0-1.0' uid:0 gid:0 projid:4294967295 [ 2993.385241] Lustre: Failing over lustre-MDT0000 [ 2993.868128] Lustre: server umount lustre-MDT0000 complete [ 2997.839988] LustreError: 6480:0:(ldlm_lockd.c:2563:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1763155930 with bad export cookie 12481373273178591673 [ 2997.844225] Lustre: Failing over lustre-MDT0001 [ 2997.850465] LustreError: 6480:0:(ldlm_lockd.c:2563:ldlm_cancel_handler()) Skipped 3 previous similar messages [ 2997.864735] LustreError: 66895:0:(ldlm_resource.c:981:ldlm_resource_complain()) lustre-MDT0000-osp-MDT0001: namespace resource [0x2000013a1:0x78:0x0].0xf7117594 (ffffa0675a34e400) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 2997.924368] Lustre: lustre-MDT0001: Not available for connect from 192.168.201.10@tcp (stopping) [ 3000.812354] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 3000.831775] Lustre: Skipped 1 previous similar message [ 3002.850561] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 3002.856080] Lustre: Skipped 3 previous similar messages [ 3004.078057] Lustre: server umount lustre-MDT0001 complete [ 3024.097549] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 3024.457709] LustreError: 67574:0:(llog.c:1616:llog_backup()) MGC192.168.201.110@tcp: failed to open log lustre-sptlrpc: rc = -108 [ 3024.469573] Lustre: 67574:0:(mgc_request_server.c:732:mgc_llog_local_copy()) MGC192.168.201.110@tcp: failed to copy new config lustre-sptlrpc: rc = -108 [ 3024.501952] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3048.208287] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 3048.675657] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 3049.066195] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1584 to 0x2c0000401:1889) [ 3049.070593] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1667 to 0x280000401:1889) [ 3049.314664] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:70 to 0x280000400:97) [ 3049.318064] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:70 to 0x2c0000400:97) [ 3049.379651] Lustre: 67592:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffffa06781a26d80 x1848799897021696/t12884901939(0) o36->fc015d71-c2ff-431f-8a0c-eef82c7bc048@192.168.201.10@tcp:31/0 lens 560/2880 e 0 to 0 dl 1763156061 ref 1 fl Interpret:/202/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 3056.938394] Lustre: DEBUG MARKER: oleg110-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 3058.451154] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3060.059345] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3069.748631] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3072.040588] Lustre: Failing over lustre-MDT0000 [ 3072.315238] Lustre: server umount lustre-MDT0000 complete [ 3074.533697] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3074.536341] LustreError: Skipped 4 previous similar messages [ 3094.063042] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3094.065224] LDISKFS-fs (dm-0): recovery complete [ 3094.071967] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3100.131333] LustreError: 3630:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffffa0677ecb0380 x1848799903891840/t0(0) o250->MGC192.168.201.110@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 [ 3100.155292] LustreError: 3630:0:(client.c:1390:ptlrpc_import_delay_req()) Skipped 4 previous similar messages [ 3103.942052] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 3105.817820] Lustre: 69696:0:(ldlm_lib.c:2067:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3105.846711] Lustre: 69696:0:(ldlm_lib.c:2067:extend_recovery_timer()) Skipped 4 previous similar messages [ 3105.947967] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1667 to 0x280000401:1921) [ 3105.952973] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1584 to 0x2c0000401:1921) [ 3110.564407] Lustre: DEBUG MARKER: oleg110-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3112.242839] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3120.274855] Lustre: DEBUG MARKER: == replay-dual test 23a: c1 rmdir d1, M1 drop reply and fail, client2 mkdir d1 ========================================================== 16:34:11 (1763156051) [ 3121.603005] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 3121.605340] LustreError: 67592:0:(ldlm_lib.c:3324:target_send_reply_msg()) @@@ dropping reply req@ffffa0677ee8d180 x1848799897065600/t17179869210(0) o36->fc015d71-c2ff-431f-8a0c-eef82c7bc048@192.168.201.10@tcp:103/0 lens 496/456 e 0 to 0 dl 1763156133 ref 1 fl Interpret:/200/0 rc 0/0 job:'rmdir.0' uid:0 gid:0 projid:4294967295 [ 3125.370377] Lustre: Failing over lustre-MDT0001 [ 3126.242089] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 3131.146272] Lustre: server umount lustre-MDT0001 complete [ 3149.316315] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 3149.748473] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 3149.751670] Lustre: Skipped 10 previous similar messages [ 3153.641904] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 3154.949459] Lustre: lustre-MDT0001-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 3154.952167] Lustre: Skipped 40 previous similar messages [ 3155.007785] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:100 to 0x280000400:129) [ 3155.008296] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:100 to 0x2c0000400:129) [ 3155.024507] Lustre: 71315:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffffa0664d416680 x1848799897065600/t17179869210(0) o36->fc015d71-c2ff-431f-8a0c-eef82c7bc048@192.168.201.10@tcp:137/0 lens 496/2888 e 0 to 0 dl 1763156167 ref 1 fl Interpret:/202/0 rc 0/0 job:'rmdir.0' uid:0 gid:0 projid:4294967295 [ 3160.767223] Lustre: DEBUG MARKER: oleg110-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 3162.604919] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3172.026142] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3173.905988] Lustre: Failing over lustre-MDT0000 [ 3174.208974] Lustre: server umount lustre-MDT0000 complete [ 3195.498555] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3195.500829] LDISKFS-fs (dm-0): recovery complete [ 3195.517761] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3205.313962] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 3207.167869] Lustre: 72642:0:(ldlm_lib.c:2067:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3207.175331] Lustre: 72642:0:(ldlm_lib.c:2067:extend_recovery_timer()) Skipped 4 previous similar messages [ 3207.314861] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1923 to 0x2c0000401:1953) [ 3207.316123] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1923 to 0x280000401:1953) [ 3212.166501] Lustre: DEBUG MARKER: oleg110-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3213.771424] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3221.652627] Lustre: DEBUG MARKER: == replay-dual test 23b: c1 rmdir d1, M1 drop reply and fail M0/M1, c2 mkdir d1 ========================================================== 16:35:52 (1763156152) [ 3222.856728] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 3222.858987] LustreError: 67593:0:(ldlm_lib.c:3324:target_send_reply_msg()) @@@ dropping reply req@ffffa0675a261c00 x1848799897099136/t21474836483(0) o36->fc015d71-c2ff-431f-8a0c-eef82c7bc048@192.168.201.10@tcp:205/0 lens 496/456 e 0 to 0 dl 1763156235 ref 1 fl Interpret:/200/0 rc 0/0 job:'rmdir.0' uid:0 gid:0 projid:4294967295 [ 3226.485286] Lustre: Failing over lustre-MDT0000 [ 3226.760810] Lustre: server umount lustre-MDT0000 complete [ 3230.087626] Lustre: Failing over lustre-MDT0001 [ 3230.088058] LustreError: 6481:0:(ldlm_lockd.c:2563:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1763156162 with bad export cookie 12481373273178598848 [ 3230.094622] LustreError: 6481:0:(ldlm_lockd.c:2563:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 3230.385354] Lustre: server umount lustre-MDT0001 complete [ 3248.627873] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 3248.866068] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3248.909184] LustreError: 74396:0:(llog.c:1616:llog_backup()) MGC192.168.201.110@tcp: failed to open log lustre-sptlrpc: rc = -108 [ 3248.917968] Lustre: 74396:0:(mgc_request_server.c:732:mgc_llog_local_copy()) MGC192.168.201.110@tcp: failed to copy new config lustre-sptlrpc: rc = -108 [ 3255.267668] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xad36bedce0dd7514 [ 3259.027093] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 3259.405912] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 3261.482158] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1923 to 0x2c0000401:1985) [ 3261.485494] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1923 to 0x280000401:1985) [ 3261.642042] Lustre: 74454:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffffa066491d5f80 x1848799897099136/t21474836483(0) o36->fc015d71-c2ff-431f-8a0c-eef82c7bc048@192.168.201.10@tcp:243/0 lens 496/2888 e 0 to 0 dl 1763156273 ref 1 fl Interpret:/202/0 rc 0/0 job:'rmdir.0' uid:0 gid:0 projid:4294967295 [ 3261.650344] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:100 to 0x280000400:161) [ 3261.650368] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:100 to 0x2c0000400:161) [ 3265.847648] Lustre: DEBUG MARKER: oleg110-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 3266.992663] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3268.068925] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3276.175391] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3278.015896] Lustre: Failing over lustre-MDT0000 [ 3278.280615] Lustre: server umount lustre-MDT0000 complete [ 3297.437280] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3297.439357] LDISKFS-fs (dm-0): recovery complete [ 3297.446021] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3300.864080] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 3303.032996] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1987 to 0x280000401:2017) [ 3303.033618] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1987 to 0x2c0000401:2017) [ 3306.633281] Lustre: DEBUG MARKER: oleg110-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3307.872248] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3315.074654] Lustre: DEBUG MARKER: == replay-dual test 23c: c1 rmdir d1, M0 drop update reply and fail M0, c2 mkdir d1 ========================================================== 16:37:26 (1763156246) [ 3316.123267] Lustre: *** cfs_fail_loc=1701, val=2147483648*** [ 3316.125507] LustreError: 8391:0:(ldlm_lib.c:3324:target_send_reply_msg()) @@@ dropping reply req@ffffa06642c8a050 x1848799904045696/t137438953491(0) o1000->lustre-MDT0001-mdtlov_UUID@0@lo:229/0 lens 1984/4320 e 0 to 0 dl 1763156259 ref 1 fl Interpret:/200/0 rc 0/0 job:'osp_up0-1.0' uid:0 gid:0 projid:4294967295 [ 3318.965844] Lustre: Failing over lustre-MDT0000 [ 3319.111130] LustreError: 77392:0:(obd_class.h:479:obd_check_dev()) Device 27 not setup [ 3319.114313] LustreError: 77392:0:(obd_class.h:479:obd_check_dev()) Skipped 119 previous similar messages [ 3319.198909] Lustre: server umount lustre-MDT0000 complete [ 3323.362521] Lustre: lustre-MDT0000-lwp-OST0001: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 3323.367721] Lustre: Skipped 48 previous similar messages [ 3336.354721] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3336.885645] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 3336.897894] Lustre: Skipped 14 previous similar messages [ 3338.958331] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 3338.967197] Lustre: Skipped 14 previous similar messages [ 3340.023782] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 3341.814495] Lustre: lustre-MDT0000: Recovery over after 0:03, of 3 clients 3 recovered and 0 were evicted. [ 3341.825210] Lustre: Skipped 14 previous similar messages [ 3341.849743] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1987 to 0x280000401:2049) [ 3341.850304] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1987 to 0x2c0000401:2049) [ 3346.391836] Lustre: DEBUG MARKER: oleg110-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3347.703807] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3355.407094] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3357.246841] Lustre: Failing over lustre-MDT0000 [ 3357.560032] Lustre: server umount lustre-MDT0000 complete [ 3377.801855] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3377.803657] LDISKFS-fs (dm-0): recovery complete [ 3377.837978] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3377.974582] LustreError: MGC192.168.201.110@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3377.979892] LustreError: Skipped 10 previous similar messages [ 3381.327871] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 3383.294843] Lustre: 79475:0:(ldlm_lib.c:2067:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3383.306518] Lustre: 79475:0:(ldlm_lib.c:2067:extend_recovery_timer()) Skipped 17 previous similar messages [ 3383.433564] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2051 to 0x280000401:2081) [ 3383.436947] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2051 to 0x2c0000401:2081) [ 3387.725899] Lustre: DEBUG MARKER: oleg110-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3389.108755] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3396.524665] Lustre: DEBUG MARKER: == replay-dual test 23d: c1 rmdir d1, M0 drop update reply and fail M0/M1, c2 mkdir d1 ========================================================== 16:38:47 (1763156327) [ 3400.706913] Lustre: *** cfs_fail_loc=1701, val=2147483648*** [ 3400.714072] LustreError: 61423:0:(ldlm_lib.c:3324:target_send_reply_msg()) @@@ dropping reply req@ffffa0677e95bb80 x1848799904105856/t146028888081(0) o1000->lustre-MDT0001-mdtlov_UUID@0@lo:314/0 lens 1984/4320 e 0 to 0 dl 1763156344 ref 1 fl Interpret:/200/0 rc 0/0 job:'osp_up0-1.0' uid:0 gid:0 projid:4294967295 [ 3403.284229] Lustre: Failing over lustre-MDT0000 [ 3403.585356] Lustre: server umount lustre-MDT0000 complete [ 3405.853964] LustreError: 10254:0:(ldlm_lockd.c:2563:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1763156338 with bad export cookie 12481373273178606072 [ 3405.855090] Lustre: Failing over lustre-MDT0001 [ 3405.861574] LustreError: 10254:0:(ldlm_lockd.c:2563:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 3405.869774] LustreError: 80600:0:(ldlm_resource.c:981:ldlm_resource_complain()) lustre-MDT0000-osp-MDT0001: namespace resource [0x2000013a1:0x80:0x0].0x0 (ffffa06762768f00) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 3405.889725] Lustre: lustre-MDT0001: Not available for connect from 192.168.201.10@tcp (stopping) [ 3405.892765] Lustre: Skipped 5 previous similar messages [ 3412.221048] Lustre: server umount lustre-MDT0001 complete [ 3428.488841] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3428.522085] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 3428.757547] LustreError: 81308:0:(llog.c:1616:llog_backup()) MGC192.168.201.110@tcp: failed to open log lustre-sptlrpc: rc = -108 [ 3428.766475] Lustre: 81308:0:(mgc_request_server.c:732:mgc_llog_local_copy()) MGC192.168.201.110@tcp: failed to copy new config lustre-sptlrpc: rc = -108 [ 3431.392732] LustreError: 3630:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffffa0676b1fe680 x1848799904112256/t0(0) o250->MGC192.168.201.110@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 [ 3431.404987] LustreError: 3630:0:(client.c:1390:ptlrpc_import_delay_req()) Skipped 6 previous similar messages [ 3434.782558] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 3435.134029] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 3437.308650] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2051 to 0x280000401:2113) [ 3437.308651] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2051 to 0x2c0000401:2113) [ 3442.451552] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:100 to 0x280000400:193) [ 3442.458358] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:100 to 0x2c0000400:193) [ 3442.477462] Lustre: 81317:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffffa06747404e00 x1848799897165440/t25769803783(0) o36->fc015d71-c2ff-431f-8a0c-eef82c7bc048@192.168.201.10@tcp:424/0 lens 496/2888 e 0 to 0 dl 1763156454 ref 1 fl Interpret:/202/0 rc 0/0 job:'rmdir.0' uid:0 gid:0 projid:4294967295 [ 3445.169746] Lustre: DEBUG MARKER: oleg110-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 3446.509864] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3448.103212] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3455.609776] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3457.078313] Lustre: Failing over lustre-MDT0000 [ 3457.265314] Lustre: server umount lustre-MDT0000 complete [ 3476.549978] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3476.551934] LDISKFS-fs (dm-0): recovery complete [ 3476.568643] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3480.272369] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 3482.259435] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2115 to 0x2c0000401:2145) [ 3482.262220] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2115 to 0x280000401:2145) [ 3486.424619] Lustre: DEBUG MARKER: oleg110-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3487.567925] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3494.014573] Lustre: DEBUG MARKER: == replay-dual test 24: reconstruct on non-existing object ========================================================== 16:40:25 (1763156425) [ 3494.927035] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 3494.929134] LustreError: 82069:0:(ldlm_lib.c:3324:target_send_reply_msg()) @@@ dropping reply req@ffffa0677ee84a80 x1848799897197952/t154618822673(0) o36->fc015d71-c2ff-431f-8a0c-eef82c7bc048@192.168.201.10@tcp:477/0 lens 488/456 e 0 to 0 dl 1763156507 ref 1 fl Interpret:/200/0 rc 0/0 job:'truncate.0' uid:0 gid:0 projid:4294967295 [ 3580.111554] Lustre: lustre-MDT0000: Client fc015d71-c2ff-431f-8a0c-eef82c7bc048 (at 192.168.201.10@tcp) reconnecting [ 3580.132925] Lustre: 81317:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffffa06777f77100 x1848799897197952/t154618822673(0) o36->fc015d71-c2ff-431f-8a0c-eef82c7bc048@192.168.201.10@tcp:562/0 lens 488/3152 e 0 to 0 dl 1763156592 ref 1 fl Interpret:/202/0 rc 0/0 job:'truncate.0' uid:0 gid:0 projid:4294967295 [ 3584.724614] Lustre: DEBUG MARKER: == replay-dual test 25: replay|resend ==================== 16:41:56 (1763156516) [ 3585.873444] Lustre: *** cfs_fail_loc=304, val=0*** [ 3587.840803] Lustre: Failing over lustre-OST0000 [ 3587.915095] Lustre: server umount lustre-OST0000 complete [ 3588.580286] LustreError: 48807:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-OST0000: 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. [ 3588.589666] LustreError: 48807:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 301 previous similar messages [ 3603.307506] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 3607.292727] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 3612.751055] Lustre: DEBUG MARKER: oleg110-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 3614.106945] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 3621.950906] Lustre: DEBUG MARKER: == replay-dual test 26: dbench and tar with mds failover ========================================================== 16:42:33 (1763156553) [ 3630.281579] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3633.447971] Lustre: DEBUG MARKER: test_26 fail mds1 1 times [ 3634.909129] Lustre: Failing over lustre-MDT0000 [ 3634.936290] Lustre: lustre-MDT0000: Not available for connect from 192.168.201.10@tcp (stopping) [ 3634.939295] Lustre: Skipped 8 previous similar messages [ 3635.221522] Lustre: server umount lustre-MDT0000 complete [ 3652.913620] LDISKFS-fs (dm-0): 3 truncates cleaned up [ 3652.915554] LDISKFS-fs (dm-0): recovery complete [ 3652.924166] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3656.231476] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 3658.737484] Lustre: 87095:0:(ldlm_lib.c:2067:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3658.743400] Lustre: 87095:0:(ldlm_lib.c:2067:extend_recovery_timer()) Skipped 17 previous similar messages [ 3660.572338] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2178 to 0x2c0000401:2209) [ 3660.575828] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2180 to 0x280000401:2209) [ 3663.566788] Lustre: DEBUG MARKER: oleg110-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3664.869753] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3674.250892] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 3677.378951] Lustre: DEBUG MARKER: test_26 fail mds2 2 times [ 3678.686429] Lustre: Failing over lustre-MDT0001 [ 3678.691186] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -19 [ 3678.698414] LustreError: Skipped 5 previous similar messages [ 3678.719058] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 3684.986934] Lustre: server umount lustre-MDT0001 complete [ 3702.974091] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 3702.977281] LDISKFS-fs (dm-1): recovery complete [ 3703.002799] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 3706.161867] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 3710.186433] Lustre: 84252:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffffa0677e978a80 x1848799898073088/t30064771858(0) o36->fc015d71-c2ff-431f-8a0c-eef82c7bc048@192.168.201.10@tcp:692/0 lens 552/2880 e 0 to 0 dl 1763156722 ref 1 fl Interpret:/202/0 rc 0/0 job:'tar.0' uid:0 gid:0 projid:4294967295 [ 3710.190078] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:270 to 0x2c0000400:289) [ 3710.190414] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:270 to 0x280000400:289) [ 3712.513655] Lustre: DEBUG MARKER: oleg110-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 3713.830786] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3722.946607] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3726.246690] Lustre: DEBUG MARKER: test_26 fail mds1 3 times [ 3727.760451] Lustre: Failing over lustre-MDT0000 [ 3727.779551] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3727.785159] Lustre: Skipped 9 previous similar messages [ 3728.096242] Lustre: server umount lustre-MDT0000 complete [ 3745.247191] Lustre: 3631:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763156661/real 1763156661] req@ffffa0677ee86300 x1848799904623872/t0(0) o400->MGC192.168.201.110@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1763156677 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3745.260492] Lustre: 3631:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 34 previous similar messages [ 3745.715216] LDISKFS-fs (dm-0): 3 truncates cleaned up [ 3745.717531] LDISKFS-fs (dm-0): recovery complete [ 3745.728295] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3755.497680] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xad36bedce0df0fac [ 3755.509473] Lustre: MGC192.168.201.110@tcp: Connection restored to 0@lo (at 0@lo) [ 3755.512430] Lustre: Skipped 44 previous similar messages [ 3755.679121] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3755.682692] Lustre: Skipped 12 previous similar messages [ 3758.044968] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 3761.861099] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2277 to 0x2c0000401:2305) [ 3761.861407] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2277 to 0x280000401:2305) [ 3764.274901] Lustre: DEBUG MARKER: oleg110-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3765.224290] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3772.949131] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 3775.833667] Lustre: DEBUG MARKER: test_26 fail mds2 4 times [ 3776.960683] Lustre: Failing over lustre-MDT0001 [ 3783.174816] Lustre: server umount lustre-MDT0001 complete [ 3799.560354] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 3799.562545] LDISKFS-fs (dm-1): recovery complete [ 3799.573890] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 3801.838847] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 3806.391313] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:382 to 0x2c0000400:417) [ 3806.391655] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:381 to 0x280000400:417) [ 3808.473958] Lustre: DEBUG MARKER: oleg110-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 3809.414895] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3817.071382] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3819.938705] Lustre: DEBUG MARKER: test_26 fail mds1 5 times [ 3821.004329] Lustre: Failing over lustre-MDT0000 [ 3821.164682] Lustre: lustre-MDT0000: Not available for connect from 192.168.201.10@tcp (stopping) [ 3821.168927] Lustre: Skipped 7 previous similar messages [ 3821.366436] Lustre: server umount lustre-MDT0000 complete [ 3822.593830] LustreError: 10254:0:(ldlm_lockd.c:2563:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1763156754 with bad export cookie 12481373273178748004 [ 3822.605815] LustreError: 10254:0:(ldlm_lockd.c:2563:ldlm_cancel_handler()) Skipped 1 previous similar message [ 3838.005754] LDISKFS-fs (dm-0): 3 truncates cleaned up [ 3838.008680] LDISKFS-fs (dm-0): recovery complete [ 3838.017819] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3840.566087] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 3844.752725] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2399 to 0x280000401:2433) [ 3844.754550] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2398 to 0x2c0000401:2433) [ 3847.037808] Lustre: DEBUG MARKER: oleg110-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3847.973606] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3894.321787] Lustre: DEBUG MARKER: == replay-dual test 28: lock replay should be ordered: waiting after granted ========================================================== 16:47:06 (1763156826) [ 3905.405445] Lustre: Failing over lustre-OST0000 [ 3905.487467] Lustre: server umount lustre-OST0000 complete [ 3919.878268] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 3922.044526] Lustre: *** cfs_fail_loc=32a, val=0*** [ 3922.829240] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 3926.832630] Lustre: DEBUG MARKER: oleg110-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 3927.693294] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 3934.491949] Lustre: DEBUG MARKER: == replay-dual test 29: replay vs update with the same xid ========================================================== 16:47:46 (1763156866) [ 3935.320791] Lustre: DEBUG MARKER: SKIP: replay-dual test_29 needs >= 2 clients [ 3936.157623] Lustre: DEBUG MARKER: == replay-dual test 30: layout lock replay is not blocked on IO ========================================================== 16:47:48 (1763156868) [ 3938.279790] Lustre: Failing over lustre-MDT0000 [ 3938.633370] LustreError: 96538:0:(obd_class.h:479:obd_check_dev()) Device 27 not setup [ 3938.636706] LustreError: 96538:0:(obd_class.h:479:obd_check_dev()) Skipped 87 previous similar messages [ 3938.689905] Lustre: server umount lustre-MDT0000 complete [ 3940.833819] 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 [ 3940.843941] Lustre: Skipped 41 previous similar messages [ 3952.661611] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3952.921087] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 3952.928590] Lustre: Skipped 11 previous similar messages [ 3954.690474] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 3956.425235] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 3956.429241] Lustre: Skipped 11 previous similar messages [ 3960.534965] Lustre: lustre-MDT0000: Recovery over after 0:04, of 3 clients 3 recovered and 0 were evicted. [ 3960.541739] Lustre: Skipped 11 previous similar messages [ 3960.570782] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2469 to 0x280000401:2497) [ 3960.570881] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2469 to 0x2c0000401:2497) [ 3962.086962] Lustre: DEBUG MARKER: oleg110-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3962.797801] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3966.975774] Lustre: DEBUG MARKER: == replay-dual test 31: deadlock on file_remove_privs and occupied mod rpc slots ========================================================== 16:48:18 (1763156898) [ 3968.678979] Lustre: Failing over lustre-OST0000 [ 3968.737760] Lustre: server umount lustre-OST0000 complete [ 3981.996313] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 3984.556437] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 3988.170832] Lustre: DEBUG MARKER: oleg110-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 3988.933372] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in IDLE [ 3993.863382] Lustre: DEBUG MARKER: == replay-dual test 32: gap in update llog shouldn't break recovery ========================================================== 16:48:45 (1763156925) [ 3994.448119] Lustre: *** cfs_fail_loc=131d, val=10*** [ 3994.971721] Lustre: *** cfs_fail_loc=131d, val=4294967288*** [ 3994.973882] Lustre: Skipped 17 previous similar messages [ 3996.460127] Lustre: Failing over lustre-MDT0001 [ 3996.616538] Lustre: server umount lustre-MDT0001 complete [ 3998.410524] Lustre: Failing over lustre-MDT0000 [ 3998.722279] Lustre: server umount lustre-MDT0000 complete [ 4002.147707] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4002.230613] LustreError: MGC192.168.201.110@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4002.239680] LustreError: Skipped 6 previous similar messages [ 4002.391747] Lustre: *** cfs_fail_loc=131d, val=4294967266*** [ 4002.393865] Lustre: Skipped 21 previous similar messages [ 4004.220269] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 4007.766035] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 4007.851444] Lustre: *** cfs_fail_loc=131d, val=4294967262*** [ 4007.853678] Lustre: Skipped 3 previous similar messages [ 4007.910715] Lustre: lustre-MDT0001: Not available for connect from 0@lo (not set up) [ 4007.914068] Lustre: Skipped 1 previous similar message [ 4009.973878] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 4013.063438] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:496 to 0x2c0000400:513) [ 4013.063613] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:496 to 0x280000400:513) [ 4013.088691] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2537 to 0x280000401:2625) [ 4013.088967] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2469 to 0x2c0000401:2529) [ 4017.733694] Lustre: DEBUG MARKER: == replay-dual test 33: Check for OBD_INCOMPAT_MULTI_RPCS in last_rcvd after abort_recovery ========================================================== 16:49:09 (1763156949) [ 4020.936832] Lustre: Failing over lustre-MDT0001 [ 4021.036148] Lustre: server umount lustre-MDT0001 complete [ 4035.363214] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 4037.229432] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 4039.410767] Lustre: DEBUG MARKER: oleg110-client.virtnet: executing wait_import_state_mount REPLAY_WAIT mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 4040.062987] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in REPLAY_WAIT state after 0 sec [ 4040.440905] Lustre: lustre-MDT0001: Aborting client recovery [ 4040.443233] LustreError: 102445:0:(ldlm_lib.c:2982:target_stop_recovery_thread()) lustre-MDT0001: Aborting recovery [ 4040.446939] Lustre: 101926:0:(ldlm_lib.c:2385:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 4040.450869] Lustre: 101926:0:(ldlm_lib.c:2385:target_recovery_overseer()) Skipped 2 previous similar messages [ 4040.454810] Lustre: 101926:0:(genops.c:1618:class_disconnect_stale_exports()) lustre-MDT0001: disconnect stale client 22967d86-5840-445c-8302-3654fd31131b@ [ 4040.460116] Lustre: lustre-MDT0001: disconnecting 2 stale clients [ 4040.468628] Lustre: lustre-MDT0001-osd: cancel update llog [0x240000400:0x1:0x0] [ 4040.475408] Lustre: lustre-MDT0000-osp-MDT0001: cancel update llog [0x200000401:0x1:0x0] [ 4040.509854] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:496 to 0x2c0000400:545) [ 4040.510373] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:496 to 0x280000400:545) [ 4041.983886] Lustre: DEBUG MARKER: oleg110-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 4042.660736] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4043.895601] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0001.recovery_status 1475 [ 4049.714952] Lustre: Failing over lustre-MDT0001 [ 4049.814531] Lustre: server umount lustre-MDT0001 complete [ 4053.447234] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 4055.399021] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing set_default_debug -1 all [ 4056.375084] Lustre: lustre-MDT0001: Denying connection for new client 13e4e652-fe06-4830-94fb-eabe8eeaced3 (at 192.168.201.10@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 2:17 [ 4057.876674] Lustre: DEBUG MARKER: oleg110-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 4059.134740] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:496 to 0x280000400:577) [ 4059.134830] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:496 to 0x2c0000400:577) [ 4060.588735] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 2 sec [ 4061.879680] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0001.recovery_status 1475 [ 4065.193145] Lustre: DEBUG MARKER: == replay-dual test complete, duration 3881 sec ========== 16:49:57 (1763156997) [ 4065.851086] Lustre: DEBUG MARKER: === replay-dual: start cleanup 16:49:57 (1763156997) === [ 4070.045887] Lustre: DEBUG MARKER: === replay-dual: finish cleanup 16:50:01 (1763157001) === [ 4106.279229] Lustre: server umount lustre-MDT0000 complete [ 4109.659859] LustreError: 90956:0:(ldlm_lockd.c:2563:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1763157041 with bad export cookie 12481373273178933770 [ 4109.664853] LustreError: 90956:0:(ldlm_lockd.c:2563:ldlm_cancel_handler()) Skipped 3 previous similar messages [ 4109.803211] Lustre: server umount lustre-MDT0001 complete [ 4177.806122] Lustre: server umount lustre-OST0000 complete [ 4245.865585] Lustre: server umount lustre-OST0001 complete [ 4252.538677] Lustre: DEBUG MARKER: oleg110-server.virtnet: executing unload_modules_local [ 4253.827684] Key type lgssc unregistered [ 4254.010487] LNet: 106708:0:(lib-ptl.c:967:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 4254.014221] LNetError: 106708:0:(acceptor.c:264:lnet_acceptor_remove_socket()) Interface ens2 not found [ 4254.023726] LNet: Removed LNI 192.168.201.110@tcp [ 4254.449220] Key type .llcrypt unregistered [ 4254.450901] Key type ._llcrypt unregistered