[ 0.000000] Linux version 4.18.0rh8.10-debug (green@maintenance) (gcc version 8.5.0 20210514 (Red Hat 8.5.0-26) (GCC)) #2 SMP Mon Jul 14 01:24:22 EDT 2025 [ 0.000000] Command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers' [ 0.000000] x86/fpu: xstate_offset[2]: 576, xstate_sizes[2]: 256 [ 0.000000] x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'standard' format. [ 0.000000] signal: max sigframe size: 1776 [ 0.000000] BIOS-provided physical RAM map: [ 0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable [ 0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000000100000-0x00000000bffcdfff] usable [ 0.000000] BIOS-e820: [mem 0x00000000bffce000-0x00000000bfffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000100000000-0x0000000146dfffff] usable [ 0.000000] NX (Execute Disable) protection: active [ 0.000000] SMBIOS 2.8 present. [ 0.000000] DMI: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.17.0-10.fc44 06/10/2025 [ 0.000000] Hypervisor detected: KVM [ 0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00 [ 0.000000] kvm-clock: using sched offset of 473385004 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2399.998 MHz processor [ 0.000000] last_pfn = 0x146e00 max_arch_pfn = 0x400000000 [ 0.000000] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT [ 0.000000] last_pfn = 0xbffce max_arch_pfn = 0x400000000 [ 0.000000] found SMP MP-table at [mem 0x000f54b0-0x000f54bf] [ 0.000000] RAMDISK: [mem 0xbcc54000-0xbffbffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F52D0 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE247C 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE2318 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 0022D8 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE238C 000090 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE241C 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE2454 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe2318-0xbffe238b] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe2317] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe238c-0xbffe241b] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe241c-0xbffe2453] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe2454-0xbffe247b] [ 0.000000] No NUMA configuration found [ 0.000000] Faking a node at [mem 0x0000000000000000-0x0000000146dfffff] [ 0.000000] NODE_DATA(0) allocated [mem 0x1465a3000-0x1465cdfff] [ 0.000000] Reserving 256MB of memory at 2752MB for crashkernel (System RAM: 4205MB) [ 0.000000] Zone ranges: [ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.000000] DMA32 [mem 0x0000000001000000-0x00000000ffffffff] [ 0.000000] Normal [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Device empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff] [ 0.000000] node 0: [mem 0x0000000000100000-0x00000000bffcdfff] [ 0.000000] node 0: [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Zeroed struct page in unavailable ranges: 4756 pages [ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x0000000146dfffff] [ 0.000000] ACPI: PM-Timer IO Port: 0x608 [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) [ 0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) [ 0.000000] Using ACPI (MADT) for SMP configuration information [ 0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000] TSC deadline timer available [ 0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs [ 0.000000] kvm-guest: KVM setup pv remote TLB flush [ 0.000000] kvm-guest: setup PV sched yield [ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff] [ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff] [ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff] [ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff] [ 0.000000] PM: Registered nosave memory: [mem 0xbffce000-0xbfffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xc0000000-0xfeffbfff] [ 0.000000] PM: Registered nosave memory: [mem 0xfeffc000-0xfeffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xff000000-0xfffbffff] [ 0.000000] PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff] [ 0.000000] [mem 0xc0000000-0xfeffbfff] available for PCI devices [ 0.000000] Booting paravirtualized kernel on KVM [ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns [ 0.000000] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1 [ 0.000000] percpu: Embedded 63 pages/cpu s221184 r8192 d28672 u524288 [ 0.000000] kvm-guest: PV spinlocks enabled [ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1059606 [ 0.000000] Policy zone: Normal [ 0.000000] Kernel command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] Specific versions of hardware are certified with Red Hat Enterprise Linux 8. Please see the list of hardware certified with Red Hat Enterprise Linux 8 at https://catalog.redhat.com. [ 0.000000] audit: disabled (until reboot) [ 0.000000] software IO TLB: area num 4. [ 0.000000] Memory: 2829652K/4306352K available (18435K kernel code, 11221K rwdata, 7248K rodata, 2908K init, 18040K bss, 524584K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] ftrace: allocating 41240 entries in 162 pages [ 0.000000] ftrace: allocated 162 pages with 3 groups [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] rcu: RCU event tracing is enabled. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ 0.000000] rcu: RCU callback double-/use-after-free debug enabled. [ 0.000000] Rude variant of Tasks RCU enabled. [ 0.000000] Tracing variant of Tasks RCU enabled. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 0.000000] NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16 [ 0.000000] random: get_random_bytes called from start_kernel+0x622/0x9a8 with crng_init=0 [ 0.001000] Console: colour *CGA 80x25 [ 0.001000] printk: console [ttyS1] enabled [ 0.001000] ACPI: Core revision 20220331 [ 0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.001011] APIC: Switch to symmetric I/O mode setup [ 0.003079] x2apic enabled [ 0.004006] Switched APIC routing to physical x2apic. [ 0.005011] kvm-guest: setup PV IPIs [ 0.008000] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.008000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.008020] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.009013] pid_max: default: 32768 minimum: 301 [ 0.011116] LSM: Security Framework initializing [ 0.012059] Yama: becoming mindful. [ 0.013033] SELinux: Initializing. [ 0.014067] *** VALIDATE selinux *** [ 0.022514] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.027013] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.029141] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.030108] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.031110] *** VALIDATE tmpfs *** [ 0.033430] *** VALIDATE proc *** [ 0.034244] *** VALIDATE cgroup *** [ 0.035014] *** VALIDATE cgroup2 *** [ 0.037251] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.038151] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.039011] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.040032] Spectre V2 : User space: Vulnerable [ 0.041012] Speculative Store Bypass: Vulnerable [ 0.044275] debug: unmapping init [mem 0xffffffffa8659000-0xffffffffa8660fff] [ 0.046994] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.047697] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.048024] ... version: 2 [ 0.049015] ... bit width: 48 [ 0.050014] ... generic registers: 4 [ 0.051013] ... value mask: 0000ffffffffffff [ 0.052015] ... max period: 00007fffffffffff [ 0.053014] ... fixed-purpose events: 3 [ 0.054014] ... event mask: 000000070000000f [ 0.055263] rcu: Hierarchical SRCU implementation. [ 0.057392] smp: Bringing up secondary CPUs ... [ 0.058593] x86: Booting SMP configuration: [ 0.059025] .... node #0, CPUs: #1 #2 #3 [ 0.062408] smp: Brought up 1 node, 4 CPUs [ 0.064016] smpboot: Max logical packages: 1 [ 0.065017] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.140037] node 0 deferred pages initialised in 72ms [ 0.143135] devtmpfs: initialized [ 0.145226] x86/mm: Memory block size: 128MB [ 0.148091] gcov: version magic: 0x41383552 [ 0.150366] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.154078] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.157291] pinctrl core: initialized pinctrl subsystem [ 0.159167] [ 0.159830] ************************************************************* [ 0.162026] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.165013] ** ** [ 0.167012] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.170017] ** ** [ 0.173013] ** This means that this kernel is built to expose internal ** [ 0.175011] ** IOMMU data structures, which may compromise security on ** [ 0.178014] ** your system. ** [ 0.180016] ** ** [ 0.183013] ** If you see this message and you are not debugging the ** [ 0.185015] ** kernel, report this immediately to your vendor! ** [ 0.188014] ** ** [ 0.190013] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.193018] ************************************************************* [ 0.196193] NET: Registered protocol family 16 [ 0.198490] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.201060] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.204066] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.208072] cpuidle: using governor menu [ 0.209846] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.212418] PCI: Using configuration type 1 for base access [ 0.214119] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.224067] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.225019] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.227134] cryptd: max_cpu_qlen set to 1000 [ 0.232112] ACPI: Added _OSI(Module Device) [ 0.233015] ACPI: Added _OSI(Processor Device) [ 0.235012] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.236012] ACPI: Added _OSI(Processor Aggregator Device) [ 0.241252] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.248293] ACPI: Interpreter enabled [ 0.249118] ACPI: PM: (supports S0 S3 S4 S5) [ 0.251013] ACPI: Using IOAPIC for interrupt routing [ 0.253090] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.256440] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.266828] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.269042] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.272016] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.276072] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.280247] acpiphp: Slot [2] registered [ 0.281155] acpiphp: Slot [5] registered [ 0.283078] acpiphp: Slot [6] registered [ 0.284122] acpiphp: Slot [7] registered [ 0.286122] acpiphp: Slot [8] registered [ 0.288127] acpiphp: Slot [9] registered [ 0.289128] acpiphp: Slot [10] registered [ 0.291123] acpiphp: Slot [3] registered [ 0.292122] acpiphp: Slot [4] registered [ 0.294127] acpiphp: Slot [11] registered [ 0.296168] acpiphp: Slot [12] registered [ 0.297090] acpiphp: Slot [13] registered [ 0.299124] acpiphp: Slot [14] registered [ 0.300105] acpiphp: Slot [15] registered [ 0.302193] acpiphp: Slot [16] registered [ 0.303105] acpiphp: Slot [17] registered [ 0.305088] acpiphp: Slot [18] registered [ 0.306078] acpiphp: Slot [19] registered [ 0.308104] acpiphp: Slot [20] registered [ 0.309101] acpiphp: Slot [21] registered [ 0.310107] acpiphp: Slot [22] registered [ 0.312107] acpiphp: Slot [23] registered [ 0.313122] acpiphp: Slot [24] registered [ 0.315109] acpiphp: Slot [25] registered [ 0.316101] acpiphp: Slot [26] registered [ 0.318105] acpiphp: Slot [27] registered [ 0.320103] acpiphp: Slot [28] registered [ 0.321119] acpiphp: Slot [29] registered [ 0.322099] acpiphp: Slot [30] registered [ 0.324105] acpiphp: Slot [31] registered [ 0.325070] PCI host bridge to bus 0000:00 [ 0.327021] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.329028] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.332025] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.335023] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.338026] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.341025] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.343190] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.346554] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.347000] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.358015] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.363568] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.366019] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.368015] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.370014] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.372398] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.374639] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.377051] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.379682] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.385012] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.399874] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.404015] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.409498] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.415016] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.421016] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.436016] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.444344] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.456016] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.466011] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.480017] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.490167] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.496015] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.505017] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.526017] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.538739] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.546015] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.558016] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.584014] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.597120] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.604027] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.613018] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.637015] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 0.647750] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.655016] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.662016] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.680018] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 0.694608] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.697343] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.699447] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.701347] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.704209] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.708087] iommu: Default domain type: Passthrough [ 0.711219] SCSI subsystem initialized [ 0.712156] ACPI: bus type USB registered [ 0.714128] usbcore: registered new interface driver usbfs [ 0.716083] usbcore: registered new interface driver hub [ 0.717084] usbcore: registered new device driver usb [ 0.719160] pps_core: LinuxPPS API ver. 1 registered [ 0.721016] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.725060] PTP clock support registered [ 0.726127] EDAC MC: Ver: 3.0.0 [ 0.728121] PCI: Using ACPI for IRQ routing [ 0.730836] NetLabel: Initializing [ 0.732010] NetLabel: domain hash size = 128 [ 0.733008] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.735093] NetLabel: unlabeled traffic allowed by default [ 0.737089] vgaarb: loaded [ 0.738259] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.740012] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.746663] clocksource: Switched to clocksource kvm-clock [ 0.854594] VFS: Disk quotas dquot_6.6.0 [ 0.856136] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.859068] *** VALIDATE ramfs *** [ 0.860461] *** VALIDATE hugetlbfs *** [ 0.862211] pnp: PnP ACPI init [ 0.864784] pnp: PnP ACPI: found 6 devices [ 0.884913] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.888274] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.890226] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.891860] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.894398] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.896446] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.898611] NET: Registered protocol family 2 [ 0.901034] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.905407] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.908772] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.913545] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.916683] TCP: Hash tables configured (established 65536 bind 65536) [ 0.919298] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.922250] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.925112] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.927743] NET: Registered protocol family 1 [ 0.931327] RPC: Registered named UNIX socket transport module. [ 0.933501] RPC: Registered udp transport module. [ 0.935220] RPC: Registered tcp transport module. [ 0.936875] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.939044] NET: Registered protocol family 44 [ 0.940617] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.942878] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.944973] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.947485] PCI: CLS 0 bytes, default 64 [ 0.949212] Unpacking initramfs... [ 2.332863] debug: unmapping init [mem 0xffff99273cc54000-0xffff99273ffbffff] [ 2.336315] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.338981] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.341671] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 2.838214] Initialise system trusted keyrings [ 2.839876] Key type blacklist registered [ 2.841521] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.850201] zbud: loaded [ 2.854173] *** VALIDATE nfs *** [ 2.855521] *** VALIDATE nfs4 *** [ 2.856895] pstore: using deflate compression [ 2.860399] Platform Keyring initialized [ 2.969092] NET: Registered protocol family 38 [ 2.970753] Key type asymmetric registered [ 2.972506] Asymmetric key parser 'x509' registered [ 2.974244] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 2.977379] io scheduler mq-deadline registered [ 2.978913] io scheduler kyber registered [ 2.980691] io scheduler bfq registered [ 2.982584] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 2.985565] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 2.988360] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 2.991083] ACPI: Power Button [PWRF] [ 2.996429] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 3.004161] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 3.018449] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 3.024897] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 3.046690] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 3.077027] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.107097] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.110900] Non-volatile memory driver v1.3 [ 3.112332] Linux agpgart interface v0.103 [ 3.143616] virtio_blk virtio1: [vda] 149376 512-byte logical blocks (76.5 MB/72.9 MiB) [ 3.146426] vda: detected capacity change from 0 to 76480512 [ 3.161174] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.163926] vdb: detected capacity change from 0 to 1073741824 [ 3.179185] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.181837] vdc: detected capacity change from 0 to 2621440000 [ 3.200386] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.203606] vdd: detected capacity change from 0 to 2621440000 [ 3.227565] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.230450] vde: detected capacity change from 0 to 4294967296 [ 3.250691] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.253568] vdf: detected capacity change from 0 to 4294967296 [ 3.261906] libphy: Fixed MDIO Bus: probed [ 3.271458] usbcore: registered new interface driver usbserial_generic [ 3.273836] usbserial: USB Serial support registered for generic [ 3.276138] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.280655] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.282364] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.284604] mousedev: PS/2 mouse device common for all mice [ 3.287737] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.289645] rtc_cmos 00:05: RTC can wake from S4 [ 3.294359] rtc_cmos 00:05: registered as rtc0 [ 3.295847] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.296914] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.303960] intel_pstate: CPU model not supported [ 3.305637] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.311711] hid: raw HID events driver (C) Jiri Kosina [ 3.314052] usbcore: registered new interface driver usbhid [ 3.316137] usbhid: USB HID core driver [ 3.317691] drop_monitor: Initializing network drop monitor service [ 3.320220] Initializing XFRM netlink socket [ 3.322454] NET: Registered protocol family 10 [ 3.325720] Segment Routing with IPv6 [ 3.327188] NET: Registered protocol family 17 [ 3.329559] mpls_gso: MPLS GSO support [ 3.335319] RAS: Correctable Errors collector initialized. [ 3.337445] AVX version of gcm_enc/dec engaged. [ 3.339398] AES CTR mode by8 optimization enabled [ 3.409965] sched_clock: Marking stable (3409936151, 0)->(4319563874, -909627723) [ 3.413193] registered taskstats version 1 [ 3.415335] Loading compiled-in X.509 certificates [ 3.417241] zswap: loaded using pool lzo/zbud [ 3.441956] Key type big_key registered [ 3.457951] Key type encrypted registered [ 3.459645] ima: No TPM chip found, activating TPM-bypass! [ 3.461520] ima: Allocated hash algorithm: sha1 [ 3.463287] ima: No architecture policies found [ 3.464987] evm: Initialising EVM extended attributes: [ 3.466928] evm: security.selinux [ 3.468255] evm: security.ima [ 3.469419] evm: security.capability [ 3.470642] evm: HMAC attrs: 0x1 [ 3.473337] rtc_cmos 00:05: setting system clock to 2026-08-22 10:10:37 UTC (1787393437) [ 3.480989] debug: unmapping init [mem 0xffffffffa9603000-0xffffffffa97fffff] [ 3.484701] debug: unmapping init [mem 0xffffffffa8382000-0xffffffffa8658fff] [ 3.494103] Write protecting the kernel read-only data: 28672k [ 3.497338] debug: unmapping init [mem 0xffffffffa6a03000-0xffffffffa6bfffff] [ 3.500132] debug: unmapping init [mem 0xffffffffa7314000-0xffffffffa73fffff] [ 3.537407] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 3.546303] systemd[1]: Detected virtualization kvm. [ 3.548762] systemd[1]: Detected architecture x86-64. [ 3.550818] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.573607] systemd[1]: No hostname configured. [ 3.575468] systemd[1]: Set hostname to . [ 3.577567] random: systemd: uninitialized urandom read (16 bytes read) [ 3.579952] systemd[1]: Initializing machine ID from random generator. [ 3.621112] random: ln: uninitialized urandom read (6 bytes read) [ 3.719084] random: systemd: uninitialized urandom read (16 bytes read) [ 3.721193] systemd[1]: Reached target Initrd Root Device. [ OK ] Reached target Initrd Root Device. [ 3.725778] systemd[1]: Reached target Timers. [ OK ] Reached target Timers. [ 3.730216] systemd[1]: Listening on udev Control Socket. [ OK ] Listening on udev Control Socket. [ OK ] Listening on Journal Socket. [ OK ] Started Memstrack Anylazing Service. Starting Setup Virtual Console... Starting Create list of required st…ce nodes for the current kernel... Starting Apply Kernel Variables... [ OK ] Reached target Swap. [ OK ] Reached target Slices. [ OK ] Listening on udev Kernel Socket. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. [ OK ] Reached target Local File Systems. Starting Create Volatile Files and Directories... [ OK ] Listening on Journal Socket (/dev/log). Starting Journal Service... [ OK ] Reached target Sockets. [ OK ] Started Setup Virtual Console. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Apply Kernel Variables. [ OK ] Started Create Volatile Files and Directories. Starting Create Static Device Nodes in /dev... Starting dracut cmdline hook... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started Journal Service. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 4.367666] device-mapper: uevent: version 1.0.3 [ 4.369634] device-mapper: ioctl: 4.46.0-ioctl (2022-02-22) initialised: dm-devel@redhat.com [ OK ] Started dracut pre-udev hook. Starting udev Kernel Device Manager... [ OK ] Started udev Kernel Device Manager. Starting dracut pre-trigger hook... [ OK ] Started dracut pre-trigger hook. Starting udev Coldplug all Devices... Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. Starting dracut initqueue hook... [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ 5.103783] virtio_net virtio0 ens2: renamed from eth0 [ 5.161799] random: fast init done [ 5.191063] scsi host0: ata_piix [ 5.226813] scsi host1: ata_piix [ 5.229293] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 5.231870] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 8.946300] dracut-initqueue[583]: RTNETLINK answers: File exists [ 9.976849] random: crng init done [ 9.978348] random: 7 urandom warning(s) missed due to ratelimiting Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. Mounting /sysroot... [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. [ 10.444774] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped target Timers. [ 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 dracut initqueue hook. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Paths. [ OK ] Stopped target Sockets. [ OK ] Stopped target Slices. [ OK ] Stopped target System Initialization. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. Stopping udev Kernel Device Manager... [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Swap. [ OK ] Stopped target Local File Systems. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Closed udev Control Socket. [ OK ] Closed udev Kernel Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 11.643766] printk: systemd: 26 output lines suppressed due to ratelimiting [ 11.936471] SELinux: Disabled at runtime. [ 12.000851] 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.010171] systemd[1]: Detected virtualization kvm. [ 12.011754] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 12.565983] systemd[1]: initrd-switch-root.service: Succeeded. [ 12.569933] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 12.575348] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 12.579452] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 12.582808] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 12.593262] systemd[1]: Starting Journal Service... Starting Journal Service... [ 12.598813] systemd[1]: proc-sys-fs-binfmt_misc.automount: Refusing to start, unit to trigger not loaded. [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Listening on udev Kernel Socket. [ OK ] Listening on RPCbind Server Activation Socket. Mounting Kernel Debug File System... Mounting Huge Pages File System... [ OK ] Created slice system-getty.slice. [ OK ] Reached target RPC Port Mapper. Mounting POSIX Message Queue File System... Activating swap /dev/disk/by-label/SWAP... Starting Apply Kernel Variables... Starting Remount Root and Kernel File Systems... Starting Create list of required st…ce nodes for the current kernel... [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd Root File System. [ OK ] Listening on udev Control Socket. [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Reached target rpc_pipefs.target. [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Started Forward Password Requests to Wall Directory Watch. [ 12.710798] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS [ OK ] Stopped target Initrd File Systems. [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Listening on Process Core Dump Socket. Starting udev Coldplug all Devices... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Paths. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Created slice User and Session Slice. [ OK ] Reached target Slices. [ OK ] Started Journal Service. [ OK ] Mounted Kernel Debug File System. [ OK ] Mounted Huge Pages File System. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Started Apply Kernel Variables. [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. Starting Configure read-only root support... Starting Create Static Device Nodes in /dev... [ OK ] Reached target Swap. Starting Flush Journal to Persistent Storage... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Reached target Local File Systems (Pre). Mounting /home/green/git/lustre-release... Mounting /mnt... Starting udev Kernel Device Manager... [ OK ] Mounted /mnt. [ 13.087313] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Started udev Coldplug all Devices. [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 13.474468] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 13.526563] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 13.578282] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 13.604236] EDAC sbridge: Ver: 1.1.2 [ 15.433189] Key type dns_resolver registered [ 15.770196] NFS: Registering the id_resolver key type [ 15.774081] Key type id_resolver registered [ 15.775791] Key type id_legacy registered [ OK ] Started Configure read-only root support. Starting Load/Save Random Seed... [ OK ] Reached target Local File Systems. Starting Rebuild Dynamic Linker Cache... Starting Create Volatile Files and Directories... Starting Mark the need to relabel after reboot... [ OK ] Started Load/Save Random Seed. [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Create Volatile Files and Directories. Starting RPC Bind... Starting Update UTMP about System Boot/Shutdown... [ OK ] Started RPC Bind. [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Started D-Bus System Message Bus. [ OK ] Started dnf makecache --timer. [ OK ] Reached target sshd-keygen.target. [ OK ] Started irqbalance daemon. [ OK ] Started daily update of the root trust anchor for DNSSEC. Starting Network Manager... Starting Login Service... [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Reached target Timers. Starting Restore /run/initramfs on shutdown... [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Login Service. [ OK ] Started Network Manager. Starting Network Manager Wait Online... [ OK ] Reached target Network. Starting Dynamic System Tuning Daemon... Starting GSSAPI Proxy Daemon... Starting OpenSSH server daemon... Starting Hostname Service... [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... [ OK ] Started OpenSSH server daemon. [ OK ] Started Permit User Sessions. [ OK ] Started 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 Notify NFS peers of a restart... Starting System Logging Service... Starting Crash recovery kernel arming... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Starting Authorization Manager... [ OK ] Started Authorization Manager. [ OK ] Started Dynamic System Tuning Daemon. [ OK ] Reached target Multi-User System. [ OK ] Reached target Graphical Interface. Starting Update UTMP about System Runlevel Changes... [ OK ] Started Update UTMP about System Runlevel Changes. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg651-server login: [ 41.899910] libcfs: loading out-of-tree module taints kernel. [ 41.919387] Key type ._llcrypt registered [ 41.921075] Key type .llcrypt registered [ 41.978364] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_hostid [ 53.907465] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing load_modules_local [ 55.255721] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 55.272103] alg: No test for adler32 (adler32-zlib) [ 56.756405] Lustre: Lustre: Build Version: 2.17.54_107_g42be189 [ 57.634865] LNet: Added LNI 192.168.206.151@tcp [8/256/0/180] [ 59.417080] Key type lgssc registered [ 61.133860] Lustre: Echo OBD driver; http://www.lustre.org/ [ 80.364857] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 118.217734] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing load_modules_local [ 132.167901] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 132.215579] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 133.581797] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 133.676556] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 133.832542] Lustre: lustre-MDT0000: new disk, initializing [ 133.954164] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 133.995828] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 137.535840] hrtimer: interrupt took 6782109 ns [ 138.900840] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 153.449592] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 153.535196] Lustre: 6488:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 153.575760] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 153.582874] Lustre: Skipped 1 previous similar message [ 153.661534] Lustre: lustre-MDT0001: new disk, initializing [ 153.737443] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 153.775737] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 153.783700] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 158.610777] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 163.725726] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 175.120109] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 175.395877] Lustre: lustre-OST0000: new disk, initializing [ 175.399467] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 175.406622] Lustre: 8427:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 175.473021] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 181.323054] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 181.332915] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 181.436616] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 181.909973] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 196.850211] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 197.011480] Lustre: lustre-OST0001: new disk, initializing [ 197.019459] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 197.027776] Lustre: 9499:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 197.135585] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 202.801516] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 202.824781] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 202.894223] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 204.056522] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 217.732148] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 226.257792] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 234.065950] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing check_logdir /tmp/testlogs/ [ 239.040996] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing yml_node [ 243.724918] Lustre: DEBUG MARKER: Client: 2.17.54.107 [ 246.175835] Lustre: DEBUG MARKER: MDS: 2.17.54.107 [ 248.919511] Lustre: DEBUG MARKER: OSS: 2.17.54.107 [ 250.833627] Lustre: DEBUG MARKER: -----============= acceptance-small: replay-dual ============----- Sat Aug 22 06:14:43 EDT 2026 [ 270.459079] Lustre: DEBUG MARKER: excepting tests: 14b 21b [ 272.195971] Lustre: DEBUG MARKER: skipping tests SLOW=no: 21b [ 274.625487] Lustre: DEBUG MARKER: === replay-dual: start setup 06:15:06 (1787393706) === [ 282.504170] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing check_config_client /mnt/lustre [ 303.175644] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 306.671422] Lustre: 13359:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 310.497629] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 315.654641] Lustre: DEBUG MARKER: === replay-dual: finish setup 06:15:48 (1787393748) === [ 317.168944] Lustre: DEBUG MARKER: == replay-dual test 0a: expired recovery with lost client ========================================================== 06:15:50 (1787393750) [ 325.996467] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 331.135841] Lustre: Failing over lustre-MDT0000 [ 331.481908] Lustre: server umount lustre-MDT0000 complete [ 333.281927] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 333.308158] 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 [ 335.844201] 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 [ 335.866291] Lustre: Skipped 2 previous similar messages [ 336.786844] LustreError: 6496:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.206.51@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 336.810704] LustreError: 6496:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 9 previous similar messages [ 340.974786] 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. [ 340.986033] LustreError: 6500:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 3 previous similar messages [ 346.089897] LustreError: 6497: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. [ 346.115043] LustreError: 6497:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 5 previous similar messages [ 351.203223] LustreError: 6496: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. [ 351.232305] LustreError: 6496:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 5 previous similar messages [ 352.208140] Lustre: 3621:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787393769/real 1787393769] req@ffff992684bbd500 x1874217917339776/t0(0) o400->MGC192.168.206.151@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1787393785 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 352.250322] LustreError: MGC192.168.206.151@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 354.463264] LDISKFS-fs (dm-0): 10 truncates cleaned up [ 354.466942] LDISKFS-fs (dm-0): recovery complete [ 354.500329] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 357.348385] 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. [ 357.378787] LustreError: 6500:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 9 previous similar messages [ 362.773724] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 362.890127] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 367.061519] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 368.138679] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 470.511213] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 470.524160] Lustre: 14905:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client b5faac4e-5505-49f5-87ac-708d8b8bf97f@192.168.206.51@tcp [ 470.570362] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 470.588640] Lustre: lustre-MDT0000-osp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 470.591384] Lustre: 14905:0:(ldlm_lib.c:2937:target_recovery_thread()) too long recovery - read logs [ 470.595988] Lustre: Skipped 2 previous similar messages [ 470.613867] LustreError: dumping log to /tmp/lustre-log.1787393904.14905 [ 470.755343] Lustre: lustre-MDT0000: Recovery over after 1:48, of 3 clients 2 recovered and 1 was evicted. [ 470.795215] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:28 to 0x2c0000401:65) [ 470.798729] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:28 to 0x280000401:65) [ 493.467071] Lustre: DEBUG MARKER: == replay-dual test 0b: lost client during waiting for next transno ========================================================== 06:18:46 (1787393926) [ 501.701287] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 504.089154] Lustre: Failing over lustre-MDT0000 [ 504.253029] Lustre: lustre-MDT0000: Not available for connect from 192.168.206.51@tcp (stopping) [ 504.453989] Lustre: server umount lustre-MDT0000 complete [ 506.338512] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 506.342544] 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 [ 506.354424] LustreError: 12324: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. [ 506.366370] Lustre: Skipped 3 previous similar messages [ 506.404689] LustreError: 12324:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 9 previous similar messages [ 522.724456] Lustre: 3621:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787393940/real 1787393940] req@ffff9926858f9c00 x1874217917421056/t0(0) o400->MGC192.168.206.151@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1787393956 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 522.765663] LustreError: MGC192.168.206.151@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 522.782594] 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. [ 522.798289] LustreError: 6500:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 18 previous similar messages [ 526.173507] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 526.178532] LDISKFS-fs (dm-0): recovery complete [ 526.192136] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 532.976715] LustreError: 3620:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff99279f354000 x1874217917430528/t0(0) o250->MGC192.168.206.151@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 [ 533.285446] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 535.947147] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 537.444292] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 538.618418] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 539.629115] Lustre: lustre-MDT0000: Client 5718fb46-3ddc-4dde-b1a4-7354abe597a9 (at 192.168.206.51@tcp) reconnected, waiting for 3 clients in recovery for 1:05 [ 550.600848] Lustre: lustre-MDT0000: Denying connection for new client 8762c7e0-dd83-49c3-95b9-be02a12d2e3e (at 192.168.206.51@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:54 [ 555.910649] Lustre: lustre-MDT0000: Denying connection for new client 8762c7e0-dd83-49c3-95b9-be02a12d2e3e (at 192.168.206.51@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:49 [ 561.044721] Lustre: lustre-MDT0000: Denying connection for new client 8762c7e0-dd83-49c3-95b9-be02a12d2e3e (at 192.168.206.51@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:44 [ 566.155905] Lustre: lustre-MDT0000: Denying connection for new client 8762c7e0-dd83-49c3-95b9-be02a12d2e3e (at 192.168.206.51@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:39 [ 569.321464] Lustre: lustre-MDT0001: haven't heard from client b5faac4e-5505-49f5-87ac-708d8b8bf97f (at 192.168.206.51@tcp) in 102 seconds. I think it's dead, and I am evicting it. exp ffff99268307c800, cur 1787394003 deadline 1787394001 last 1787393901 [ 571.278612] Lustre: lustre-MDT0000: Denying connection for new client 8762c7e0-dd83-49c3-95b9-be02a12d2e3e (at 192.168.206.51@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:34 [ 581.511634] Lustre: lustre-MDT0000: Denying connection for new client 8762c7e0-dd83-49c3-95b9-be02a12d2e3e (at 192.168.206.51@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:23 [ 581.530455] Lustre: Skipped 1 previous similar message [ 601.989256] Lustre: lustre-MDT0000: Denying connection for new client 8762c7e0-dd83-49c3-95b9-be02a12d2e3e (at 192.168.206.51@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 0 evicted) to recover in 0:03 [ 602.019395] Lustre: Skipped 3 previous similar messages [ 605.500755] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 605.510169] Lustre: 16648:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client d66a00d6-8c1a-4c81-99fa-93a087aff407@ [ 605.524529] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 637.828841] Lustre: lustre-MDT0000: Denying connection for new client 8762c7e0-dd83-49c3-95b9-be02a12d2e3e (at 192.168.206.51@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 1 evicted) to recover in 1:08 [ 637.847660] Lustre: lustre-MDT0001: haven't heard from client 5718fb46-3ddc-4dde-b1a4-7354abe597a9 (at 192.168.206.51@tcp) in 102 seconds. I think it's dead, and I am evicting it. exp ffff9927bb2ae000, cur 1787394071 deadline 1787394069 last 1787393969 [ 637.856547] Lustre: Skipped 6 previous similar messages [ 704.393788] Lustre: lustre-MDT0000: Denying connection for new client 8762c7e0-dd83-49c3-95b9-be02a12d2e3e (at 192.168.206.51@tcp), waiting for 3 known clients (1 recovered, 1 in progress, and 1 evicted) to recover in 0:02 [ 704.417714] Lustre: Skipped 12 previous similar messages [ 706.506768] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 706.511056] Lustre: 16648:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 5718fb46-3ddc-4dde-b1a4-7354abe597a9@192.168.206.51@tcp [ 706.528790] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 706.547637] Lustre: 16648:0:(ldlm_lib.c:2071:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 706.572753] Lustre: lustre-MDT0000-osp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 706.574020] Lustre: 16648:0:(ldlm_lib.c:2937:target_recovery_thread()) too long recovery - read logs [ 706.580068] Lustre: Skipped 2 previous similar messages [ 706.604117] LustreError: dumping log to /tmp/lustre-log.1787394140.16648 [ 706.672992] Lustre: lustre-MDT0000: Recovery over after 2:51, of 3 clients 1 recovered and 2 were evicted. [ 706.720565] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:28 to 0x2c0000401:97) [ 706.724356] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:28 to 0x280000401:97) [ 716.829594] Lustre: DEBUG MARKER: == replay-dual test 1: |X| simple create ================= 06:22:29 (1787394149) [ 724.213257] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 726.730201] Lustre: Failing over lustre-MDT0000 [ 727.016151] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 727.030875] 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 [ 727.051499] 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. [ 727.066363] LustreError: 6500:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 16 previous similar messages [ 727.142805] Lustre: server umount lustre-MDT0000 complete [ 744.418120] Lustre: 3623:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787394162/real 1787394162] req@ffff9926858ad880 x1874217917520000/t0(0) o400->MGC192.168.206.151@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1787394178 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 744.430183] LustreError: MGC192.168.206.151@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 750.763315] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 750.769519] LDISKFS-fs (dm-0): recovery complete [ 750.793264] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 754.657804] LustreError: 3620:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9927b5550000 x1874217917528448/t0(0) o250->MGC192.168.206.151@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 [ 754.946023] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 755.004549] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 756.106549] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 760.276516] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 760.311403] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 760.514845] Lustre: lustre-MDT0000: Recovery over after 0:04, of 3 clients 3 recovered and 0 were evicted. [ 760.569285] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:129) [ 760.569304] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:129) [ 770.884629] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 772.428624] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 782.037963] Lustre: DEBUG MARKER: == replay-dual test 2: |X| mkdir adir ==================== 06:23:34 (1787394214) [ 789.284243] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 791.252900] Lustre: Failing over lustre-MDT0000 [ 791.526652] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 791.530942] 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 [ 791.554364] Lustre: Skipped 3 previous similar messages [ 791.565615] LustreError: 11200: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. [ 791.584639] LustreError: 11200:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 42 previous similar messages [ 791.659499] Lustre: server umount lustre-MDT0000 complete [ 812.512219] Lustre: 3622:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787394230/real 1787394230] req@ffff992783847480 x1874217917558016/t0(0) o400->MGC192.168.206.151@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1787394246 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 812.557780] LustreError: MGC192.168.206.151@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 814.147360] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 814.151249] LDISKFS-fs (dm-0): recovery complete [ 814.160403] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 823.860809] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xa7ced98b0c8770d5 [ 823.874565] Lustre: MGC192.168.206.151@tcp: Connection restored to 0@lo (at 0@lo) [ 823.885228] Lustre: Skipped 3 previous similar messages [ 824.268124] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 824.318294] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 825.493603] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 828.184126] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 829.553886] Lustre: lustre-MDT0000: Recovery over after 0:04, of 3 clients 3 recovered and 0 were evicted. [ 829.601452] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:161) [ 829.610858] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:161) [ 838.096688] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 839.913867] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 848.401885] Lustre: DEBUG MARKER: == replay-dual test 3: |X| mkdir adir, mkdir adir/bdir === 06:24:40 (1787394280) [ 855.875643] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 858.011141] Lustre: Failing over lustre-MDT0000 [ 858.613452] Lustre: server umount lustre-MDT0000 complete [ 860.134959] 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 [ 860.149093] Lustre: Skipped 4 previous similar messages [ 876.523402] Lustre: 3622:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787394294/real 1787394294] req@ffff992683098e00 x1874217917598464/t0(0) o400->MGC192.168.206.151@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1787394310 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 876.585527] LustreError: MGC192.168.206.151@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 882.705379] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 882.710596] LDISKFS-fs (dm-0): recovery complete [ 882.740042] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 887.337617] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 888.216229] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 892.410824] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 892.429042] Lustre: Skipped 4 previous similar messages [ 892.532459] Lustre: lustre-MDT0000: Recovery over after 0:04, of 3 clients 3 recovered and 0 were evicted. [ 892.599392] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:193) [ 892.603765] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:193) [ 893.121571] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 902.368993] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 904.204127] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 912.336785] Lustre: DEBUG MARKER: == replay-dual test 4: |X| mkdir adir (-EEXIST), mkdir adir/bdir ========================================================== 06:25:45 (1787394345) [ 920.836204] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 922.724858] Lustre: Failing over lustre-MDT0000 [ 922.915690] Lustre: server umount lustre-MDT0000 complete [ 923.105978] 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 [ 923.122760] Lustre: Skipped 2 previous similar messages [ 923.127111] LustreError: 6497: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. [ 923.143318] LustreError: 6497:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 89 previous similar messages [ 939.488092] Lustre: 3623:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787394357/real 1787394357] req@ffff99279f355880 x1874217917638144/t0(0) o400->MGC192.168.206.151@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1787394373 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 939.529370] LustreError: MGC192.168.206.151@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 947.879038] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 947.883231] LDISKFS-fs (dm-0): recovery complete [ 947.898201] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 949.088124] LustreError: 24181:0:(import.c:339:ptlrpc_invalidate_import()) MGS: timeout waiting for callback (1 != 0) [ 949.102961] LustreError: 24181:0:(import.c:363:ptlrpc_invalidate_import()) @@@ still on sending list req@ffff992684c1e680 x1874217917644160/t0(0) o250->MGC192.168.206.151@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 1787394383 ref 1 fl Rpc:NQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 949.160055] LustreError: 24181:0:(import.c:373:ptlrpc_invalidate_import()) MGS: Unregistering RPCs found (0). Network is sluggish? Waiting for them to error out. [ 950.162345] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 950.172647] Lustre: Skipped 1 previous similar message [ 950.243220] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 950.661195] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 955.273955] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 955.382624] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 955.397010] Lustre: Skipped 3 previous similar messages [ 955.480085] Lustre: lustre-MDT0000: Recovery over after 0:05, of 3 clients 3 recovered and 0 were evicted. [ 955.537526] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:225) [ 955.539176] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:225) [ 965.406968] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 967.115813] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 976.061576] Lustre: DEBUG MARKER: == replay-dual test 5: open, unlink |X| close ============ 06:26:48 (1787394408) [ 983.998442] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 986.107382] Lustre: Failing over lustre-MDT0000 [ 986.596881] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 986.609211] 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 [ 986.618111] Lustre: Skipped 3 previous similar messages [ 986.661959] Lustre: server umount lustre-MDT0000 complete [ 1007.056215] Lustre: 3622:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787394425/real 1787394425] req@ffff9927b3cb5500 x1874217917676288/t0(0) o400->MGC192.168.206.151@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1787394441 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1007.092994] LustreError: MGC192.168.206.151@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1009.179533] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1009.181683] LDISKFS-fs (dm-0): recovery complete [ 1009.191956] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1017.770091] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1019.091697] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 1022.479369] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 1022.973362] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1022.985423] Lustre: Skipped 3 previous similar messages [ 1023.110896] Lustre: lustre-MDT0000: Recovery over after 0:04, of 3 clients 3 recovered and 0 were evicted. [ 1023.188637] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:257) [ 1023.188705] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:257) [ 1032.621569] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1034.637948] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1043.698872] Lustre: DEBUG MARKER: == replay-dual test 6: open1, open2, unlink |X| close1 [fail mds1] close2 ========================================================== 06:27:56 (1787394476) [ 1051.340526] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1053.500627] Lustre: Failing over lustre-MDT0000 [ 1053.685381] 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 [ 1053.701678] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1053.711697] Lustre: Skipped 5 previous similar messages [ 1053.881729] Lustre: server umount lustre-MDT0000 complete [ 1075.169580] Lustre: 3621:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787394492/real 1787394492] req@ffff9927b5554380 x1874217917712640/t0(0) o400->MGC192.168.206.151@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1787394508 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1075.205856] LustreError: MGC192.168.206.151@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1077.569901] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1077.573356] LDISKFS-fs (dm-0): recovery complete [ 1077.583214] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1085.415622] LustreError: 3620:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff992684e03480 x1874217917721472/t0(0) o250->MGC192.168.206.151@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 [ 1085.803843] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1085.818161] Lustre: Skipped 1 previous similar message [ 1085.896483] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1086.866689] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 1090.576887] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 1091.193713] Lustre: lustre-MDT0000: Recovery over after 0:05, of 3 clients 3 recovered and 0 were evicted. [ 1091.281640] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:289) [ 1091.283324] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:289) [ 1101.004864] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1103.012086] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1112.204225] Lustre: DEBUG MARKER: == replay-dual test 8: replay of resent request ========== 06:29:04 (1787394544) [ 1119.904271] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1121.067608] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 1121.076974] LustreError: 6496:0:(ldlm_lib.c:3332:target_send_reply_msg()) @@@ dropping reply req@ffff9927b73fb100 x1874217903871744/t38654705670(0) o36->8762c7e0-dd83-49c3-95b9-be02a12d2e3e@192.168.206.51@tcp:16/0 lens 512/448 e 0 to 0 dl 1787394566 ref 1 fl Interpret:/200/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 1137.613917] Lustre: lustre-MDT0000: Client 8762c7e0-dd83-49c3-95b9-be02a12d2e3e (at 192.168.206.51@tcp) reconnecting [ 1137.655255] Lustre: 20701:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9927b3cb5500 x1874217903871744/t38654705670(0) o36->8762c7e0-dd83-49c3-95b9-be02a12d2e3e@192.168.206.51@tcp:32/0 lens 512/2880 e 0 to 0 dl 1787394582 ref 1 fl Interpret:/202/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 1141.230720] Lustre: Failing over lustre-MDT0000 [ 1141.543851] Lustre: server umount lustre-MDT0000 complete [ 1158.625023] Lustre: 3622:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787394576/real 1787394576] req@ffff9927bfbbf100 x1874217917757056/t0(0) o400->MGC192.168.206.151@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1787394592 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1158.644913] LustreError: MGC192.168.206.151@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1164.700380] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1164.706370] LDISKFS-fs (dm-0): recovery complete [ 1164.740817] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1168.865946] LustreError: 3620:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff992683352d80 x1874217917765632/t0(0) o250->MGC192.168.206.151@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 [ 1169.352519] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1169.945162] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 1173.891239] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 1174.517793] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 1174.532191] Lustre: Skipped 7 previous similar messages [ 1174.616198] Lustre: lustre-MDT0000: Recovery over after 0:05, of 3 clients 3 recovered and 0 were evicted. [ 1174.658897] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:321) [ 1174.668770] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:321) [ 1182.747737] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1184.346884] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1191.977378] Lustre: DEBUG MARKER: == replay-dual test 9: resending a replayed create ======= 06:30:24 (1787394624) [ 1198.959761] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1201.947303] Lustre: Failing over lustre-MDT0000 [ 1202.307533] Lustre: server umount lustre-MDT0000 complete [ 1205.149121] LustreError: 6496:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.206.51@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1205.168560] LustreError: 6496:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 166 previous similar messages [ 1205.220747] 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 [ 1205.232230] Lustre: Skipped 8 previous similar messages [ 1224.041136] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1224.043072] LDISKFS-fs (dm-0): recovery complete [ 1224.049344] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1231.867792] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xa7ced98b0c879621 [ 1232.284892] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1236.687049] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 1237.528584] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 1237.534115] LustreError: 32143:0:(ldlm_lib.c:3332:target_send_reply_msg()) @@@ dropping reply req@ffff9926848e1880 x1874217903889024/t42949672962(42949672962) o36->8762c7e0-dd83-49c3-95b9-be02a12d2e3e@192.168.206.51@tcp:128/0 lens 528/448 e 0 to 0 dl 1787394678 ref 1 fl Complete:/204/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 1249.692242] Lustre: lustre-MDT0000: Client 8762c7e0-dd83-49c3-95b9-be02a12d2e3e (at 192.168.206.51@tcp) reconnected, waiting for 3 clients in recovery for 1:28 [ 1249.847804] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:353) [ 1249.848487] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:353) [ 1255.878574] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1257.240355] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1266.235365] Lustre: DEBUG MARKER: == replay-dual test 10: resending a replayed unlink ====== 06:31:38 (1787394698) [ 1273.719968] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1276.303930] Lustre: Failing over lustre-MDT0000 [ 1276.566736] Lustre: server umount lustre-MDT0000 complete [ 1294.816598] Lustre: 3623:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787394712/real 1787394712] req@ffff9926848e0700 x1874217917832448/t0(0) o400->MGC192.168.206.151@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1787394728 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1294.852485] Lustre: 3623:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 1294.869248] LustreError: MGC192.168.206.151@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1294.898611] LustreError: Skipped 1 previous similar message [ 1300.844456] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1300.847249] LDISKFS-fs (dm-0): recovery complete [ 1300.859313] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1304.035539] LustreError: 3620:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9927b73fad80 x1874217917840896/t0(0) o250->MGC192.168.206.151@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 [ 1304.463277] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1305.478170] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 1305.495937] Lustre: Skipped 1 previous similar message [ 1309.698213] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 1309.707798] LustreError: 34197:0:(ldlm_lib.c:3332:target_send_reply_msg()) @@@ dropping reply req@ffff9927b73fb800 x1874217903909248/t47244640260(47244640260) o36->8762c7e0-dd83-49c3-95b9-be02a12d2e3e@192.168.206.51@tcp:200/0 lens 528/448 e 0 to 0 dl 1787394750 ref 1 fl Complete:/204/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 1309.767661] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 1321.891070] Lustre: lustre-MDT0000: Client 8762c7e0-dd83-49c3-95b9-be02a12d2e3e (at 192.168.206.51@tcp) reconnected, waiting for 3 clients in recovery for 1:28 [ 1321.985711] Lustre: lustre-MDT0000: Recovery over after 0:16, of 3 clients 3 recovered and 0 were evicted. [ 1321.989586] Lustre: Skipped 1 previous similar message [ 1322.033815] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:385) [ 1322.036599] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:385) [ 1328.662707] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1330.367681] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1339.512847] Lustre: DEBUG MARKER: == replay-dual test 11: both clients timeout during replay ========================================================== 06:32:52 (1787394772) [ 1346.217294] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1348.916419] Lustre: Failing over lustre-MDT0000 [ 1349.170831] Lustre: server umount lustre-MDT0000 complete [ 1372.710161] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1372.713188] LDISKFS-fs (dm-0): recovery complete [ 1372.734552] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1376.239110] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xa7ced98b0c87a2a7 [ 1376.615081] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1376.620917] Lustre: Skipped 3 previous similar messages [ 1380.743763] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 1381.942195] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 1381.945681] LustreError: 36254:0:(ldlm_lib.c:3332:target_send_reply_msg()) @@@ dropping reply req@ffff99278383e680 x1874217903928064/t51539607554(51539607554) o36->8762c7e0-dd83-49c3-95b9-be02a12d2e3e@192.168.206.51@tcp:272/0 lens 528/448 e 0 to 0 dl 1787394822 ref 1 fl Complete:/204/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 1388.909268] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1393.577232] Lustre: lustre-MDT0000: Client 8762c7e0-dd83-49c3-95b9-be02a12d2e3e (at 192.168.206.51@tcp) reconnected, waiting for 3 clients in recovery for 1:28 [ 1393.878258] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:417) [ 1393.878450] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:417) [ 1396.534752] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 5 sec [ 1405.917811] Lustre: DEBUG MARKER: == replay-dual test 12: open resend timeout ============== 06:33:58 (1787394838) [ 1415.466189] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1418.260926] Lustre: Failing over lustre-MDT0000 [ 1418.665888] Lustre: server umount lustre-MDT0000 complete [ 1419.751732] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1442.944876] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1442.949694] LDISKFS-fs (dm-0): recovery complete [ 1442.958373] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1448.418226] LustreError: 3620:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff99268758ad80 x1874217917915904/t0(0) o250->MGC192.168.206.151@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 [ 1448.759564] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1448.771231] Lustre: Skipped 1 previous similar message [ 1453.644483] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 1454.069770] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1454.078898] Lustre: Skipped 17 previous similar messages [ 1454.178551] Lustre: *** cfs_fail_loc=302, val=2147483648*** [ 1470.384423] Lustre: lustre-MDT0000: Client 8762c7e0-dd83-49c3-95b9-be02a12d2e3e (at 192.168.206.51@tcp) reconnected, waiting for 3 clients in recovery for 1:24 [ 1470.599993] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:449) [ 1470.600679] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:449) [ 1479.204354] Lustre: DEBUG MARKER: == replay-dual test 13: close resend timeout ============= 06:35:11 (1787394911) [ 1487.380404] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1490.719747] Lustre: Failing over lustre-MDT0000 [ 1490.917282] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1490.922705] 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 [ 1490.941105] Lustre: Skipped 12 previous similar messages [ 1490.979956] Lustre: server umount lustre-MDT0000 complete [ 1514.480076] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1514.483211] LDISKFS-fs (dm-0): recovery complete [ 1514.489728] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1521.133641] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xa7ced98b0c87af9d [ 1526.370344] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 1526.870179] Lustre: *** cfs_fail_loc=115, val=2147483648*** [ 1542.054709] Lustre: lustre-MDT0000: Client 8762c7e0-dd83-49c3-95b9-be02a12d2e3e (at 192.168.206.51@tcp) reconnected, waiting for 3 clients in recovery for 1:25 [ 1542.180072] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:481) [ 1542.186573] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:99 to 0x280000401:481) [ 1550.273083] Lustre: DEBUG MARKER: SKIP: replay-dual test_14b skipping ALWAYS excluded test 14b [ 1552.580869] Lustre: DEBUG MARKER: == replay-dual test 15a: timeout waiting for lost client during replay, 1 client completes ========================================================== 06:36:24 (1787394984) [ 1561.321690] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1564.865331] Lustre: Failing over lustre-MDT0000 [ 1565.254415] Lustre: server umount lustre-MDT0000 complete [ 1581.520131] Lustre: 3624:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787394999/real 1787394999] req@ffff99279f357100 x1874217917984128/t0(0) o400->MGC192.168.206.151@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1787395015 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1581.550648] Lustre: 3624:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 1581.555820] LustreError: MGC192.168.206.151@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1581.562318] LustreError: Skipped 3 previous similar messages [ 1588.210586] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1588.214102] LDISKFS-fs (dm-0): recovery complete [ 1588.221968] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1591.813040] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xa7ced98b0c87ba24 [ 1593.228260] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 1593.234721] Lustre: Skipped 3 previous similar messages [ 1596.937550] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 1663.500283] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 1663.513140] Lustre: 41928:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 61abea09-d49f-42ff-b5fe-50eb3dc4ab13@ [ 1663.523222] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 1664.312123] Lustre: lustre-MDT0000: Recovery over after 1:11, of 3 clients 2 recovered and 1 was evicted. [ 1664.334793] Lustre: Skipped 3 previous similar messages [ 1664.372173] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:495 to 0x280000401:513) [ 1664.386525] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:494 to 0x2c0000401:513) [ 1670.520595] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1672.076994] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1682.175411] Lustre: DEBUG MARKER: == replay-dual test 15c: remove multiple OST orphans ===== 06:38:34 (1787395114) [ 1690.452984] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1814.194934] Lustre: Failing over lustre-MDT0000 [ 1814.740864] Lustre: server umount lustre-MDT0000 complete [ 1815.533350] LustreError: 12324: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. [ 1815.556406] LustreError: 12324:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 231 previous similar messages [ 1839.487285] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1839.491563] LDISKFS-fs (dm-0): recovery complete [ 1839.500866] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1841.128778] LustreError: 3620:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff99268323fb80 x1874217918116480/t0(0) o250->MGC192.168.206.151@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 [ 1841.588685] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1841.608172] Lustre: Skipped 2 previous similar messages [ 1846.518329] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 1915.502788] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 1915.508204] Lustre: 43941:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 01b333ba-c88a-48b3-8c17-c76be5a49fc6@ [ 1915.525721] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 1915.656831] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:494 to 0x2c0000401:1537) [ 1915.661824] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:495 to 0x280000401:1537) [ 1922.740152] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1924.541301] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1934.981893] Lustre: DEBUG MARKER: == replay-dual test 16: fail MDS during recovery (3571) == 06:42:47 (1787395367) [ 1943.208869] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1946.904931] Lustre: Failing over lustre-MDT0000 [ 1947.228789] Lustre: server umount lustre-MDT0000 complete [ 1971.682930] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 1971.688084] LDISKFS-fs (dm-0): recovery complete [ 1971.698360] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1975.780506] LustreError: 3620:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9927c19e3b80 x1874217918179584/t0(0) o250->MGC192.168.206.151@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 [ 1976.148697] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1976.157567] Lustre: Skipped 4 previous similar messages [ 1980.994972] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 1981.441401] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1981.449045] Lustre: Skipped 17 previous similar messages [ 2006.854161] Lustre: Failing over lustre-MDT0000 [ 2006.866905] LustreError: 46391:0:(ldlm_lib.c:2990:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 2006.880513] Lustre: 45916:0:(ldlm_lib.c:2390:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 2006.887465] Lustre: 45916:0:(ldlm_lib.c:1900:abort_req_replay_queue()) @@@ aborted: req@ffff9927bfa7ed80 x1874217906384640/t0(73014444033) o36->8762c7e0-dd83-49c3-95b9-be02a12d2e3e@192.168.206.51@tcp:140/0 lens 528/0 e 2 to 0 dl 1787395445 ref 1 fl Complete:/204/ffffffff rc 0/-1 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 2006.910463] Lustre: lustre-MDT0000-osd: cancel update llog [0x200000400:0x1:0x0] [ 2006.934185] Lustre: lustre-MDT0000: Not available for connect from 192.168.206.51@tcp (stopping) [ 2006.946414] Lustre: lustre-MDT0001-osp-MDT0000: cancel update llog [0x240000401:0x1:0x0] [ 2006.949182] Lustre: Skipped 3 previous similar messages [ 2006.971230] LustreError: 45916:0:(client.c:1381:ptlrpc_import_delay_req()) @@@ IMP_CLOSED req@ffff99279f35b100 x1874217918202368/t0(0) o700->lustre-MDT0001-osp-MDT0000@0@lo:30/10 lens 264/248 e 0 to 0 dl 0 ref 2 fl Rpc:QU/200/ffffffff rc 0/-1 job:'tgt_recover_0.0' uid:0 gid:0 projid:4294967295 [ 2007.006183] LustreError: 45916:0:(fid_request.c:217:seq_client_alloc_seq()) cli-cli-lustre-MDT0001-osp-MDT0000: Cannot allocate new meta-sequence: rc = -5 [ 2007.010211] 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 [ 2007.023984] LustreError: 45916:0:(fid_request.c:321:seq_client_alloc_fid()) cli-cli-lustre-MDT0001-osp-MDT0000: Can't allocate new sequence: rc = -5 [ 2007.087601] Lustre: Skipped 17 previous similar messages [ 2007.566273] Lustre: server umount lustre-MDT0000 complete [ 2028.039769] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2028.439759] Lustre: lustre-MDT0000: Not available for connect from 192.168.206.51@tcp (not set up) [ 2028.452420] Lustre: Skipped 3 previous similar messages [ 2033.678291] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 2100.503868] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 2100.506753] Lustre: 46849:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client bfada57b-481c-41fc-b19d-a1a1c715e622@ [ 2100.516923] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 2101.457783] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1551 to 0x2c0000401:1569) [ 2101.458860] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1550 to 0x280000401:1569) [ 2108.613803] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2110.874627] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2126.069405] Lustre: DEBUG MARKER: == replay-dual test 17: fail OST during recovery (3571) == 06:45:57 (1787395557) [ 2136.313531] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 2138.883101] Lustre: Failing over lustre-OST0000 [ 2139.066567] Lustre: server umount lustre-OST0000 complete [ 2160.988620] LDISKFS-fs (dm-2): 3 truncates cleaned up [ 2161.002231] LDISKFS-fs (dm-2): recovery complete [ 2161.011501] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2162.477400] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 4 clients reconnect [ 2162.496855] Lustre: Skipped 3 previous similar messages [ 2167.405178] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 2192.226950] Lustre: Failing over lustre-OST0000 [ 2192.238426] LustreError: 49366:0:(ldlm_lib.c:2990:target_stop_recovery_thread()) lustre-OST0000: Aborting recovery [ 2192.251052] Lustre: 48803:0:(ldlm_lib.c:2390:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 2192.259612] Lustre: 48803:0:(ldlm_lib.c:2390:target_recovery_overseer()) Skipped 2 previous similar messages [ 2192.271710] LustreError: 48803:0:(ofd_obd.c:1324:ofd_iocontrol()) lustre-OST0000: iocontrol from 'tgt_recover_0' cmd=c00866c1 _IOWR('f', 193, 8) unrecognized: rc = -25 [ 2192.288686] Lustre: lustre-OST0000: Recovery over after 0:30, of 4 clients 0 recovered and 4 were evicted. [ 2192.301192] Lustre: Skipped 3 previous similar messages [ 2192.478823] Lustre: server umount lustre-OST0000 complete [ 2202.593951] Lustre: 3620:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787395596/real 1787395596] req@ffff99268323ce00 x1874217918280704/t0(0) o400->lustre-OST0000-osc-MDT0000@0@lo:28/4 lens 224/224 e 2 to 1 dl 1787395636 ref 1 fl Rpc:XQr/2c0/ffffffff rc 0/-1 job:'ldlm_lock_repla.0' uid:0 gid:0 projid:4294967295 [ 2202.622191] Lustre: 3620:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 2212.531911] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2219.307933] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 2284.500229] Lustre: lustre-OST0000: recovery is timed out, evict stale exports [ 2284.512717] Lustre: 49805:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-OST0000: disconnect stale client efcc62fd-4e12-429f-820d-487fb051ec26@ [ 2284.527886] Lustre: lustre-OST0000: disconnecting 1 stale clients [ 2291.127627] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 2292.740448] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 2302.854869] Lustre: DEBUG MARKER: == replay-dual test 18: ldlm_handle_enqueue succeeds on evicted export (3822) ========================================================== 06:48:55 (1787395735) [ 2307.218141] LustreError: 7717:0:(ldlm_lockd.c:1361:ldlm_handle_enqueue()) cfs_fail_timeout id 30b sleeping for 40000ms [ 2347.248169] LustreError: 7717:0:(ldlm_lockd.c:1361:ldlm_handle_enqueue()) cfs_fail_timeout id 30b awake [ 2363.034624] Lustre: DEBUG MARKER: == replay-dual test 19: resend of open request =========== 06:49:55 (1787395795) [ 2371.779593] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2373.399071] Lustre: *** cfs_fail_loc=157, val=2147483648*** [ 2373.405785] LustreError: 6495:0:(ldlm_lib.c:3332:target_send_reply_msg()) @@@ dropping reply req@ffff992683098380 x1874217906512000/t0(0) o101->8762c7e0-dd83-49c3-95b9-be02a12d2e3e@192.168.206.51@tcp:584/0 lens 576/688 e 0 to 0 dl 1787395889 ref 1 fl Interpret:/600/0 rc 0/0 job:'createmany.0' uid:0 gid:0 projid:0 [ 2460.057875] Lustre: lustre-MDT0000: Client 8762c7e0-dd83-49c3-95b9-be02a12d2e3e (at 192.168.206.51@tcp) reconnecting [ 2463.814739] Lustre: Failing over lustre-MDT0000 [ 2464.255619] Lustre: server umount lustre-MDT0000 complete [ 2465.215572] LustreError: 12324:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.206.51@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 2465.250146] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 2465.255677] LustreError: 12324:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 102 previous similar messages [ 2481.122116] LustreError: MGC192.168.206.151@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2481.131662] LustreError: Skipped 3 previous similar messages [ 2487.147633] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2487.154565] LDISKFS-fs (dm-0): recovery complete [ 2487.162031] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2491.825701] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 2491.832615] Lustre: Skipped 4 previous similar messages [ 2496.413303] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 2497.063822] Lustre: 52456:0:(ldlm_lib.c:2071:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 2497.325071] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1584 to 0x2c0000401:1601) [ 2497.325425] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1584 to 0x280000401:1601) [ 2506.697711] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2508.650480] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2517.686245] Lustre: DEBUG MARKER: == replay-dual test 20: recovery time is not increasing == 06:52:30 (1787395950) [ 2526.270744] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2529.135145] Lustre: Failing over lustre-MDT0000 [ 2529.506413] Lustre: server umount lustre-MDT0000 complete [ 2554.244101] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2554.253652] LDISKFS-fs (dm-0): recovery complete [ 2554.278698] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2556.397714] LustreError: 3620:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9927b54d6d80 x1874217918462336/t0(0) o250->MGC192.168.206.151@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 [ 2561.681375] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 2698.500540] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 2698.508829] Lustre: 54393:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 4221e6f8-ba26-4b5f-bc3d-2c232a1a9b72@ [ 2698.531824] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 2698.590134] Lustre: 54393:0:(ldlm_lib.c:2071:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 2698.603989] Lustre: 54393:0:(ldlm_lib.c:2071:extend_recovery_timer()) Skipped 6 previous similar messages [ 2698.704286] Lustre: lustre-MDT0000-osp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 2698.715068] Lustre: Skipped 15 previous similar messages [ 2698.750845] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1603 to 0x280000401:1633) [ 2698.755698] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1584 to 0x2c0000401:1633) [ 2705.450227] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2707.171329] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2717.525384] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2719.468232] Lustre: Failing over lustre-MDT0000 [ 2719.763665] Lustre: server umount lustre-MDT0000 complete [ 2720.747984] 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 [ 2720.776310] Lustre: Skipped 12 previous similar messages [ 2742.760946] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2742.766691] LDISKFS-fs (dm-0): recovery complete [ 2742.775273] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2746.341507] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xa7ced98b0c89e921 [ 2746.717484] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 2746.724487] Lustre: Skipped 5 previous similar messages [ 2751.079474] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 2889.503503] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 2889.512205] Lustre: 56177:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 3555a61b-aa15-485a-97a7-850ce88bc170@ [ 2889.522817] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 2889.575882] Lustre: 56177:0:(ldlm_lib.c:2071:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 2889.595889] Lustre: 56177:0:(ldlm_lib.c:2071:extend_recovery_timer()) Skipped 4 previous similar messages [ 2889.735124] Lustre: lustre-MDT0000: Recovery over after 2:21, of 3 clients 2 recovered and 1 was evicted. [ 2889.753552] Lustre: Skipped 3 previous similar messages [ 2889.799958] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1584 to 0x2c0000401:1665) [ 2889.800939] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1635 to 0x280000401:1665) [ 2895.964394] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2897.615881] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2907.408448] Lustre: DEBUG MARKER: == replay-dual test 21a: commit on sharing =============== 06:58:59 (1787396339) [ 2915.877876] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2917.974574] Lustre: Failing over lustre-MDT0000 [ 2918.230553] Lustre: server umount lustre-MDT0000 complete [ 2920.419882] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 2936.293312] Lustre: 3621:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787396354/real 1787396354] req@ffff9927afe44700 x1874217918618752/t0(0) o400->MGC192.168.206.151@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1787396370 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2936.330882] Lustre: 3621:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 4 previous similar messages [ 2940.585592] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 2940.590741] LDISKFS-fs (dm-0): recovery complete [ 2940.603236] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2946.537754] LustreError: 3620:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9927bb13c380 x1874217918627072/t0(0) o250->MGC192.168.206.151@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 [ 2947.746375] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 2947.764352] Lustre: Skipped 4 previous similar messages [ 2952.289261] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 3087.500449] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 3087.508396] Lustre: 58203:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client c77b8053-6555-445d-b24c-ced96e2b5f14@ [ 3087.522646] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 3087.584155] Lustre: 58203:0:(ldlm_lib.c:2071:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3087.595549] Lustre: 58203:0:(ldlm_lib.c:2071:extend_recovery_timer()) Skipped 4 previous similar messages [ 3087.726454] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1584 to 0x2c0000401:1697) [ 3087.726898] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1667 to 0x280000401:1697) [ 3098.918527] Lustre: DEBUG MARKER: SKIP: replay-dual test_21b skipping SLOW test 21b [ 3101.457391] Lustre: DEBUG MARKER: == replay-dual test 22a: c1 lfs mkdir -i 1 dir1, M1 drop reply [ 3102.831275] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 3102.837725] LustreError: 20701:0:(ldlm_lib.c:3332:target_send_reply_msg()) @@@ dropping reply req@ffff9927c1255f80 x1874217906632960/t4294967333(0) o36->8762c7e0-dd83-49c3-95b9-be02a12d2e3e@192.168.206.51@tcp:557/0 lens 560/448 e 0 to 0 dl 1787396617 ref 1 fl Interpret:/200/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 3106.126098] Lustre: Failing over lustre-MDT0001 [ 3106.438240] Lustre: server umount lustre-MDT0001 complete [ 3108.835627] LustreError: 6497:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0001: not available for connect from 192.168.206.51@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3108.853828] LustreError: 6497:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 126 previous similar messages [ 3110.889207] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 3125.419482] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3125.837923] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 3125.854156] Lustre: Skipped 3 previous similar messages [ 3130.179257] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 3130.909914] Lustre: 6495:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9927afe40e00 x1874217906632960/t4294967333(0) o36->8762c7e0-dd83-49c3-95b9-be02a12d2e3e@192.168.206.51@tcp:585/0 lens 560/2880 e 0 to 0 dl 1787396645 ref 1 fl Interpret:/202/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 3139.508110] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 3141.315928] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3150.772242] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3153.276816] Lustre: Failing over lustre-MDT0000 [ 3153.624176] Lustre: server umount lustre-MDT0000 complete [ 3156.474728] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3172.835813] LustreError: MGC192.168.206.151@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3172.842721] LustreError: Skipped 3 previous similar messages [ 3175.490888] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3175.493067] LDISKFS-fs (dm-0): recovery complete [ 3175.498800] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3182.067198] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xa7ced98b0c89f7fa [ 3186.763822] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 3187.747966] Lustre: 61286:0:(ldlm_lib.c:2071:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3187.926356] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1584 to 0x2c0000401:1729) [ 3187.927316] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1667 to 0x280000401:1729) [ 3195.730636] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3197.638954] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3206.903610] Lustre: DEBUG MARKER: == replay-dual test 22b: c1 lfs mkdir -i 1 d1, M1 drop reply [ 3208.140990] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 3208.145823] LustreError: 6496:0:(ldlm_lib.c:3332:target_send_reply_msg()) @@@ dropping reply req@ffff992687c14000 x1874217906673792/t8589934617(0) o36->8762c7e0-dd83-49c3-95b9-be02a12d2e3e@192.168.206.51@tcp:663/0 lens 560/448 e 0 to 0 dl 1787396723 ref 1 fl Interpret:/200/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 3210.969171] Lustre: Failing over lustre-MDT0000 [ 3211.357744] Lustre: server umount lustre-MDT0000 complete [ 3215.297242] LustreError: 9498:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787396649 with bad export cookie 12091841240770410490 [ 3215.301565] Lustre: Failing over lustre-MDT0001 [ 3215.309797] LustreError: 9498:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 3215.335932] LustreError: 62427:0:(client.c:1381:ptlrpc_import_delay_req()) @@@ IMP_CLOSED req@ffff9927c1823480 x1874217918771328/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 [ 3215.378202] LustreError: 62427:0:(osp_object.c:618:osp_attr_get()) lustre-MDT0000-osp-MDT0001: osp_attr_get update error [0x200000401:0x1:0x0]: rc = -5 [ 3215.757340] Lustre: server umount lustre-MDT0001 complete [ 3236.306041] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3236.575238] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3236.660487] LustreError: 63115:0:(llog.c:1655:llog_backup()) MGC192.168.206.151@tcp: failed to open log lustre-sptlrpc: rc = -108 [ 3236.667795] Lustre: 63115:0:(mgc_request_server.c:770:mgc_llog_local_copy()) MGC192.168.206.151@tcp: failed to copy new config lustre-sptlrpc: rc = -108 [ 3240.936556] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xa7ced98b0c89ff40 [ 3246.286526] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 3246.728200] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 3247.699841] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:36 to 0x280000400:65) [ 3247.701892] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:36 to 0x2c0000400:65) [ 3247.719740] Lustre: 63140:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9927c1806300 x1874217906673792/t8589934617(0) o36->8762c7e0-dd83-49c3-95b9-be02a12d2e3e@192.168.206.51@tcp:702/0 lens 560/2880 e 0 to 0 dl 1787396762 ref 1 fl Interpret:/202/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 3254.641641] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1667 to 0x280000401:1761) [ 3254.643248] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1584 to 0x2c0000401:1761) [ 3261.201733] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 3262.515351] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3263.781521] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3274.655989] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3277.585300] Lustre: Failing over lustre-MDT0000 [ 3278.035082] Lustre: server umount lustre-MDT0000 complete [ 3302.680151] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3302.684960] LDISKFS-fs (dm-0): recovery complete [ 3302.695452] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3304.432508] LustreError: 3620:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9926890d8a80 x1874217918816128/t0(0) o250->MGC192.168.206.151@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 [ 3304.455747] LustreError: 3620:0:(client.c:1391:ptlrpc_import_delay_req()) Skipped 1 previous similar message [ 3309.377603] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 3310.059624] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 3310.066365] Lustre: Skipped 24 previous similar messages [ 3310.111066] Lustre: 65362:0:(ldlm_lib.c:2071:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3310.132305] Lustre: 65362:0:(ldlm_lib.c:2071:extend_recovery_timer()) Skipped 4 previous similar messages [ 3310.222830] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1584 to 0x2c0000401:1793) [ 3310.222830] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1667 to 0x280000401:1793) [ 3319.792349] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3321.510612] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3330.623882] Lustre: DEBUG MARKER: == replay-dual test 22c: c1 lfs mkdir -i 1 d1, M1 drop update [ 3331.873704] Lustre: *** cfs_fail_loc=1701, val=2147483648*** [ 3331.880670] LustreError: 8421:0:(ldlm_lib.c:3332:target_send_reply_msg()) @@@ dropping reply req@ffff9927c188c380 x1874217918843008/t107374182411(0) o1000->lustre-MDT0001-mdtlov_UUID@0@lo:716/0 lens 2520/4320 e 0 to 0 dl 1787396776 ref 1 fl Interpret:/200/0 rc 0/0 job:'osp_up0-1.0' uid:0 gid:0 projid:4294967295 [ 3335.680238] Lustre: Failing over lustre-MDT0000 [ 3336.162322] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3336.172682] 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 [ 3336.193739] Lustre: Skipped 22 previous similar messages [ 3336.268370] Lustre: server umount lustre-MDT0000 complete [ 3356.724246] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3357.493938] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3357.506303] Lustre: Skipped 6 previous similar messages [ 3362.763157] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 3362.920086] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1667 to 0x280000401:1825) [ 3362.922982] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1584 to 0x2c0000401:1825) [ 3371.675778] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3373.091530] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3383.167353] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3385.418618] Lustre: Failing over lustre-MDT0000 [ 3385.732200] Lustre: server umount lustre-MDT0000 complete [ 3407.625137] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3407.627210] LDISKFS-fs (dm-0): recovery complete [ 3407.632651] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3414.033433] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xa7ced98b0c8a15ac [ 3419.082969] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 3419.678495] Lustre: 68555:0:(ldlm_lib.c:2071:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3419.701722] Lustre: 68555:0:(ldlm_lib.c:2071:extend_recovery_timer()) Skipped 4 previous similar messages [ 3419.809906] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1667 to 0x280000401:1857) [ 3419.817478] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1584 to 0x2c0000401:1857) [ 3428.482445] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3430.105323] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3438.818556] Lustre: DEBUG MARKER: == replay-dual test 22d: c1 lfs mkdir -i 1 d1, M1 drop update [ 3443.544407] Lustre: *** cfs_fail_loc=1701, val=2147483648*** [ 3443.553912] LustreError: 8420:0:(ldlm_lib.c:3332:target_send_reply_msg()) @@@ dropping reply req@ffff99279e117b80 x1874217918917504/t115964117002(0) o1000->lustre-MDT0001-mdtlov_UUID@0@lo:73/0 lens 2520/4320 e 0 to 0 dl 1787396888 ref 1 fl Interpret:/200/0 rc 0/0 job:'osp_up0-1.0' uid:0 gid:0 projid:4294967295 [ 3447.331767] Lustre: Failing over lustre-MDT0000 [ 3447.655867] Lustre: server umount lustre-MDT0000 complete [ 3451.113651] LustreError: 6481:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787396885 with bad export cookie 12091841240770418092 [ 3451.114654] Lustre: Failing over lustre-MDT0001 [ 3451.128095] LustreError: 6481:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 3451.177476] Lustre: lustre-MDT0001: Not available for connect from 192.168.206.51@tcp (stopping) [ 3452.821371] Lustre: lustre-MDT0001: Not available for connect from 192.168.206.51@tcp (stopping) [ 3452.831321] Lustre: Skipped 1 previous similar message [ 3455.472355] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 3455.487885] Lustre: Skipped 1 previous similar message [ 3457.412669] Lustre: server umount lustre-MDT0001 complete [ 3476.579817] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3476.622642] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3476.978219] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xa7ced98b0c8a1d07 [ 3482.147505] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 3482.451783] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 3482.745085] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1584 to 0x2c0000401:1889) [ 3482.749974] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1667 to 0x280000401:1889) [ 3492.985964] Lustre: lustre-MDT0001: Recovery over after 0:15, of 3 clients 3 recovered and 0 were evicted. [ 3492.994421] Lustre: Skipped 9 previous similar messages [ 3493.037506] Lustre: 71004:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff99278d936680 x1874217906759296/t12884901939(0) o36->8762c7e0-dd83-49c3-95b9-be02a12d2e3e@192.168.206.51@tcp:192/0 lens 560/2880 e 0 to 0 dl 1787397007 ref 1 fl Interpret:/202/0 rc 0/0 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 3493.058406] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:70 to 0x280000400:97) [ 3493.061618] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:70 to 0x2c0000400:97) [ 3498.431966] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 3500.148872] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3501.620224] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3511.828884] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3514.414595] Lustre: Failing over lustre-MDT0000 [ 3514.854305] Lustre: server umount lustre-MDT0000 complete [ 3537.756432] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3537.759265] LDISKFS-fs (dm-0): recovery complete [ 3537.774159] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3542.517646] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xa7ced98b0c8a25c0 [ 3548.168696] Lustre: 72716:0:(ldlm_lib.c:2071:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3548.187082] Lustre: 72716:0:(ldlm_lib.c:2071:extend_recovery_timer()) Skipped 4 previous similar messages [ 3548.332797] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1667 to 0x280000401:1921) [ 3548.338605] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1584 to 0x2c0000401:1921) [ 3548.476072] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 3558.194866] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3560.090260] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3568.910564] Lustre: DEBUG MARKER: == replay-dual test 23a: c1 rmdir d1, M1 drop reply and fail, client2 mkdir d1 ========================================================== 07:10:01 (1787397001) [ 3570.174714] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 3570.185327] LustreError: 71290:0:(ldlm_lib.c:3332:target_send_reply_msg()) @@@ dropping reply req@ffff992683098700 x1874217906802432/t17179869210(0) o36->8762c7e0-dd83-49c3-95b9-be02a12d2e3e@192.168.206.51@tcp:269/0 lens 496/456 e 0 to 0 dl 1787397084 ref 1 fl Interpret:/200/0 rc 0/0 job:'rmdir.0' uid:0 gid:0 projid:4294967295 [ 3573.634201] Lustre: Failing over lustre-MDT0001 [ 3573.737422] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 3573.740388] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 3573.747459] Lustre: Skipped 3 previous similar messages [ 3573.765460] LustreError: Skipped 1 previous similar message [ 3578.854678] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 3578.862901] Lustre: Skipped 5 previous similar messages [ 3579.334487] Lustre: server umount lustre-MDT0001 complete [ 3598.180422] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3600.054331] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 3600.060665] Lustre: Skipped 10 previous similar messages [ 3601.934872] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 3604.093939] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:100 to 0x2c0000400:129) [ 3604.095524] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:100 to 0x280000400:129) [ 3604.107325] Lustre: 70518:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9927afe41c00 x1874217906802432/t17179869210(0) o36->8762c7e0-dd83-49c3-95b9-be02a12d2e3e@192.168.206.51@tcp:303/0 lens 496/2888 e 0 to 0 dl 1787397118 ref 1 fl Interpret:/202/0 rc 0/0 job:'rmdir.0' uid:0 gid:0 projid:4294967295 [ 3612.970234] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 3615.147774] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3624.261475] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3626.365269] Lustre: Failing over lustre-MDT0000 [ 3626.659644] Lustre: server umount lustre-MDT0000 complete [ 3645.992255] Lustre: 3624:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787397063/real 1787397063] req@ffff99279e9a8380 x1874217919031168/t0(0) o400->MGC192.168.206.151@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1787397079 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3646.046746] Lustre: 3624:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 17 previous similar messages [ 3652.018584] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3652.021335] LDISKFS-fs (dm-0): recovery complete [ 3652.041047] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3656.705368] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xa7ced98b0c8a31dd [ 3661.302461] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 3662.356478] Lustre: 75892:0:(ldlm_lib.c:2071:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3662.365230] Lustre: 75892:0:(ldlm_lib.c:2071:extend_recovery_timer()) Skipped 4 previous similar messages [ 3662.603264] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1923 to 0x280000401:1953) [ 3662.606143] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1923 to 0x2c0000401:1953) [ 3670.868361] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3672.830498] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3681.617532] Lustre: DEBUG MARKER: == replay-dual test 23b: c1 rmdir d1, M1 drop reply and fail M0/M1, c2 mkdir d1 ========================================================== 07:11:54 (1787397114) [ 3683.085381] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 3683.092344] LustreError: 74702:0:(ldlm_lib.c:3332:target_send_reply_msg()) @@@ dropping reply req@ffff99268905f800 x1874217906838528/t21474836483(0) o36->8762c7e0-dd83-49c3-95b9-be02a12d2e3e@192.168.206.51@tcp:382/0 lens 496/456 e 0 to 0 dl 1787397197 ref 1 fl Interpret:/200/0 rc 0/0 job:'rmdir.0' uid:0 gid:0 projid:4294967295 [ 3686.285058] Lustre: Failing over lustre-MDT0000 [ 3686.547172] Lustre: server umount lustre-MDT0000 complete [ 3687.918586] LustreError: 6479:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787397121 with bad export cookie 12091841240770425407 [ 3690.204289] LustreError: 6480:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787397124 with bad export cookie 12091841240770425309 [ 3690.209503] Lustre: Failing over lustre-MDT0001 [ 3690.214098] LustreError: 6480:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 3690.673028] Lustre: server umount lustre-MDT0001 complete [ 3711.707944] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3711.727539] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3711.933042] LustreError: 77787:0:(llog.c:1655:llog_backup()) MGC192.168.206.151@tcp: failed to open log lustre-sptlrpc: rc = -108 [ 3711.940774] Lustre: 77787:0:(mgc_request_server.c:770:mgc_llog_local_copy()) MGC192.168.206.151@tcp: failed to copy new config lustre-sptlrpc: rc = -108 [ 3713.356037] LustreError: 77796:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0001: not available for connect from 192.168.206.51@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3713.386567] LustreError: 77796:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 299 previous similar messages [ 3722.428175] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 3722.523837] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:100 to 0x280000400:161) [ 3722.526394] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:100 to 0x2c0000400:161) [ 3722.551849] Lustre: 77795:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff99278d91a680 x1874217906838528/t21474836483(0) o36->8762c7e0-dd83-49c3-95b9-be02a12d2e3e@192.168.206.51@tcp:421/0 lens 496/2888 e 0 to 0 dl 1787397236 ref 1 fl Interpret:/202/0 rc 0/0 job:'rmdir.0' uid:0 gid:0 projid:4294967295 [ 3722.864123] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 3728.987496] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1923 to 0x2c0000401:1985) [ 3728.988505] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1923 to 0x280000401:1985) [ 3736.427823] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 3738.388524] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3740.317405] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3750.349352] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3752.793733] Lustre: Failing over lustre-MDT0000 [ 3753.109658] Lustre: server umount lustre-MDT0000 complete [ 3754.475778] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3754.488064] LustreError: Skipped 1 previous similar message [ 3777.442654] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3777.451307] LDISKFS-fs (dm-0): recovery complete [ 3777.468612] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3780.142981] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xa7ced98b0c8a4150 [ 3780.513315] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 3780.518368] Lustre: Skipped 13 previous similar messages [ 3785.313404] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 3785.950860] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1987 to 0x280000401:2017) [ 3785.955352] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1987 to 0x2c0000401:2017) [ 3794.865597] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3796.775428] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3805.725113] Lustre: DEBUG MARKER: == replay-dual test 23c: c1 rmdir d1, M0 drop update reply and fail M0, c2 mkdir d1 ========================================================== 07:13:58 (1787397238) [ 3807.254776] Lustre: *** cfs_fail_loc=1701, val=2147483648*** [ 3807.263282] LustreError: 8420:0:(ldlm_lib.c:3332:target_send_reply_msg()) @@@ dropping reply req@ffff9926858f9500 x1874217919147392/t137438953491(0) o1000->lustre-MDT0001-mdtlov_UUID@0@lo:437/0 lens 1984/4320 e 0 to 0 dl 1787397252 ref 1 fl Interpret:/200/0 rc 0/0 job:'osp_up0-1.0' uid:0 gid:0 projid:4294967295 [ 3811.345855] Lustre: Failing over lustre-MDT0000 [ 3811.618456] Lustre: server umount lustre-MDT0000 complete [ 3832.219243] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3832.279719] LustreError: MGC192.168.206.151@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3832.289280] LustreError: Skipped 9 previous similar messages [ 3847.730544] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 3848.282129] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1987 to 0x280000401:2049) [ 3848.284629] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1987 to 0x2c0000401:2049) [ 3858.352182] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3860.319742] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3870.340876] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3872.542622] Lustre: Failing over lustre-MDT0000 [ 3872.805200] Lustre: server umount lustre-MDT0000 complete [ 3896.091766] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 3896.096077] LDISKFS-fs (dm-0): recovery complete [ 3896.116836] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3900.321879] LustreError: 83162:0:(import.c:339:ptlrpc_invalidate_import()) MGS: timeout waiting for callback (1 != 0) [ 3900.337186] LustreError: 83162:0:(import.c:363:ptlrpc_invalidate_import()) @@@ still on sending list req@ffff9927c13cc380 x1874217919191552/t0(0) o250->MGC192.168.206.151@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 1787397333 ref 1 fl Rpc:NQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3900.382966] LustreError: 83162:0:(import.c:373:ptlrpc_invalidate_import()) MGS: Unregistering RPCs found (0). Network is sluggish? Waiting for them to error out. [ 3900.901254] LustreError: 3620:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff992688e93800 x1874217919195264/t0(0) o250->MGC192.168.206.151@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 [ 3900.946469] LustreError: 3620:0:(client.c:1391:ptlrpc_import_delay_req()) Skipped 29 previous similar messages [ 3905.740567] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 3906.576633] Lustre: 83195:0:(ldlm_lib.c:2071:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3906.592259] Lustre: 83195:0:(ldlm_lib.c:2071:extend_recovery_timer()) Skipped 17 previous similar messages [ 3906.819203] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2051 to 0x280000401:2081) [ 3906.821063] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2051 to 0x2c0000401:2081) [ 3916.534149] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3918.539533] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3928.409468] Lustre: DEBUG MARKER: == replay-dual test 23d: c1 rmdir d1, M0 drop update reply and fail M0/M1, c2 mkdir d1 ========================================================== 07:16:00 (1787397360) [ 3933.194673] Lustre: *** cfs_fail_loc=1701, val=2147483648*** [ 3933.205435] LustreError: 63792:0:(ldlm_lib.c:3332:target_send_reply_msg()) @@@ dropping reply req@ffff9927b7377050 x1874217919225472/t146028888081(0) o1000->lustre-MDT0001-mdtlov_UUID@0@lo:563/0 lens 1984/4320 e 0 to 0 dl 1787397378 ref 1 fl Interpret:/200/0 rc 0/0 job:'osp_up0-1.0' uid:0 gid:0 projid:4294967295 [ 3936.583045] Lustre: Failing over lustre-MDT0000 [ 3936.861561] Lustre: server umount lustre-MDT0000 complete [ 3937.254446] 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 [ 3937.272257] Lustre: Skipped 45 previous similar messages [ 3940.089216] Lustre: Failing over lustre-MDT0001 [ 3940.092960] LustreError: 6479:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787397374 with bad export cookie 12091841240770432610 [ 3940.099175] LustreError: 84432:0:(ldlm_resource.c:1207:ldlm_resource_complain()) lustre-MDT0000-osp-MDT0001: namespace resource [0x2000013a1:0x81:0x0].0x0 (ffff992798a99800) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 3940.107200] LustreError: 6479:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 3 previous similar messages [ 3940.152743] Lustre: lustre-MDT0001: Not available for connect from 192.168.206.51@tcp (stopping) [ 3946.266484] Lustre: server umount lustre-MDT0001 complete [ 3965.129595] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3965.165210] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3965.931088] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xa7ced98b0c8a55a8 [ 3965.941160] Lustre: MGC192.168.206.151@tcp: Connection restored to 0@lo (at 0@lo) [ 3965.955798] Lustre: Skipped 51 previous similar messages [ 3966.377019] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 3966.383146] Lustre: Skipped 11 previous similar messages [ 3970.966671] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2051 to 0x280000401:2113) [ 3970.971435] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2051 to 0x2c0000401:2113) [ 3971.449861] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 3971.506572] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 3982.937605] Lustre: 85156:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9926896ce300 x1874217906922112/t25769803783(0) o36->8762c7e0-dd83-49c3-95b9-be02a12d2e3e@192.168.206.51@tcp:681/0 lens 496/2888 e 0 to 0 dl 1787397496 ref 1 fl Interpret:/202/0 rc 0/0 job:'rmdir.0' uid:0 gid:0 projid:4294967295 [ 3982.953482] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:100 to 0x2c0000400:193) [ 3982.953782] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:100 to 0x280000400:193) [ 3989.416308] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 3991.103986] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3992.836361] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4002.443650] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4004.743455] Lustre: Failing over lustre-MDT0000 [ 4005.038432] Lustre: server umount lustre-MDT0000 complete [ 4029.661420] LDISKFS-fs (dm-0): 2 truncates cleaned up [ 4029.663533] LDISKFS-fs (dm-0): recovery complete [ 4029.680610] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4031.904244] LustreError: 87348:0:(import.c:339:ptlrpc_invalidate_import()) MGS: timeout waiting for callback (1 != 0) [ 4031.910662] LustreError: 87348:0:(import.c:363:ptlrpc_invalidate_import()) @@@ still on sending list req@ffff992688e92d80 x1874217919271808/t0(0) o250->MGC192.168.206.151@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 1787397465 ref 1 fl Rpc:NQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4031.928710] LustreError: 87348:0:(import.c:373:ptlrpc_invalidate_import()) MGS: Unregistering RPCs found (0). Network is sluggish? Waiting for them to error out. [ 4032.509271] LustreError: 87358:0:(ldlm_resource.c:1207:ldlm_resource_complain()) MGC192.168.206.151@tcp: namespace resource [0x65727473756c:0x5:0x0].0x0 (ffff992785397200) refcount nonzero (2) after lock cleanup; forcing cleanup. [ 4032.541045] LustreError: 87358:0:(ldlm_resource.c:1207:ldlm_resource_complain()) Skipped 1 previous similar message [ 4038.338109] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2115 to 0x2c0000401:2145) [ 4038.368426] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2115 to 0x280000401:2145) [ 4038.587954] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 4047.573206] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4049.318953] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4056.986552] Lustre: DEBUG MARKER: == replay-dual test 24: reconstruct on non-existing object ========================================================== 07:18:09 (1787397489) [ 4057.986156] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 4057.992704] LustreError: 85156:0:(ldlm_lib.c:3332:target_send_reply_msg()) @@@ dropping reply req@ffff9927b73f8e00 x1874217906959360/t154618822673(0) o36->8762c7e0-dd83-49c3-95b9-be02a12d2e3e@192.168.206.51@tcp:2/0 lens 488/456 e 0 to 0 dl 1787397572 ref 1 fl Interpret:/200/0 rc 0/0 job:'truncate.0' uid:0 gid:0 projid:4294967295 [ 4142.469633] Lustre: lustre-MDT0000: Client 8762c7e0-dd83-49c3-95b9-be02a12d2e3e (at 192.168.206.51@tcp) reconnecting [ 4142.502631] Lustre: 88344:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff992681bdd880 x1874217906959360/t154618822673(0) o36->8762c7e0-dd83-49c3-95b9-be02a12d2e3e@192.168.206.51@tcp:86/0 lens 488/3152 e 0 to 0 dl 1787397656 ref 1 fl Interpret:/202/0 rc 0/0 job:'truncate.0' uid:0 gid:0 projid:4294967295 [ 4149.911443] Lustre: DEBUG MARKER: == replay-dual test 25: replay|resend ==================== 07:19:42 (1787397582) [ 4152.358482] Lustre: *** cfs_fail_loc=304, val=0*** [ 4154.562979] Lustre: Failing over lustre-OST0000 [ 4154.664990] Lustre: server umount lustre-OST0000 complete [ 4172.571383] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4174.294196] Lustre: lustre-OST0000: Recovery over after 0:01, of 4 clients 4 recovered and 0 were evicted. [ 4174.317640] Lustre: Skipped 11 previous similar messages [ 4178.723525] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 4188.370867] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 4189.877475] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4198.719798] Lustre: DEBUG MARKER: == replay-dual test 26: dbench and tar with mds failover ========================================================== 07:20:31 (1787397631) [ 4208.068837] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4211.780944] Lustre: DEBUG MARKER: test_26 fail mds1 1 times [ 4213.907601] Lustre: Failing over lustre-MDT0000 [ 4214.164541] Lustre: lustre-MDT0000: Not available for connect from 192.168.206.51@tcp (stopping) [ 4214.170481] Lustre: Skipped 6 previous similar messages [ 4214.330065] Lustre: server umount lustre-MDT0000 complete [ 4217.826474] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4217.836622] LustreError: Skipped 2 previous similar messages [ 4235.827778] LDISKFS-fs (dm-0): 4 truncates cleaned up [ 4235.839433] LDISKFS-fs (dm-0): recovery complete [ 4235.846822] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4245.898962] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 4245.913178] Lustre: Skipped 10 previous similar messages [ 4250.108482] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 4250.638496] Lustre: 91306:0:(ldlm_lib.c:2071:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 4250.652403] Lustre: 91306:0:(ldlm_lib.c:2071:extend_recovery_timer()) Skipped 17 previous similar messages [ 4253.480391] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2183 to 0x2c0000401:2209) [ 4253.481475] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2185 to 0x280000401:2209) [ 4259.691983] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4261.400791] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4273.203917] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 4276.927306] Lustre: DEBUG MARKER: test_26 fail mds2 2 times [ 4278.658588] Lustre: Failing over lustre-MDT0001 [ 4278.715324] Lustre: lustre-MDT0001: Not available for connect from 192.168.206.51@tcp (stopping) [ 4278.911872] Lustre: server umount lustre-MDT0001 complete [ 4300.370740] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 4300.374212] LDISKFS-fs (dm-1): recovery complete [ 4300.394892] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4305.721549] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 4308.884741] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:263 to 0x2c0000400:289) [ 4308.885268] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:263 to 0x280000400:289) [ 4317.474404] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 4320.187314] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4334.325796] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4338.340174] Lustre: DEBUG MARKER: test_26 fail mds1 3 times [ 4340.603399] Lustre: Failing over lustre-MDT0000 [ 4343.175449] Lustre: lustre-MDT0000: Not available for connect from 192.168.206.51@tcp (stopping) [ 4343.186537] Lustre: Skipped 8 previous similar messages [ 4345.902064] Lustre: server umount lustre-MDT0000 complete [ 4347.371592] LustreError: 85929: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. [ 4347.390621] LustreError: 85929:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 268 previous similar messages [ 4363.746138] Lustre: 3623:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787397781/real 1787397781] req@ffff99278961b100 x1874217919777536/t0(0) o400->MGC192.168.206.151@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1787397797 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4363.791150] Lustre: 3623:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 18 previous similar messages [ 4367.175894] LDISKFS-fs (dm-0): 3 truncates cleaned up [ 4367.177701] LDISKFS-fs (dm-0): recovery complete [ 4367.188110] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4374.007371] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xa7ced98b0c8bb266 [ 4374.017821] Lustre: Skipped 1 previous similar message [ 4378.879633] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 4381.722636] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2268 to 0x280000401:2305) [ 4381.723271] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2268 to 0x2c0000401:2305) [ 4390.044866] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4392.258700] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4405.810586] Lustre: DEBUG MARKER: mds2 REPLAY BARRIER on lustre-MDT0001 [ 4409.622822] Lustre: DEBUG MARKER: test_26 fail mds2 4 times [ 4411.697143] Lustre: Failing over lustre-MDT0001 [ 4412.179780] Lustre: server umount lustre-MDT0001 complete [ 4435.098924] LDISKFS-fs (dm-1): 6 truncates cleaned up [ 4435.102035] LDISKFS-fs (dm-1): recovery complete [ 4435.114765] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4435.531055] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 4435.547533] Lustre: Skipped 9 previous similar messages [ 4439.582538] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 4442.254576] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:360 to 0x280000400:385) [ 4442.256031] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:360 to 0x2c0000400:385) [ 4450.088149] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 4452.056319] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4515.577135] Lustre: DEBUG MARKER: == replay-dual test 28: lock replay should be ordered: waiting after granted ========================================================== 07:25:47 (1787397947) [ 4528.133399] Lustre: Failing over lustre-OST0000 [ 4528.139214] Lustre: *** cfs_fail_loc=32a, val=0*** [ 4528.243699] Lustre: server umount lustre-OST0000 complete [ 4546.570171] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4549.016478] Lustre: *** cfs_fail_loc=32a, val=0*** [ 4554.014400] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 4563.774650] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 4565.441276] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4576.035904] Lustre: DEBUG MARKER: == replay-dual test 29: replay vs update with the same xid ========================================================== 07:26:48 (1787398008) [ 4577.525268] Lustre: DEBUG MARKER: SKIP: replay-dual test_29 needs >= 2 clients [ 4578.886410] Lustre: DEBUG MARKER: == replay-dual test 30: layout lock replay is not blocked on IO ========================================================== 07:26:51 (1787398011) [ 4582.118132] Lustre: Failing over lustre-MDT0000 [ 4582.441880] Lustre: server umount lustre-MDT0000 complete [ 4582.883767] 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 [ 4582.896519] Lustre: Skipped 27 previous similar messages [ 4599.983768] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4600.197389] LustreError: MGC192.168.206.151@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4600.211786] LustreError: Skipped 5 previous similar messages [ 4600.546072] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4600.554141] Lustre: Skipped 8 previous similar messages [ 4605.060145] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 4605.945378] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4605.956256] Lustre: Skipped 30 previous similar messages [ 4606.180718] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2371 to 0x280000401:2401) [ 4606.187062] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2370 to 0x2c0000401:2401) [ 4614.796288] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4616.414590] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4624.354276] Lustre: DEBUG MARKER: == replay-dual test 31: deadlock on file_remove_privs and occupied mod rpc slots ========================================================== 07:27:36 (1787398056) [ 4627.816685] Lustre: Failing over lustre-OST0000 [ 4627.867762] Lustre: lustre-OST0000: Not available for connect from 192.168.206.51@tcp (stopping) [ 4628.076283] Lustre: server umount lustre-OST0000 complete [ 4645.267747] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4651.421472] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 4662.515831] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 4664.833844] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL [ 4676.159924] Lustre: DEBUG MARKER: == replay-dual test 32: gap in update llog shouldn't break recovery ========================================================== 07:28:28 (1787398108) [ 4677.499041] Lustre: *** cfs_fail_loc=131d, val=10*** [ 4678.049395] Lustre: *** cfs_fail_loc=131d, val=0*** [ 4678.052867] Lustre: Skipped 9 previous similar messages [ 4679.100126] Lustre: *** cfs_fail_loc=131d, val=4294967274*** [ 4679.103675] Lustre: Skipped 21 previous similar messages [ 4681.470530] Lustre: Failing over lustre-MDT0001 [ 4681.899928] Lustre: server umount lustre-MDT0001 complete [ 4685.574433] Lustre: Failing over lustre-MDT0000 [ 4685.988468] Lustre: server umount lustre-MDT0000 complete [ 4693.556665] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4693.943465] Lustre: *** cfs_fail_loc=131d, val=4294967266*** [ 4693.945969] Lustre: Skipped 7 previous similar messages [ 4698.776280] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 4706.776283] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4706.998430] Lustre: *** cfs_fail_loc=131d, val=4294967262*** [ 4707.007227] Lustre: Skipped 3 previous similar messages [ 4711.846982] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 4712.570833] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:401 to 0x280000400:417) [ 4712.581963] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:400 to 0x2c0000400:417) [ 4712.624130] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2441 to 0x280000401:2529) [ 4712.628287] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2370 to 0x2c0000401:2433) [ 4723.645252] Lustre: DEBUG MARKER: == replay-dual test 33: Check for OBD_INCOMPAT_MULTI_RPCS in last_rcvd after abort_recovery ========================================================== 07:29:16 (1787398156) [ 4729.225768] Lustre: Failing over lustre-MDT0001 [ 4729.453669] Lustre: server umount lustre-MDT0001 complete [ 4732.911936] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 4732.937720] LustreError: Skipped 7 previous similar messages [ 4748.590985] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4753.833160] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 4760.452764] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount REPLAY_WAIT mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 4761.865194] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in REPLAY_WAIT state after 0 sec [ 4762.742256] Lustre: lustre-MDT0001: Aborting client recovery [ 4762.746231] LustreError: 105769:0:(ldlm_lib.c:2990:target_stop_recovery_thread()) lustre-MDT0001: Aborting recovery [ 4762.758660] Lustre: 105136:0:(ldlm_lib.c:2390:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 4762.769407] Lustre: 105136:0:(ldlm_lib.c:2390:target_recovery_overseer()) Skipped 2 previous similar messages [ 4762.778366] Lustre: 105136:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0001: disconnect stale client 5fbd5a8c-9fd9-4f3e-a626-812bca16e5d5@ [ 4762.791328] Lustre: lustre-MDT0001: disconnecting 1 stale clients [ 4762.806210] Lustre: lustre-MDT0001-osd: cancel update llog [0x240000400:0x1:0x0] [ 4762.819258] Lustre: lustre-MDT0000-osp-MDT0001: cancel update llog [0x200000401:0x1:0x0] [ 4762.888200] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:400 to 0x2c0000400:449) [ 4762.891235] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:401 to 0x280000400:449) [ 4768.261517] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 4770.167356] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4774.402823] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0001.recovery_status 1475 [ 4781.269470] Lustre: Failing over lustre-MDT0001 [ 4781.527843] Lustre: server umount lustre-MDT0001 complete [ 4790.556586] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4795.234161] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug -1 all [ 4796.411146] Lustre: lustre-MDT0001: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 4796.422259] Lustre: Skipped 10 previous similar messages [ 4796.473070] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:400 to 0x2c0000400:481) [ 4796.473446] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:401 to 0x280000400:481) [ 4803.052752] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 4804.680644] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4808.421764] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0001.recovery_status 1475 [ 4815.510498] Lustre: DEBUG MARKER: == replay-dual test complete, duration 4563 sec ========== 07:30:48 (1787398248) [ 4817.085718] Lustre: DEBUG MARKER: === replay-dual: start cleanup 07:30:49 (1787398249) === [ 4828.055510] Lustre: DEBUG MARKER: === replay-dual: finish cleanup 07:31:00 (1787398260) === [ 4830.137816] Lustre: Failing over lustre-MDT0000 [ 4830.356672] Lustre: server umount lustre-MDT0000 complete [ 4858.187754] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4859.278369] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 4859.286263] Lustre: Skipped 10 previous similar messages [ 4863.603170] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4999.500782] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 4999.511663] Lustre: 108915:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 5fbd5a8c-9fd9-4f3e-a626-812bca16e5d5@ [ 4999.536866] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 4999.649871] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:2370 to 0x2c0000401:2465) [ 4999.649871] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:2441 to 0x280000401:2561) [ 5007.041811] Lustre: DEBUG MARKER: oleg651-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 5008.599264] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5015.009834] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5015.017067] Lustre: Skipped 3 previous similar messages [ 5021.308649] Lustre: server umount lustre-MDT0000 complete [ 5022.690828] LustreError: 103192: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. [ 5022.705143] LustreError: 103192:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 176 previous similar messages [ 5029.997970] LustreError: 97271:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787398464 with bad export cookie 12091841240770669525 [ 5030.005920] LustreError: 97271:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 5030.407914] Lustre: server umount lustre-MDT0001 complete [ 5048.277437] Lustre: server umount lustre-OST0000 complete [ 5067.868386] Lustre: server umount lustre-OST0001 complete [ 5082.555254] Lustre: DEBUG MARKER: oleg651-server.virtnet: executing unload_modules_local [ 5085.163979] Key type lgssc unregistered [ 5085.445495] LNet: 111855:0:(lib-ptl.c:967:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 5085.450772] LNetError: 111855:0:(acceptor.c:246:lnet_acceptor_remove_socket()) Interface ens2 not found [ 5085.467325] LNet: Removed LNI 192.168.206.151@tcp [ 5086.279188] Key type .llcrypt unregistered [ 5086.281607] Key type ._llcrypt unregistered