[ 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 505544293 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.003202] x2apic enabled [ 0.004009] Switched APIC routing to physical x2apic. [ 0.005014] kvm-guest: setup PV IPIs [ 0.008664] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.009000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.010017] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.011017] pid_max: default: 32768 minimum: 301 [ 0.012137] LSM: Security Framework initializing [ 0.013054] Yama: becoming mindful. [ 0.014040] SELinux: Initializing. [ 0.015081] *** VALIDATE selinux *** [ 0.024286] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.029208] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.031072] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.032106] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.033143] *** VALIDATE tmpfs *** [ 0.034471] *** VALIDATE proc *** [ 0.035252] *** VALIDATE cgroup *** [ 0.036010] *** VALIDATE cgroup2 *** [ 0.037286] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.038162] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.039010] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.040030] Spectre V2 : User space: Vulnerable [ 0.041010] Speculative Store Bypass: Vulnerable [ 0.044059] debug: unmapping init [mem 0xffffffff9c259000-0xffffffff9c260fff] [ 0.046804] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.047719] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.048030] ... version: 2 [ 0.049011] ... bit width: 48 [ 0.050010] ... generic registers: 4 [ 0.051008] ... value mask: 0000ffffffffffff [ 0.052009] ... max period: 00007fffffffffff [ 0.053011] ... fixed-purpose events: 3 [ 0.054014] ... event mask: 000000070000000f [ 0.055312] rcu: Hierarchical SRCU implementation. [ 0.057501] smp: Bringing up secondary CPUs ... [ 0.058647] x86: Booting SMP configuration: [ 0.059027] .... node #0, CPUs: #1 #2 #3 [ 0.062271] smp: Brought up 1 node, 4 CPUs [ 0.063658] smpboot: Max logical packages: 1 [ 0.064010] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.139742] node 0 deferred pages initialised in 70ms [ 0.142016] devtmpfs: initialized [ 0.143260] x86/mm: Memory block size: 128MB [ 0.145878] gcov: version magic: 0x41383552 [ 0.147323] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.148085] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.149230] pinctrl core: initialized pinctrl subsystem [ 0.150141] [ 0.150647] ************************************************************* [ 0.151011] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.152013] ** ** [ 0.153013] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.154017] ** ** [ 0.155013] ** This means that this kernel is built to expose internal ** [ 0.156014] ** IOMMU data structures, which may compromise security on ** [ 0.157017] ** your system. ** [ 0.158018] ** ** [ 0.159013] ** If you see this message and you are not debugging the ** [ 0.160016] ** kernel, report this immediately to your vendor! ** [ 0.161012] ** ** [ 0.162017] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.163022] ************************************************************* [ 0.164887] NET: Registered protocol family 16 [ 0.165522] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.166086] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.167060] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.169041] cpuidle: using governor menu [ 0.170801] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.173510] PCI: Using configuration type 1 for base access [ 0.176129] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.185152] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.186028] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.188033] cryptd: max_cpu_qlen set to 1000 [ 0.191289] ACPI: Added _OSI(Module Device) [ 0.192018] ACPI: Added _OSI(Processor Device) [ 0.193013] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.194018] ACPI: Added _OSI(Processor Aggregator Device) [ 0.198110] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.201281] ACPI: Interpreter enabled [ 0.202054] ACPI: PM: (supports S0 S3 S4 S5) [ 0.203013] ACPI: Using IOAPIC for interrupt routing [ 0.204115] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.205401] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.214888] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.215038] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.216019] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.217077] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.219392] acpiphp: Slot [2] registered [ 0.220181] acpiphp: Slot [5] registered [ 0.221115] acpiphp: Slot [6] registered [ 0.222122] acpiphp: Slot [7] registered [ 0.223100] acpiphp: Slot [8] registered [ 0.224097] acpiphp: Slot [9] registered [ 0.225131] acpiphp: Slot [10] registered [ 0.226173] acpiphp: Slot [3] registered [ 0.227109] acpiphp: Slot [4] registered [ 0.228075] acpiphp: Slot [11] registered [ 0.229066] acpiphp: Slot [12] registered [ 0.229962] acpiphp: Slot [13] registered [ 0.230079] acpiphp: Slot [14] registered [ 0.231092] acpiphp: Slot [15] registered [ 0.232094] acpiphp: Slot [16] registered [ 0.232922] acpiphp: Slot [17] registered [ 0.233049] acpiphp: Slot [18] registered [ 0.233762] acpiphp: Slot [19] registered [ 0.234092] acpiphp: Slot [20] registered [ 0.235108] acpiphp: Slot [21] registered [ 0.236148] acpiphp: Slot [22] registered [ 0.237082] acpiphp: Slot [23] registered [ 0.238091] acpiphp: Slot [24] registered [ 0.239096] acpiphp: Slot [25] registered [ 0.240097] acpiphp: Slot [26] registered [ 0.241099] acpiphp: Slot [27] registered [ 0.242122] acpiphp: Slot [28] registered [ 0.243127] acpiphp: Slot [29] registered [ 0.244113] acpiphp: Slot [30] registered [ 0.245106] acpiphp: Slot [31] registered [ 0.246055] PCI host bridge to bus 0000:00 [ 0.247017] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.248024] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.249024] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.250020] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.251034] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.252022] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.253327] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.256082] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.259396] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.270877] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.277063] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.280019] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.283026] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.285018] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.289359] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.291630] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.293048] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.294817] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.299013] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.310013] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.314020] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.319978] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.329019] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.342021] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.366020] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.380030] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.394020] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.401020] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.417024] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.428973] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.439018] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.447022] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.462019] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.474733] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.485016] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.491242] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.507019] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.521246] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.530017] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.538017] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.557025] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 0.567893] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.574023] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.580025] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.598023] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 0.612377] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.616443] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.619520] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.623520] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.626312] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.631219] iommu: Default domain type: Passthrough [ 0.633470] SCSI subsystem initialized [ 0.635160] ACPI: bus type USB registered [ 0.637208] usbcore: registered new interface driver usbfs [ 0.639110] usbcore: registered new interface driver hub [ 0.641088] usbcore: registered new device driver usb [ 0.643176] pps_core: LinuxPPS API ver. 1 registered [ 0.645014] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.646056] PTP clock support registered [ 0.648142] EDAC MC: Ver: 3.0.0 [ 0.650126] PCI: Using ACPI for IRQ routing [ 0.652806] NetLabel: Initializing [ 0.654023] NetLabel: domain hash size = 128 [ 0.656018] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.658131] NetLabel: unlabeled traffic allowed by default [ 0.662052] vgaarb: loaded [ 0.663405] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.664017] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.667865] clocksource: Switched to clocksource kvm-clock [ 0.771520] VFS: Disk quotas dquot_6.6.0 [ 0.773031] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.775697] *** VALIDATE ramfs *** [ 0.776791] *** VALIDATE hugetlbfs *** [ 0.777950] pnp: PnP ACPI init [ 0.780918] pnp: PnP ACPI: found 6 devices [ 0.801142] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.804485] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.806729] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.808266] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.810417] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.812322] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.814646] NET: Registered protocol family 2 [ 0.816821] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.821629] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.825571] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.830803] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.834802] TCP: Hash tables configured (established 65536 bind 65536) [ 0.838366] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.842500] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.845752] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.849441] NET: Registered protocol family 1 [ 0.853723] RPC: Registered named UNIX socket transport module. [ 0.856013] RPC: Registered udp transport module. [ 0.857934] RPC: Registered tcp transport module. [ 0.860041] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.862533] NET: Registered protocol family 44 [ 0.864371] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.866759] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.869046] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.871493] PCI: CLS 0 bytes, default 64 [ 0.873208] Unpacking initramfs... [ 2.292102] debug: unmapping init [mem 0xffff95bb7cc54000-0xffff95bb7ffbffff] [ 2.296387] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.298902] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.302139] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 2.807420] Initialise system trusted keyrings [ 2.809296] Key type blacklist registered [ 2.811258] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.822583] zbud: loaded [ 2.826321] *** VALIDATE nfs *** [ 2.827556] *** VALIDATE nfs4 *** [ 2.829266] pstore: using deflate compression [ 2.834065] Platform Keyring initialized [ 2.927579] NET: Registered protocol family 38 [ 2.929641] Key type asymmetric registered [ 2.931594] Asymmetric key parser 'x509' registered [ 2.934383] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 2.936922] io scheduler mq-deadline registered [ 2.938425] io scheduler kyber registered [ 2.939829] io scheduler bfq registered [ 2.942234] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 2.945839] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 2.949736] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 2.954087] ACPI: Power Button [PWRF] [ 2.960070] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 2.967802] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 2.983655] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 2.994269] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 3.010748] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 3.037751] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.065026] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.069734] Non-volatile memory driver v1.3 [ 3.071539] Linux agpgart interface v0.103 [ 3.101622] virtio_blk virtio1: [vda] 146640 512-byte logical blocks (75.1 MB/71.6 MiB) [ 3.104930] vda: detected capacity change from 0 to 75079680 [ 3.124489] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.128996] vdb: detected capacity change from 0 to 1073741824 [ 3.143881] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.148289] vdc: detected capacity change from 0 to 2621440000 [ 3.165666] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.168684] vdd: detected capacity change from 0 to 2621440000 [ 3.183496] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.186873] vde: detected capacity change from 0 to 4294967296 [ 3.202531] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.205062] vdf: detected capacity change from 0 to 4294967296 [ 3.217394] libphy: Fixed MDIO Bus: probed [ 3.226413] usbcore: registered new interface driver usbserial_generic [ 3.228534] usbserial: USB Serial support registered for generic [ 3.230412] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.234242] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.235655] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.237623] mousedev: PS/2 mouse device common for all mice [ 3.240148] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.245137] rtc_cmos 00:05: RTC can wake from S4 [ 3.246297] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.252608] rtc_cmos 00:05: registered as rtc0 [ 3.253756] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.255092] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.261223] intel_pstate: CPU model not supported [ 3.264347] hid: raw HID events driver (C) Jiri Kosina [ 3.266739] usbcore: registered new interface driver usbhid [ 3.269037] usbhid: USB HID core driver [ 3.270763] drop_monitor: Initializing network drop monitor service [ 3.273342] Initializing XFRM netlink socket [ 3.275639] NET: Registered protocol family 10 [ 3.279344] Segment Routing with IPv6 [ 3.281542] NET: Registered protocol family 17 [ 3.284399] mpls_gso: MPLS GSO support [ 3.292527] RAS: Correctable Errors collector initialized. [ 3.295732] AVX version of gcm_enc/dec engaged. [ 3.298200] AES CTR mode by8 optimization enabled [ 3.384039] sched_clock: Marking stable (3384012287, 0)->(4387859983, -1003847696) [ 3.387451] registered taskstats version 1 [ 3.389491] Loading compiled-in X.509 certificates [ 3.391332] zswap: loaded using pool lzo/zbud [ 3.417301] Key type big_key registered [ 3.433139] Key type encrypted registered [ 3.435317] ima: No TPM chip found, activating TPM-bypass! [ 3.438306] ima: Allocated hash algorithm: sha1 [ 3.440694] ima: No architecture policies found [ 3.443507] evm: Initialising EVM extended attributes: [ 3.446285] evm: security.selinux [ 3.448071] evm: security.ima [ 3.449661] evm: security.capability [ 3.451493] evm: HMAC attrs: 0x1 [ 3.454383] rtc_cmos 00:05: setting system clock to 2026-08-31 21:33:02 UTC (1788211982) [ 3.462290] debug: unmapping init [mem 0xffffffff9d203000-0xffffffff9d3fffff] [ 3.466690] debug: unmapping init [mem 0xffffffff9bf82000-0xffffffff9c258fff] [ 3.477123] Write protecting the kernel read-only data: 28672k [ 3.481064] debug: unmapping init [mem 0xffffffff9a603000-0xffffffff9a7fffff] [ 3.485082] debug: unmapping init [mem 0xffffffff9af14000-0xffffffff9affffff] [ 3.521841] 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.532660] systemd[1]: Detected virtualization kvm. [ 3.535502] systemd[1]: Detected architecture x86-64. [ 3.538294] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.567340] systemd[1]: No hostname configured. [ 3.569837] systemd[1]: Set hostname to . [ 3.572913] random: systemd: uninitialized urandom read (16 bytes read) [ 3.575879] systemd[1]: Initializing machine ID from random generator. [ 3.686466] random: systemd: uninitialized urandom read (16 bytes read) [ 3.688893] systemd[1]: Reached target Initrd Root Device. [ OK ] Reached target Initrd Root Device. [ 3.694032] random: systemd: uninitialized urandom read (16 bytes read) [ 3.696676] systemd[1]: Reached target Swap. [ OK ] Reached target Swap. [ 3.701259] systemd[1]: Reached target Slices. [ OK ] Reached target Slices. [ OK ] Listening on udev Kernel Socket. [ OK ] Listening on Journal Socket. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Listening on udev Control Socket. [ OK ] Reached target Local File Systems. Starting Create Volatile Files and Directories... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. [ OK ] Reached target Timers. [ OK ] Listening on Journal Socket (/dev/log). Starting Journal Service... [ OK ] Reached target Sockets. Starting Setup Virtual Console... [ OK ] Started Memstrack Anylazing Service. Starting Apply Kernel Variables... [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Setup Virtual Console. [ OK ] Started Apply Kernel Variables. Starting dracut cmdline hook... Starting Create Static Device Nodes in /dev... [ OK ] Started Journal Service. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 4.301852] device-mapper: uevent: version 1.0.3 [ 4.304251] device-mapper: ioctl: 4.46.0-ioctl (2022-02-22) initialised: dm-devel@redhat.com [ OK ] Started dracut pre-udev hook. Starting udev Kernel Device Manager... [ OK ] Started udev Kernel Device Manager. Starting dracut pre-trigger hook... [ OK ] Started dracut pre-trigger hook. Starting udev Coldplug all Devices... Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting dracut initqueue hook... [ 4.965914] random: fast init done [ 4.977937] virtio_net virtio0 ens2: renamed from eth0 [ 4.991929] scsi host0: ata_piix [ 5.007223] scsi host1: ata_piix [ 5.009380] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 5.012610] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 9.348391] dracut-initqueue[585]: RTNETLINK answers: File exists [ 9.980085] random: crng init done [ 9.981726] random: 7 urandom warning(s) missed due to ratelimiting Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Mounting /sysroot... [ 10.328457] 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 Initrd Default Target. [ OK ] Stopped target Initrd Root Device. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Paths. [ OK ] Stopped target Sockets. [ OK ] Stopped target Slices. [ OK ] Stopped target System Initialization. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. Stopping udev Kernel Device Manager... [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped target Swap. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Closed udev Kernel Socket. [ OK ] Closed udev Control Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 11.579514] printk: systemd: 25 output lines suppressed due to ratelimiting [ 11.822823] SELinux: Disabled at runtime. [ 11.884118] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 11.892705] systemd[1]: Detected virtualization kvm. [ 11.894504] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 12.361274] systemd[1]: initrd-switch-root.service: Succeeded. [ 12.364120] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 12.372455] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 12.376725] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 12.380211] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 12.386824] systemd[1]: Starting Journal Service... Starting Journal Service... [ 12.391663] systemd[1]: Created slice User and Session Slice. [ OK ] Created slice User and Session Slice. Starting Apply Kernel Variables... Starting Remount Root and Kernel File Systems... [ OK ] Listening on Process Core Dump Socket. [ OK ] Reached target rpc_pipefs.target. [ OK ] Created slice system-getty.slice. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Listening on udev Kernel Socket. [ OK ] Created slice system-sshd\x2dkeygen.slice. Mounting POSIX Message Queue File System... Mounting Kernel Debug File System... [ OK ] Listening on udev Control Socket. Starting udev Coldplug all Devices... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd Root File System. [ OK ] Stopped target Initrd File Systems. Mounting Huge Pages File System... [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Reached target Slices. [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Reached target Paths. [ OK ] Reached target Local Encrypted Volumes. Activating swap /dev/disk/by-label/SWAP... [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Reached target RPC Port Mapper. [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ 12.568618] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS [ OK ] Started Journal Service. [ 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. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Mounted Kernel Debug File System. [ OK ] Mounted Huge Pages File System. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Reached target Swap. Starting Create Static Device Nodes in /dev... Starting Configure read-only root support... Starting Flush Journal to Persistent Storage... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. Starting udev Kernel Device Manager... [ OK ] Reached target Local File Systems (Pre). Mounting /mnt... Mounting /home/green/git/lustre-release... [ OK ] Mounted /mnt. [ OK ] Started udev Coldplug all Devices. [ 12.879863] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 13.274786] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 13.325521] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 13.434641] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 13.444396] EDAC sbridge: Ver: 1.1.2 [ 14.981648] Key type dns_resolver registered [ 15.301761] NFS: Registering the id_resolver key type [ 15.303535] Key type id_resolver registered [ 15.304655] 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 Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Started dnf makecache --timer. [ OK ] Reached target Timers. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. Starting Restore /run/initramfs on shutdown... [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Started D-Bus System Message Bus. [ OK ] Reached target sshd-keygen.target. [ OK ] Started irqbalance daemon. Starting Network Manager... Starting Login Service... [ 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 OpenSSH server daemon... Starting Dynamic System Tuning Daemon... Starting GSSAPI Proxy Daemon... [ OK ] Started 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 Permit User Sessions. [ OK ] Started Command Scheduler. [ OK ] Started Serial Getty on ttyS1. [ OK ] Started Getty on tty1. [ OK ] Started Serial Getty on ttyS0. [ OK ] Reached target Login Prompts. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting Notify NFS peers of a restart... Starting Crash recovery kernel arming... Starting System Logging Service... [ 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 oleg233-server login: [ 33.207741] spl: loading out-of-tree module taints kernel. [ 35.821051] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 44.916739] Key type ._llcrypt registered [ 44.921401] Key type .llcrypt registered [ 45.128117] Lustre: DEBUG MARKER: oleg233-server.virtnet: executing set_hostid [ 65.397709] Lustre: DEBUG MARKER: oleg233-server.virtnet: executing load_modules_local [ 67.614027] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 67.646390] alg: No test for adler32 (adler32-zlib) [ 69.198821] Lustre: Lustre: Build Version: 2.17.57_85_gb71fc30 [ 70.345441] LNet: Added LNI 192.168.202.133@tcp [8/256/0/180] [ 72.263665] Key type lgssc registered [ 73.943439] Lustre: Echo OBD driver; http://www.lustre.org/ [ 85.907534] vdc: vdc1 vdc9 [ 85.953501] vdc: vdc1 vdc9 [ 96.860528] vde: vde1 vde9 [ 99.977311] hrtimer: interrupt took 12850010 ns [ 107.619495] vdf: vdf1 vdf9 [ 129.506308] Lustre: DEBUG MARKER: oleg233-server.virtnet: executing load_modules_local [ 140.947531] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 142.269168] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 142.592825] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 142.673924] Lustre: lustre-MDT0000: new disk, initializing [ 143.449949] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 143.624868] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 149.921565] Lustre: DEBUG MARKER: oleg233-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 155.365236] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 164.386451] Lustre: lustre-OST0000: new disk, initializing [ 164.389608] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 164.393685] Lustre: Skipped 1 previous similar message [ 164.547540] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 165.133701] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:0:ost [ 165.142446] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:0:ost] [ 165.318181] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x240000400 [ 172.846547] Lustre: DEBUG MARKER: oleg233-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 185.123418] Lustre: lustre-OST0001: new disk, initializing [ 185.133441] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 185.245626] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 193.612101] Lustre: DEBUG MARKER: oleg233-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 195.440181] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:1:ost [ 195.465323] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:1:ost] [ 195.654359] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x280000400 [ 209.001243] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 217.690444] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 224.730229] Lustre: DEBUG MARKER: oleg233-server.virtnet: executing check_logdir /tmp/testlogs/ [ 230.574988] Lustre: DEBUG MARKER: oleg233-server.virtnet: executing yml_node [ 235.225840] Lustre: DEBUG MARKER: Client: 2.17.57.85 [ 238.128577] Lustre: DEBUG MARKER: MDS: 2.17.57.85 [ 241.371238] Lustre: DEBUG MARKER: OSS: 2.17.57.85 [ 243.429585] Lustre: DEBUG MARKER: -----============= acceptance-small: replay-dual ============----- Mon Aug 31 17:37:00 EDT 2026 [ 264.352931] Lustre: DEBUG MARKER: excepting tests: 14b 21b 21b [ 266.242852] Lustre: DEBUG MARKER: skipping tests SLOW=no: 21b [ 268.100797] Lustre: DEBUG MARKER: === replay-dual: start setup 17:37:24 (1788212244) === [ 273.930498] Lustre: DEBUG MARKER: oleg233-client.virtnet: executing check_config_client /mnt/lustre [ 289.158647] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 293.431055] Lustre: 11362:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 298.795780] Lustre: DEBUG MARKER: oleg233-server.virtnet: executing set_default_debug -1 all [ 302.700621] Lustre: DEBUG MARKER: === replay-dual: finish setup 17:37:59 (1788212279) === [ 305.263369] Lustre: DEBUG MARKER: == replay-dual test 0a: expired recovery with lost client ========================================================== 17:38:02 (1788212282) [ 309.274771] LustreError: 11859:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 310.400827] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 314.978882] Lustre: Failing over lustre-MDT0000 [ 315.252107] Lustre: server umount lustre-MDT0000 complete [ 334.623580] Lustre: 3304:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788212297/real 1788212297] req@ffff95bac38e4380 x1875076237551104/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788212313 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 334.667130] 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 [ 334.945362] LustreError: MGC192.168.202.133@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 335.264205] Lustre: lustre-MDT0000: Not available for connect from 192.168.202.33@tcp (not set up) [ 335.275170] Lustre: Skipped 1 previous similar message [ 335.578315] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 336.891249] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 339.551296] Lustre: 3301:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788212302/real 1788212302] req@ffff95bac18b5500 x1875076237551360/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788212318 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 339.586232] Lustre: 3301:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 340.643985] Lustre: 3302:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788212302/real 1788212302] req@ffff95bac18b5880 x1875076237551488/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788212318 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 341.003349] Lustre: DEBUG MARKER: oleg233-server.virtnet: executing set_default_debug -1 all [ 344.735307] Lustre: 3301:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788212307/real 1788212307] req@ffff95bac38e4700 x1875076237551872/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788212323 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 344.741244] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 344.759517] Lustre: 3301:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 349.855212] Lustre: 3303:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788212312/real 1788212312] req@ffff95bac18b6a00 x1875076237552256/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788212328 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 439.503444] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 439.506187] Lustre: 12513:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client ce52a6ed-ca10-4107-8d3e-494cc55ec492@192.168.202.33@tcp [ 439.535977] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 439.668198] Lustre: 12513:0:(ldlm_lib.c:2976:target_recovery_thread()) too long recovery - read logs [ 439.675831] LustreError: dumping log to /tmp/lustre-log.1788212418.12513 [ 439.940178] Lustre: lustre-MDT0000: Recovery over after 1:43, of 2 clients 1 recovered and 1 was evicted. [ 440.015663] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:28 to 0x240000400:65) [ 440.017577] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:28 to 0x280000400:65) [ 462.687366] Lustre: DEBUG MARKER: == replay-dual test 0b: lost client during waiting for next transno ========================================================== 17:40:39 (1788212439) [ 465.618542] LustreError: 13261:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 466.432392] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 468.743088] Lustre: Failing over lustre-MDT0000 [ 469.172865] Lustre: server umount lustre-MDT0000 complete [ 487.502101] LustreError: MGC192.168.202.133@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 487.843589] 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 [ 487.871762] Lustre: Skipped 1 previous similar message [ 488.070642] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 488.417733] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 489.126468] Lustre: 3301:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788212452/real 1788212452] req@ffff95bbfaf00a80 x1875076237589504/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788212468 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 489.166216] Lustre: 3301:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 492.740682] Lustre: DEBUG MARKER: oleg233-server.virtnet: executing set_default_debug -1 all [ 493.042249] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 493.049983] Lustre: Skipped 1 previous similar message [ 505.492854] Lustre: lustre-MDT0000: Denying connection for new client 66ffe90d-8ff5-453b-a1b4-29c6a3766d40 (at 192.168.202.33@tcp), waiting for 2 known clients (0 recovered, 1 in progress, and 0 evicted) to recover in 0:53 [ 510.841482] Lustre: lustre-MDT0000: Denying connection for new client 66ffe90d-8ff5-453b-a1b4-29c6a3766d40 (at 192.168.202.33@tcp), waiting for 2 known clients (0 recovered, 1 in progress, and 0 evicted) to recover in 0:47 [ 515.972809] Lustre: lustre-MDT0000: Denying connection for new client 66ffe90d-8ff5-453b-a1b4-29c6a3766d40 (at 192.168.202.33@tcp), waiting for 2 known clients (0 recovered, 1 in progress, and 0 evicted) to recover in 0:42 [ 521.086040] Lustre: lustre-MDT0000: Denying connection for new client 66ffe90d-8ff5-453b-a1b4-29c6a3766d40 (at 192.168.202.33@tcp), waiting for 2 known clients (0 recovered, 1 in progress, and 0 evicted) to recover in 0:37 [ 526.207497] Lustre: lustre-MDT0000: Denying connection for new client 66ffe90d-8ff5-453b-a1b4-29c6a3766d40 (at 192.168.202.33@tcp), waiting for 2 known clients (0 recovered, 1 in progress, and 0 evicted) to recover in 0:32 [ 536.439775] Lustre: lustre-MDT0000: Denying connection for new client 66ffe90d-8ff5-453b-a1b4-29c6a3766d40 (at 192.168.202.33@tcp), waiting for 2 known clients (0 recovered, 1 in progress, and 0 evicted) to recover in 0:22 [ 536.473100] Lustre: Skipped 1 previous similar message [ 556.920072] Lustre: lustre-MDT0000: Denying connection for new client 66ffe90d-8ff5-453b-a1b4-29c6a3766d40 (at 192.168.202.33@tcp), waiting for 2 known clients (0 recovered, 1 in progress, and 0 evicted) to recover in 0:01 [ 556.945744] Lustre: Skipped 3 previous similar messages [ 558.500373] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 558.503217] Lustre: 13898:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 695345fa-f0fb-4bd3-a965-2826c451d158@ [ 558.528022] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 592.760211] Lustre: lustre-MDT0000: Denying connection for new client 66ffe90d-8ff5-453b-a1b4-29c6a3766d40 (at 192.168.202.33@tcp), waiting for 2 known clients (0 recovered, 1 in progress, and 1 evicted) to recover in 1:06 [ 592.788262] Lustre: Skipped 6 previous similar messages [ 659.322674] Lustre: lustre-MDT0000: Denying connection for new client 66ffe90d-8ff5-453b-a1b4-29c6a3766d40 (at 192.168.202.33@tcp), waiting for 2 known clients (0 recovered, 1 in progress, and 1 evicted) to recover in 0:00 [ 659.345743] Lustre: Skipped 12 previous similar messages [ 659.501619] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 659.507894] Lustre: 13898:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 3ecc6705-077e-4015-9102-355940b716a3@192.168.202.33@tcp [ 659.528362] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 659.535111] Lustre: 13898:0:(ldlm_lib.c:2110:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 659.617091] Lustre: 13898:0:(ldlm_lib.c:2976:target_recovery_thread()) too long recovery - read logs [ 659.622631] LustreError: dumping log to /tmp/lustre-log.1788212638.13898 [ 659.701649] Lustre: lustre-MDT0000: Recovery over after 2:51, of 2 clients 0 recovered and 2 were evicted. [ 659.732669] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:28 to 0x280000400:97) [ 659.735844] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:67 to 0x240000400:97) [ 672.784629] Lustre: DEBUG MARKER: == replay-dual test 1: |X| simple create ================= 17:44:09 (1788212649) [ 676.919519] LustreError: 14663:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 677.837874] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 679.793224] Lustre: Failing over lustre-MDT0000 [ 680.219592] Lustre: server umount lustre-MDT0000 complete [ 698.847123] Lustre: 3304:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788212661/real 1788212661] req@ffff95bac26ab800 x1875076237630976/t0(0) o400->MGC192.168.202.133@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1788212677 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 698.849142] 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 [ 698.892226] Lustre: 3304:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 6 previous similar messages [ 698.892352] LustreError: MGC192.168.202.133@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 698.938826] Lustre: Skipped 2 previous similar messages [ 708.067134] LustreError: 3300:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff95bac26ab100 x1875076237633024/t0(0) o250->MGC192.168.202.133@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 [ 708.668219] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 708.749475] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 713.457685] Lustre: DEBUG MARKER: oleg233-server.virtnet: executing set_default_debug -1 all [ 721.278032] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 721.488208] Lustre: lustre-MDT0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 721.544908] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:99 to 0x280000400:129) [ 721.546782] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:99 to 0x240000400:129) [ 723.953349] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 723.968938] Lustre: Skipped 1 previous similar message [ 727.526349] Lustre: DEBUG MARKER: oleg233-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 729.020073] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 737.589795] Lustre: DEBUG MARKER: == replay-dual test 2: |X| mkdir adir ==================== 17:45:14 (1788212714) [ 740.426078] LustreError: 16260:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 741.287818] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 743.073529] Lustre: Failing over lustre-MDT0000 [ 743.368581] Lustre: server umount lustre-MDT0000 complete [ 760.126759] LustreError: MGC192.168.202.133@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 760.433793] 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 [ 760.448054] Lustre: Skipped 1 previous similar message [ 760.548827] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 760.673885] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 761.503097] Lustre: 3304:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788212723/real 1788212723] req@ffff95bbf71e1500 x1875076237648256/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788212739 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 761.513224] Lustre: 3304:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 7 previous similar messages [ 762.271806] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 762.436382] Lustre: lustre-MDT0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 762.474911] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:99 to 0x240000400:161) [ 762.476092] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:99 to 0x280000400:161) [ 764.055239] Lustre: DEBUG MARKER: oleg233-server.virtnet: executing set_default_debug -1 all [ 765.934539] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 765.941962] Lustre: Skipped 1 previous similar message [ 773.088597] Lustre: DEBUG MARKER: oleg233-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 774.702340] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 783.314477] Lustre: DEBUG MARKER: == replay-dual test 3: |X| mkdir adir, mkdir adir/bdir === 17:46:00 (1788212760) [ 786.967427] LustreError: 17844:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 788.057987] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 790.286988] Lustre: Failing over lustre-MDT0000 [ 790.771956] Lustre: server umount lustre-MDT0000 complete [ 807.903218] 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 [ 807.909165] LustreError: MGC192.168.202.133@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 807.919425] Lustre: Skipped 1 previous similar message [ 817.120961] LustreError: 3300:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff95bac2d54e00 x1875076237665152/t0(0) o250->MGC192.168.202.133@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 [ 818.273856] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 818.470724] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 818.562254] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 818.894247] Lustre: lustre-MDT0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 818.943418] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:99 to 0x240000400:193) [ 818.943524] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:99 to 0x280000400:193) [ 823.035151] Lustre: DEBUG MARKER: oleg233-server.virtnet: executing set_default_debug -1 all [ 832.430141] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 832.446825] Lustre: Skipped 1 previous similar message [ 833.956959] Lustre: DEBUG MARKER: oleg233-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 835.772345] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 845.283630] Lustre: DEBUG MARKER: == replay-dual test 4: |X| mkdir adir (-EEXIST), mkdir adir/bdir ========================================================== 17:47:01 (1788212821) [ 848.803686] LustreError: 19434:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 850.041395] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 852.573122] Lustre: Failing over lustre-MDT0000 [ 853.020252] Lustre: server umount lustre-MDT0000 complete [ 869.343189] Lustre: 3303:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788212832/real 1788212832] req@ffff95bbfaf00a80 x1875076237680128/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788212848 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 869.346334] 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 [ 869.378388] Lustre: 3303:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 17 previous similar messages [ 869.395172] Lustre: Skipped 1 previous similar message [ 872.198474] LustreError: MGC192.168.202.133@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 873.023475] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 877.882772] Lustre: DEBUG MARKER: oleg233-server.virtnet: executing set_default_debug -1 all [ 879.031809] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 879.049821] Lustre: Skipped 1 previous similar message [ 879.989914] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 880.138725] Lustre: lustre-MDT0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 880.190394] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:99 to 0x240000400:225) [ 880.202073] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:99 to 0x280000400:225) [ 888.378539] Lustre: DEBUG MARKER: oleg233-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 890.178602] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 898.925868] Lustre: DEBUG MARKER: == replay-dual test 5: open, unlink |X| close ============ 17:47:56 (1788212876) [ 902.296198] LustreError: 21011:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 903.078360] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 905.266752] Lustre: Failing over lustre-MDT0000 [ 905.682921] Lustre: server umount lustre-MDT0000 complete [ 924.333841] LustreError: MGC192.168.202.133@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 924.737143] 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 [ 924.752860] Lustre: Skipped 1 previous similar message [ 924.923160] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 924.926969] Lustre: Skipped 1 previous similar message [ 925.018700] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 929.771786] Lustre: DEBUG MARKER: oleg233-server.virtnet: executing set_default_debug -1 all [ 930.279493] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 930.287673] Lustre: Skipped 1 previous similar message [ 931.254529] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 932.452694] Lustre: lustre-MDT0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 932.512776] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:99 to 0x280000400:257) [ 932.514683] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:99 to 0x240000400:257) [ 940.169569] Lustre: DEBUG MARKER: oleg233-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 941.832374] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 951.079216] Lustre: DEBUG MARKER: == replay-dual test 6: open1, open2, unlink |X| close1 [fail mds1] close2 ========================================================== 17:48:48 (1788212928) [ 954.941575] LustreError: 22593:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 956.140854] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 958.008508] Lustre: Failing over lustre-MDT0000 [ 958.305545] Lustre: server umount lustre-MDT0000 complete [ 976.259141] LustreError: MGC192.168.202.133@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 976.354655] 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 [ 976.384764] Lustre: Skipped 1 previous similar message [ 976.913746] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 977.290881] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 977.444406] Lustre: lustre-MDT0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 977.495690] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:99 to 0x280000400:289) [ 977.508826] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:99 to 0x240000400:289) [ 981.997768] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 982.013045] Lustre: Skipped 1 previous similar message [ 982.364317] Lustre: DEBUG MARKER: oleg233-server.virtnet: executing set_default_debug -1 all [ 993.939301] Lustre: DEBUG MARKER: oleg233-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 995.931977] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1006.524253] Lustre: DEBUG MARKER: == replay-dual test 8: replay of resent request ========== 17:49:43 (1788212983) [ 1011.078839] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1012.444304] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 1012.446401] LustreError: 23200:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff95bbe9c78000 x1875076215695232/t38654705670(0) o36->66ffe90d-8ff5-453b-a1b4-29c6a3766d40@192.168.202.33@tcp:32/0 lens 512/448 e 0 to 0 dl 1788213002 ref 1 fl Interpret:/200/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 1029.041633] Lustre: lustre-MDT0000: Client 66ffe90d-8ff5-453b-a1b4-29c6a3766d40 (at 192.168.202.33@tcp) reconnecting [ 1029.078145] Lustre: 23201:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff95bbd181f100 x1875076215695232/t38654705670(0) o36->66ffe90d-8ff5-453b-a1b4-29c6a3766d40@192.168.202.33@tcp:49/0 lens 512/2880 e 0 to 0 dl 1788213019 ref 1 fl Interpret:/202/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 1033.214961] Lustre: Failing over lustre-MDT0000 [ 1033.621131] Lustre: server umount lustre-MDT0000 complete [ 1053.588877] Lustre: MGS: Not available for connect from 192.168.202.33@tcp (not set up) [ 1053.607341] LustreError: MGC192.168.202.133@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1053.695889] 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 [ 1053.708893] Lustre: Skipped 1 previous similar message [ 1053.717826] LustreError: 24901:0:(ldlm_lib.c:1190: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. [ 1053.739046] LustreError: 24901:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 3 previous similar messages [ 1054.256485] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1054.259262] Lustre: Skipped 1 previous similar message [ 1054.321522] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1055.229760] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 1055.252946] Lustre: 3301:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788213017/real 1788213017] req@ffff95bac2859f80 x1875076237733632/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788213033 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1055.252958] Lustre: 3301:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 18 previous similar messages [ 1055.345792] Lustre: Skipped 1 previous similar message [ 1059.887421] Lustre: DEBUG MARKER: oleg233-server.virtnet: executing set_default_debug -1 all [ 1063.802027] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 1064.041549] Lustre: lustre-MDT0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 1064.105294] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:99 to 0x280000400:321) [ 1064.106382] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:99 to 0x240000400:321) [ 1071.380876] Lustre: DEBUG MARKER: oleg233-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1073.453472] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1083.410326] Lustre: DEBUG MARKER: == replay-dual test 9: resending a replayed create ======= 17:51:00 (1788213060) [ 1086.489515] LustreError: 25881:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 1086.503106] LustreError: 25881:0:(osd_handler.c:715:osd_ro()) Skipped 1 previous similar message [ 1087.355159] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1090.741727] Lustre: Failing over lustre-MDT0000 [ 1091.051688] Lustre: server umount lustre-MDT0000 complete [ 1118.602827] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1121.289612] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 1121.291592] LustreError: 26572:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff95bac2858a80 x1875076215710592/t42949672966(42949672966) o36->66ffe90d-8ff5-453b-a1b4-29c6a3766d40@192.168.202.33@tcp:141/0 lens 520/448 e 0 to 0 dl 1788213111 ref 1 fl Complete:/204/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 1124.330266] Lustre: DEBUG MARKER: oleg233-server.virtnet: executing set_default_debug -1 all [ 1136.545919] Lustre: lustre-MDT0000: Client 66ffe90d-8ff5-453b-a1b4-29c6a3766d40 (at 192.168.202.33@tcp) reconnected, waiting for 2 clients in recovery for 1:24 [ 1136.705974] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:99 to 0x280000400:353) [ 1136.705974] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:99 to 0x240000400:353) [ 1143.492120] Lustre: DEBUG MARKER: oleg233-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1145.413469] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1154.910513] Lustre: DEBUG MARKER: == replay-dual test 10: resending a replayed unlink ====== 17:52:12 (1788213132) [ 1159.038499] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1162.135598] Lustre: Failing over lustre-MDT0000 [ 1162.430225] Lustre: server umount lustre-MDT0000 complete [ 1189.859253] LustreError: 3300:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff95bbf7739500 x1875076237769088/t0(0) o250->MGC192.168.202.133@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 [ 1190.504338] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1192.821531] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 1192.835408] Lustre: Skipped 1 previous similar message [ 1192.918542] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 1192.929728] LustreError: 28279:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff95bac3b2f800 x1875076215725568/t47244640264(47244640264) o36->66ffe90d-8ff5-453b-a1b4-29c6a3766d40@192.168.202.33@tcp:212/0 lens 504/456 e 0 to 0 dl 1788213182 ref 1 fl Complete:/204/0 rc 0/0 job:'unlink.0' uid:0 gid:0 projid:4294967295 [ 1195.227234] Lustre: DEBUG MARKER: oleg233-server.virtnet: executing set_default_debug -1 all [ 1204.661804] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 1204.672939] Lustre: Skipped 3 previous similar messages [ 1209.230179] Lustre: lustre-MDT0000: Client 66ffe90d-8ff5-453b-a1b4-29c6a3766d40 (at 192.168.202.33@tcp) reconnected, waiting for 2 clients in recovery for 1:24 [ 1209.293761] Lustre: lustre-MDT0000: Recovery over after 0:17, of 2 clients 2 recovered and 0 were evicted. [ 1209.308194] Lustre: Skipped 1 previous similar message [ 1209.363168] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:99 to 0x280000400:385) [ 1209.364195] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:99 to 0x240000400:385) [ 1216.353856] Lustre: DEBUG MARKER: oleg233-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1217.785496] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1227.409673] Lustre: DEBUG MARKER: == replay-dual test 11: both clients timeout during replay ========================================================== 17:53:24 (1788213204) [ 1230.151855] LustreError: 29295:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 1230.159829] LustreError: 29295:0:(osd_handler.c:715:osd_ro()) Skipped 1 previous similar message [ 1231.081146] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1233.559158] Lustre: Failing over lustre-MDT0000 [ 1233.792389] LustreError: 28246:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.202.33@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1233.937812] Lustre: server umount lustre-MDT0000 complete [ 1251.620776] 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 [ 1251.631917] Lustre: Skipped 4 previous similar messages [ 1251.637732] LustreError: MGC192.168.202.133@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1251.652163] LustreError: Skipped 2 previous similar messages [ 1261.026488] LustreError: 3300:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff95bbf709f480 x1875076237786240/t0(0) o250->MGC192.168.202.133@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 [ 1267.399000] Lustre: DEBUG MARKER: oleg233-server.virtnet: executing set_default_debug -1 all [ 1273.756868] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 1273.766546] LustreError: 29987:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff95bac2d55880 x1875076215739904/t51539607558(51539607558) o36->66ffe90d-8ff5-453b-a1b4-29c6a3766d40@192.168.202.33@tcp:293/0 lens 520/448 e 0 to 0 dl 1788213263 ref 1 fl Complete:/204/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 1277.033645] Lustre: DEBUG MARKER: oleg233-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1290.231889] Lustre: lustre-MDT0000: Client 66ffe90d-8ff5-453b-a1b4-29c6a3766d40 (at 192.168.202.33@tcp) reconnected, waiting for 2 clients in recovery for 1:24 [ 1290.458237] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:99 to 0x240000400:417) [ 1290.464674] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:99 to 0x280000400:417) [ 1293.543254] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 13 sec [ 1301.284026] Lustre: DEBUG MARKER: == replay-dual test 12: open resend timeout ============== 17:54:38 (1788213278) [ 1305.788061] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1308.918312] Lustre: Failing over lustre-MDT0000 [ 1309.360674] Lustre: server umount lustre-MDT0000 complete [ 1328.031157] Lustre: 3303:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788213291/real 1788213291] req@ffff95bbff733800 x1875076237802752/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788213307 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1328.088377] Lustre: 3303:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 30 previous similar messages [ 1338.336046] LustreError: 3300:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff95bbfb28c000 x1875076237804288/t0(0) o250->MGC192.168.202.133@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 [ 1338.842813] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1338.845337] Lustre: Skipped 3 previous similar messages [ 1338.925889] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1338.928959] Lustre: Skipped 1 previous similar message [ 1343.644418] Lustre: DEBUG MARKER: oleg233-server.virtnet: executing set_default_debug -1 all [ 1350.857034] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:99 to 0x240000400:449) [ 1350.871758] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:99 to 0x280000400:449) [ 1358.753956] Lustre: DEBUG MARKER: == replay-dual test 13: close resend timeout ============= 17:55:35 (1788213335) [ 1363.639082] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1366.550508] Lustre: Failing over lustre-MDT0000 [ 1367.042450] Lustre: server umount lustre-MDT0000 complete [ 1394.151655] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xc184202f28ed749b [ 1396.666988] Lustre: *** cfs_fail_loc=115, val=2147483648*** [ 1402.157489] Lustre: DEBUG MARKER: oleg233-server.virtnet: executing set_default_debug -1 all [ 1413.012296] Lustre: lustre-MDT0000: Client 66ffe90d-8ff5-453b-a1b4-29c6a3766d40 (at 192.168.202.33@tcp) reconnected, waiting for 2 clients in recovery for 1:24 [ 1413.244911] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:99 to 0x280000400:481) [ 1413.253267] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:99 to 0x240000400:481) [ 1421.756688] Lustre: DEBUG MARKER: SKIP: replay-dual test_14b skipping ALWAYS excluded test 14b [ 1423.490976] Lustre: DEBUG MARKER: == replay-dual test 15a: timeout waiting for lost client during replay, 1 client completes ========================================================== 17:56:40 (1788213400) [ 1429.093689] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1432.769843] Lustre: Failing over lustre-MDT0000 [ 1433.263201] Lustre: server umount lustre-MDT0000 complete [ 1461.728932] LustreError: 3300:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff95bbd193ca80 x1875076237836544/t0(0) o250->MGC192.168.202.133@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 [ 1464.185134] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 1464.201525] Lustre: Skipped 3 previous similar messages [ 1467.020251] Lustre: DEBUG MARKER: oleg233-server.virtnet: executing set_default_debug -1 all [ 1476.652570] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 1476.668062] Lustre: Skipped 8 previous similar messages [ 1534.500425] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 1534.504912] Lustre: 34602:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client cecaccbf-3a74-455b-b6ca-1e84c7508380@ [ 1534.515923] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 1535.575768] Lustre: lustre-MDT0000: Recovery over after 1:11, of 2 clients 1 recovered and 1 was evicted. [ 1535.591651] Lustre: Skipped 3 previous similar messages [ 1535.653681] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:495 to 0x240000400:513) [ 1535.670503] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:494 to 0x280000400:513) [ 1543.746131] Lustre: DEBUG MARKER: oleg233-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1545.754905] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1556.674895] Lustre: DEBUG MARKER: == replay-dual test 15c: remove multiple OST orphans ===== 17:58:53 (1788213533) [ 1560.132655] LustreError: 35588:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 1560.138642] LustreError: 35588:0:(osd_handler.c:715:osd_ro()) Skipped 3 previous similar messages [ 1561.170602] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1669.078304] Lustre: Failing over lustre-MDT0000 [ 1669.737512] Lustre: server umount lustre-MDT0000 complete [ 1687.455305] 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 [ 1687.466612] Lustre: Skipped 7 previous similar messages [ 1687.478239] LustreError: MGC192.168.202.133@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1687.489980] LustreError: Skipped 3 previous similar messages [ 1697.763608] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xc184202f28ef4232 [ 1698.441523] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1698.453747] Lustre: Skipped 2 previous similar messages [ 1704.819880] Lustre: DEBUG MARKER: oleg233-server.virtnet: executing set_default_debug -1 all [ 1769.506422] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 1769.516281] Lustre: 36352:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 2b61c733-b2b8-4302-8ef6-33805a23ad63@ [ 1769.542797] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 1769.685279] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:494 to 0x280000400:1537) [ 1769.685931] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:495 to 0x240000400:1537) [ 1778.698624] Lustre: DEBUG MARKER: oleg233-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1780.815342] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1792.456791] Lustre: DEBUG MARKER: == replay-dual test 16: fail MDS during recovery (3571) == 18:02:48 (1788213768) [ 1797.078238] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1800.558852] Lustre: Failing over lustre-MDT0000 [ 1800.986059] Lustre: server umount lustre-MDT0000 complete [ 1826.630228] Lustre: DEBUG MARKER: oleg233-server.virtnet: executing set_default_debug -1 all [ 1852.201171] Lustre: Failing over lustre-MDT0000 [ 1852.221915] LustreError: 38462:0:(ldlm_lib.c:3029:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 1852.235214] Lustre: 37988:0:(ldlm_lib.c:2429:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 1852.240319] Lustre: 37988:0:(ldlm_lib.c:1939:abort_req_replay_queue()) @@@ aborted: req@ffff95bbf71e2300 x1875076218152832/t0(73014444037) o101->66ffe90d-8ff5-453b-a1b4-29c6a3766d40@192.168.202.33@tcp:119/0 lens 592/0 e 2 to 0 dl 1788213844 ref 1 fl Complete:/604/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 1852.258338] Lustre: lustre-MDT0000-osd: cancel update llog [0x200000400:0x1:0x0] [ 1852.275575] Lustre: lustre-MDT0000: Not available for connect from 192.168.202.33@tcp (stopping) [ 1852.955724] Lustre: server umount lustre-MDT0000 complete [ 1872.351210] Lustre: 3301:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788213835/real 1788213835] req@ffff95bbc50bea00 x1875076237937536/t0(0) o400->MGC192.168.202.133@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1788213851 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1872.388063] Lustre: 3301:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 44 previous similar messages [ 1883.289803] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1883.295197] Lustre: Skipped 4 previous similar messages [ 1889.341891] Lustre: DEBUG MARKER: oleg233-server.virtnet: executing set_default_debug -1 all [ 1961.502583] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 1961.506593] Lustre: 38956:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 4f486e0b-5926-427a-b2b4-c3db9aa9aab9@ [ 1961.536518] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 1962.395277] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1551 to 0x280000400:1569) [ 1962.402670] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1550 to 0x240000400:1569) [ 1969.516860] Lustre: DEBUG MARKER: oleg233-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1971.598263] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1982.834647] Lustre: DEBUG MARKER: == replay-dual test 17: fail OST during recovery (3571) == 18:05:59 (1788213959) [ 1988.603219] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 1990.938869] Lustre: Failing over lustre-OST0000 [ 1991.078726] Lustre: server umount lustre-OST0000 complete [ 1993.195196] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 1993.217916] LustreError: 6694:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1993.240701] LustreError: 6694:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 1 previous similar message [ 1994.732955] LustreError: 35409:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1999.841139] LustreError: 35409:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1999.890063] LustreError: 35409:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 1 previous similar message [ 2004.967483] LustreError: 35409:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 2004.993489] LustreError: 35409:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 1 previous similar message [ 2010.084658] LustreError: 35409:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 2010.102022] LustreError: 35409:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 1 previous similar message [ 2010.998185] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 2011.014124] Lustre: Skipped 3 previous similar messages [ 2017.440559] Lustre: DEBUG MARKER: oleg233-server.virtnet: executing set_default_debug -1 all [ 2042.490578] Lustre: Failing over lustre-OST0000 [ 2042.502050] LustreError: 41116:0:(ldlm_lib.c:3029:target_stop_recovery_thread()) lustre-OST0000: Aborting recovery [ 2042.507770] Lustre: 40549:0:(ldlm_lib.c:2429:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 2042.512537] Lustre: 40549:0:(ldlm_lib.c:2429:target_recovery_overseer()) Skipped 2 previous similar messages [ 2042.516451] LustreError: 40549:0:(ofd_obd.c:1325:ofd_iocontrol()) lustre-OST0000: iocontrol from 'tgt_recover_0' cmd=c00866c1 _IOWR('f', 193, 8) unrecognized: rc = -25 [ 2042.596546] Lustre: server umount lustre-OST0000 complete [ 2052.065520] LustreError: 6694:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 2069.311836] Lustre: DEBUG MARKER: oleg233-server.virtnet: executing set_default_debug -1 all [ 2132.501340] Lustre: lustre-OST0000: recovery is timed out, evict stale exports [ 2132.507324] Lustre: 41578:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-OST0000: disconnect stale client 501cdaa6-ee12-48c9-9f66-839854d065b6@ [ 2132.513649] Lustre: lustre-OST0000: disconnecting 1 stale clients [ 2132.609615] Lustre: lustre-OST0000: Recovery over after 1:10, of 3 clients 2 recovered and 1 was evicted. [ 2132.612890] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 2132.614171] Lustre: Skipped 4 previous similar messages [ 2132.622286] Lustre: Skipped 8 previous similar messages [ 2140.361505] Lustre: DEBUG MARKER: oleg233-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 2142.040878] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 2152.345429] Lustre: DEBUG MARKER: == replay-dual test 18: ldlm_handle_enqueue succeeds on evicted export (3822) ========================================================== 18:08:49 (1788214129) [ 2157.289308] LustreError: 38917:0:(ldlm_lockd.c:1361:ldlm_handle_enqueue()) cfs_fail_timeout id 30b sleeping for 40000ms [ 2197.393991] LustreError: 38917:0:(ldlm_lockd.c:1361:ldlm_handle_enqueue()) cfs_fail_timeout id 30b awake [ 2212.009842] Lustre: DEBUG MARKER: == replay-dual test 19: resend of open request =========== 18:09:49 (1788214189) [ 2214.814050] LustreError: 43129:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 2214.816812] LustreError: 43129:0:(osd_handler.c:715:osd_ro()) Skipped 2 previous similar messages [ 2215.483534] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2216.813891] Lustre: *** cfs_fail_loc=157, val=2147483648*** [ 2216.820987] LustreError: 38918:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff95bbfbe60e00 x1875076218256768/t0(0) o101->66ffe90d-8ff5-453b-a1b4-29c6a3766d40@192.168.202.33@tcp:552/0 lens 576/688 e 0 to 0 dl 1788214277 ref 1 fl Interpret:/600/0 rc 0/0 job:'createmany.0' uid:0 gid:0 projid:0 [ 2303.897874] Lustre: lustre-MDT0000: Client 66ffe90d-8ff5-453b-a1b4-29c6a3766d40 (at 192.168.202.33@tcp) reconnecting [ 2308.498911] Lustre: Failing over lustre-MDT0000 [ 2309.052956] Lustre: server umount lustre-MDT0000 complete [ 2325.987393] LustreError: MGC192.168.202.133@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2326.012929] LustreError: Skipped 2 previous similar messages [ 2336.226060] LustreError: 3300:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff95bbf6e3d500 x1875076238039040/t0(0) o250->MGC192.168.202.133@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 [ 2337.329783] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 2337.355760] Lustre: Skipped 4 previous similar messages [ 2337.820060] Lustre: 43910:0:(ldlm_lib.c:2110:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 2338.015471] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1584 to 0x240000400:1601) [ 2338.018539] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1584 to 0x280000400:1601) [ 2342.408169] 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 [ 2342.449606] Lustre: Skipped 6 previous similar messages [ 2342.921078] Lustre: DEBUG MARKER: oleg233-server.virtnet: executing set_default_debug -1 all [ 2353.513741] Lustre: DEBUG MARKER: oleg233-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2355.326168] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2364.682296] Lustre: DEBUG MARKER: == replay-dual test 20: recovery time is not increasing == 18:12:21 (1788214341) [ 2368.992276] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2371.264040] Lustre: Failing over lustre-MDT0000 [ 2371.598534] Lustre: server umount lustre-MDT0000 complete [ 2405.110667] Lustre: DEBUG MARKER: oleg233-server.virtnet: executing set_default_debug -1 all [ 2474.847453] Lustre: 3301:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788214367/real 1788214367] req@ffff95bac3280000 x1875076238055168/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788214453 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2474.879116] Lustre: 3301:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 29 previous similar messages [ 2541.501730] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 2541.509593] Lustre: 45515:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 6b15e7c7-194d-4df5-934a-10c361b62834@ [ 2541.533467] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 2541.597501] Lustre: 45515:0:(ldlm_lib.c:2110:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 2541.617638] Lustre: 45515:0:(ldlm_lib.c:2110:extend_recovery_timer()) Skipped 2 previous similar messages [ 2541.827242] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1603 to 0x240000400:1633) [ 2541.827858] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1584 to 0x280000400:1633) [ 2548.957346] Lustre: DEBUG MARKER: oleg233-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2550.448730] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2557.862403] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2560.121969] Lustre: Failing over lustre-MDT0000 [ 2560.593171] Lustre: server umount lustre-MDT0000 complete [ 2589.583271] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 2589.592839] Lustre: Skipped 4 previous similar messages [ 2595.210466] Lustre: DEBUG MARKER: oleg233-server.virtnet: executing set_default_debug -1 all [ 2730.500115] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 2730.506080] Lustre: 46937:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client a609223e-028f-48be-a046-da11dcd85a5c@ [ 2730.513329] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 2730.604605] Lustre: 46937:0:(ldlm_lib.c:2110:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 2730.618923] Lustre: 46937:0:(ldlm_lib.c:2110:extend_recovery_timer()) Skipped 2 previous similar messages [ 2730.824621] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1635 to 0x280000400:1665) [ 2730.825947] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1603 to 0x240000400:1665) [ 2737.808273] Lustre: DEBUG MARKER: oleg233-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2740.400202] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2751.117060] Lustre: DEBUG MARKER: == replay-dual test 21a: commit on sharing =============== 18:18:48 (1788214728) [ 2756.265230] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2758.671210] Lustre: Failing over lustre-MDT0000 [ 2758.976037] Lustre: server umount lustre-MDT0000 complete [ 2779.038739] LustreError: 48592:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.202.33@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 2779.055644] LustreError: 48592:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 1 previous similar message [ 2781.084493] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 2781.096175] Lustre: Skipped 4 previous similar messages [ 2784.762796] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 2784.774638] Lustre: DEBUG MARKER: oleg233-server.virtnet: executing set_default_debug -1 all [ 2784.775641] Lustre: Skipped 6 previous similar messages [ 2921.500103] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 2921.508215] Lustre: 48629:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 8771ba29-f06f-4547-9589-7a01c264cd1e@ [ 2921.523710] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 2921.573742] Lustre: lustre-MDT0000: Recovery over after 2:20, of 2 clients 1 recovered and 1 was evicted. [ 2921.579309] Lustre: Skipped 3 previous similar messages [ 2921.639415] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1667 to 0x240000400:1697) [ 2921.641221] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1635 to 0x280000400:1697) [ 2932.116480] Lustre: DEBUG MARKER: SKIP: replay-dual test_21b skipping SLOW test 21b [ 2933.837564] Lustre: DEBUG MARKER: == replay-dual test 22a: c1 lfs mkdir -i 1 dir1, M1 drop reply [ 2935.384437] Lustre: DEBUG MARKER: SKIP: replay-dual test_22a needs >= 2 MDTs [ 2937.230171] Lustre: DEBUG MARKER: == replay-dual test 22b: c1 lfs mkdir -i 1 d1, M1 drop reply [ 2938.509663] Lustre: DEBUG MARKER: SKIP: replay-dual test_22b needs >= 2 MDTs [ 2940.058591] Lustre: DEBUG MARKER: == replay-dual test 22c: c1 lfs mkdir -i 1 d1, M1 drop update [ 2941.527559] Lustre: DEBUG MARKER: SKIP: replay-dual test_22c needs >= 2 MDTs [ 2943.131337] Lustre: DEBUG MARKER: == replay-dual test 22d: c1 lfs mkdir -i 1 d1, M1 drop update [ 2944.467208] Lustre: DEBUG MARKER: SKIP: replay-dual test_22d needs >= 2 MDTs [ 2946.307942] Lustre: DEBUG MARKER: == replay-dual test 23a: c1 rmdir d1, M1 drop reply and fail, client2 mkdir d1 ========================================================== 18:22:03 (1788214923) [ 2948.079703] Lustre: DEBUG MARKER: SKIP: replay-dual test_23a needs >= 2 MDTs [ 2950.342280] Lustre: DEBUG MARKER: == replay-dual test 23b: c1 rmdir d1, M1 drop reply and fail M0/M1, c2 mkdir d1 ========================================================== 18:22:07 (1788214927) [ 2952.452965] Lustre: DEBUG MARKER: SKIP: replay-dual test_23b needs >= 2 MDTs [ 2954.595872] Lustre: DEBUG MARKER: == replay-dual test 23c: c1 rmdir d1, M0 drop update reply and fail M0, c2 mkdir d1 ========================================================== 18:22:11 (1788214931) [ 2956.715936] Lustre: DEBUG MARKER: SKIP: replay-dual test_23c needs >= 2 MDTs [ 2958.842897] Lustre: DEBUG MARKER: == replay-dual test 23d: c1 rmdir d1, M0 drop update reply and fail M0/M1, c2 mkdir d1 ========================================================== 18:22:15 (1788214935) [ 2960.875644] Lustre: DEBUG MARKER: SKIP: replay-dual test_23d needs >= 2 MDTs [ 2963.033820] Lustre: DEBUG MARKER: == replay-dual test 24: reconstruct on non-existing object ========================================================== 18:22:19 (1788214939) [ 2964.855485] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 2964.861051] LustreError: 48593:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff95bbfc2b2a00 x1875076218354560/t94489280518(0) o36->66ffe90d-8ff5-453b-a1b4-29c6a3766d40@192.168.202.33@tcp:543/0 lens 488/456 e 0 to 0 dl 1788215023 ref 1 fl Interpret:/200/0 rc 0/0 job:'truncate.0' uid:0 gid:0 projid:4294967295 [ 3050.464201] Lustre: lustre-MDT0000: Client 66ffe90d-8ff5-453b-a1b4-29c6a3766d40 (at 192.168.202.33@tcp) reconnecting [ 3050.509334] Lustre: 48594:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff95bbfa67f100 x1875076218354560/t94489280518(0) o36->66ffe90d-8ff5-453b-a1b4-29c6a3766d40@192.168.202.33@tcp:629/0 lens 488/3152 e 0 to 0 dl 1788215109 ref 1 fl Interpret:/202/0 rc 0/0 job:'truncate.0' uid:0 gid:0 projid:4294967295 [ 3062.388908] Lustre: DEBUG MARKER: == replay-dual test 25: replay|resend ==================== 18:23:59 (1788215039) [ 3064.162666] Lustre: *** cfs_fail_loc=304, val=0*** [ 3066.929985] Lustre: Failing over lustre-OST0000 [ 3067.128323] Lustre: server umount lustre-OST0000 complete [ 3070.440543] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 3070.450425] Lustre: lustre-OST0000-osc-MDT0000: Connection to lustre-OST0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 3070.461112] Lustre: Skipped 7 previous similar messages [ 3070.469137] LustreError: 6693:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3070.481613] LustreError: 6693:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 2 previous similar messages [ 3075.958345] LustreError: 11873:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.202.33@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3075.973955] LustreError: 11873:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 4 previous similar messages [ 3086.212980] LustreError: 42413:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.202.33@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3086.227207] LustreError: 42413:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 5 previous similar messages [ 3088.343847] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 3088.365934] Lustre: Skipped 3 previous similar messages [ 3098.953769] Lustre: DEBUG MARKER: oleg233-server.virtnet: executing set_default_debug -1 all [ 3110.194192] Lustre: DEBUG MARKER: oleg233-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 3112.368994] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 3125.216412] Lustre: DEBUG MARKER: == replay-dual test 26: dbench and tar with mds failover ========================================================== 18:25:02 (1788215102) [ 3131.755097] LustreError: 52291:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 3131.764299] LustreError: 52291:0:(osd_handler.c:715:osd_ro()) Skipped 3 previous similar messages [ 3133.272913] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3137.330183] Lustre: DEBUG MARKER: test_26 fail mds1 1 times [ 3139.583444] Lustre: Failing over lustre-MDT0000 [ 3139.886407] Lustre: server umount lustre-MDT0000 complete [ 3161.003339] LustreError: MGC192.168.202.133@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3161.025838] LustreError: Skipped 3 previous similar messages [ 3161.032435] Lustre: 3302:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788215123/real 1788215123] req@ffff95bac78b4000 x1875076238224384/t0(0) o400->MGC192.168.202.133@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1788215139 ref 1 fl Rpc:EXNQr/200/ffffffff rc -5/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3161.067216] Lustre: 3302:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 28 previous similar messages [ 3167.061341] Lustre: DEBUG MARKER: oleg233-server.virtnet: executing set_default_debug -1 all [ 3178.509626] Lustre: 52977:0:(ldlm_lib.c:2110:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3178.516282] Lustre: 52977:0:(ldlm_lib.c:2110:extend_recovery_timer()) Skipped 2 previous similar messages [ 3181.240060] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1745 to 0x280000400:1761) [ 3181.240935] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1747 to 0x240000400:1793) [ 3189.272805] Lustre: DEBUG MARKER: oleg233-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3191.225819] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3200.337049] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3204.848584] Lustre: DEBUG MARKER: test_26 fail mds1 2 times [ 3207.649890] Lustre: Failing over lustre-MDT0000 [ 3207.803350] LustreError: 52940:0:(ldlm_lockd.c:1453:ldlm_handle_enqueue()) ### lock on destroyed export 00000000cfa66e55 ns: mdt-lustre-MDT0000_UUID lock: ffff95bac2402c00/0xc184202f28f051a3 lrc: 3/0,0 mode: CW/CW res: [0x20000afe1:0x5b:0x0].0x0 bits 0x5/0x0 rrc: 2 type: IBT gid 0 flags: 0x50200000000000 nid: 192.168.202.33@tcp remote: 0xa5ef1013fffa7fb9 expref: 4 pid: 52940 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 [ 3208.163060] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3209.079313] Lustre: lustre-MDT0000: Not available for connect from 192.168.202.33@tcp (stopping) [ 3209.082203] Lustre: Skipped 1 previous similar message [ 3213.281463] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3213.292201] Lustre: Skipped 2 previous similar messages [ 3214.224533] LustreError: 52941:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.202.33@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3214.254913] LustreError: 52941:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 2 previous similar messages [ 3214.473892] Lustre: server umount lustre-MDT0000 complete [ 3234.987265] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3234.990330] Lustre: Skipped 3 previous similar messages [ 3239.868486] Lustre: DEBUG MARKER: oleg233-server.virtnet: executing set_default_debug -1 all [ 3244.044682] Lustre: 54474:0:(ldlm_lib.c:2110:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3244.058657] Lustre: 54474:0:(ldlm_lib.c:2110:extend_recovery_timer()) Skipped 275 previous similar messages [ 3246.766594] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1847 to 0x280000400:1889) [ 3246.769086] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1879 to 0x240000400:1921) [ 3253.280761] Lustre: DEBUG MARKER: oleg233-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3255.573046] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3264.411893] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3268.094710] Lustre: DEBUG MARKER: test_26 fail mds1 3 times [ 3270.335512] Lustre: Failing over lustre-MDT0000 [ 3270.797087] Lustre: server umount lustre-MDT0000 complete [ 3289.984689] Lustre: lustre-MDT0000: Not available for connect from 192.168.202.33@tcp (not set up) [ 3292.033920] Lustre: 55932:0:(ldlm_lib.c:2110:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3292.041505] Lustre: 55932:0:(ldlm_lib.c:2110:extend_recovery_timer()) Skipped 274 previous similar messages [ 3295.883667] Lustre: DEBUG MARKER: oleg233-server.virtnet: executing set_default_debug -1 all [ 3296.259082] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1993 to 0x240000400:2017) [ 3296.267981] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1961 to 0x280000400:1985) [ 3309.046715] Lustre: DEBUG MARKER: oleg233-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3310.989905] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3320.368437] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3324.227823] Lustre: DEBUG MARKER: test_26 fail mds1 4 times [ 3327.124347] Lustre: Failing over lustre-MDT0000 [ 3327.198439] LustreError: 55894:0:(ldlm_lockd.c:1453:ldlm_handle_enqueue()) ### lock on destroyed export 00000000798ba5ae ns: mdt-lustre-MDT0000_UUID lock: ffff95bac6fb3600/0xc184202f28f151f5 lrc: 3/0,0 mode: PR/PR res: [0x20000afe1:0xc4:0x0].0x0 bits 0x1b/0x0 rrc: 2 type: IBT gid 0 flags: 0x50200000000000 nid: 192.168.202.33@tcp remote: 0xa5ef1013fffabdbd expref: 49 pid: 55894 timeout: 0 lvb_type: 0 lru_score: 0 lru_type: 0 [ 3327.295124] Lustre: lustre-MDT0000: Not available for connect from 192.168.202.33@tcp (stopping) [ 3327.299236] Lustre: Skipped 1 previous similar message [ 3327.834901] Lustre: server umount lustre-MDT0000 complete [ 3357.154863] LustreError: 3300:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff95bac8286300 x1875076238431488/t0(0) o250->MGC192.168.202.133@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 [ 3363.246549] Lustre: DEBUG MARKER: oleg233-server.virtnet: executing set_default_debug -1 all [ 3365.816452] Lustre: 57384:0:(ldlm_lib.c:2110:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3365.825136] Lustre: 57384:0:(ldlm_lib.c:2110:extend_recovery_timer()) Skipped 328 previous similar messages [ 3368.316376] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2091 to 0x240000400:2113) [ 3368.321437] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2059 to 0x280000400:2145) [ 3375.419578] Lustre: DEBUG MARKER: oleg233-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3377.324296] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3428.069911] Lustre: DEBUG MARKER: == replay-dual test 28: lock replay should be ordered: waiting after granted ========================================================== 18:30:05 (1788215405) [ 3455.624314] Lustre: Failing over lustre-OST0000 [ 3455.742724] Lustre: server umount lustre-OST0000 complete [ 3457.939271] LustreError: 55097:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.202.33@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3476.645588] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 3476.657049] Lustre: Skipped 5 previous similar messages [ 3477.587496] Lustre: *** cfs_fail_loc=32a, val=0*** [ 3477.751915] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 3477.761830] Lustre: Skipped 10 previous similar messages [ 3483.479481] Lustre: DEBUG MARKER: oleg233-server.virtnet: executing set_default_debug -1 all [ 3494.494240] Lustre: DEBUG MARKER: oleg233-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 3496.212523] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 3507.425133] Lustre: DEBUG MARKER: == replay-dual test 29: replay vs update with the same xid ========================================================== 18:31:24 (1788215484) [ 3508.888285] Lustre: DEBUG MARKER: SKIP: replay-dual test_29 needs >= 2 MDTs [ 3510.947946] Lustre: DEBUG MARKER: == replay-dual test 30: layout lock replay is not blocked on IO ========================================================== 18:31:27 (1788215487) [ 3514.164091] Lustre: Failing over lustre-MDT0000 [ 3514.293431] Lustre: lustre-MDT0000: Not available for connect from 192.168.202.33@tcp (stopping) [ 3514.781598] Lustre: server umount lustre-MDT0000 complete [ 3549.152862] Lustre: DEBUG MARKER: oleg233-server.virtnet: executing set_default_debug -1 all [ 3558.080396] Lustre: 60899:0:(ldlm_lib.c:2110:extend_recovery_timer()) lustre-MDT0000: extended recovery timer reached hard limit: 180, extend: 1 [ 3558.111746] Lustre: 60899:0:(ldlm_lib.c:2110:extend_recovery_timer()) Skipped 272 previous similar messages [ 3558.202437] Lustre: lustre-MDT0000: Recovery over after 0:05, of 2 clients 2 recovered and 0 were evicted. [ 3558.226601] Lustre: Skipped 6 previous similar messages [ 3558.313976] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2148 to 0x240000400:2177) [ 3558.315022] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2179 to 0x280000400:2209) [ 3564.761832] Lustre: DEBUG MARKER: oleg233-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3566.438976] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3575.870661] Lustre: DEBUG MARKER: == replay-dual test 31: deadlock on file_remove_privs and occupied mod rpc slots ========================================================== 18:32:32 (1788215552) [ 3580.560525] Lustre: Failing over lustre-OST0000 [ 3580.705337] Lustre: server umount lustre-OST0000 complete [ 3583.038862] LustreError: lustre-OST0000-osc-MDT0000: operation ost_create to node 0@lo failed: rc = -107 [ 3583.056665] LustreError: 54998:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3583.076520] LustreError: 54998:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 10 previous similar messages [ 3607.714238] Lustre: DEBUG MARKER: oleg233-server.virtnet: executing set_default_debug -1 all [ 3617.959643] Lustre: DEBUG MARKER: oleg233-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 3619.501969] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL [ 3630.514463] Lustre: DEBUG MARKER: == replay-dual test 32: gap in update llog shouldn't break recovery ========================================================== 18:33:27 (1788215607) [ 3632.229259] Lustre: DEBUG MARKER: SKIP: replay-dual test_32 needs >= 2 MDTs [ 3634.095173] Lustre: DEBUG MARKER: == replay-dual test 33: Check for OBD_INCOMPAT_MULTI_RPCS in last_rcvd after abort_recovery ========================================================== 18:33:31 (1788215611) [ 3635.788814] Lustre: DEBUG MARKER: SKIP: replay-dual test_33 ldiskfs only test [ 3637.597785] Lustre: DEBUG MARKER: == replay-dual test complete, duration 3392 sec ========== 18:33:34 (1788215614) [ 3639.511299] Lustre: DEBUG MARKER: === replay-dual: start cleanup 18:33:36 (1788215616) === [ 3646.763312] Lustre: DEBUG MARKER: === replay-dual: finish cleanup 18:33:43 (1788215623) === [ 3649.060744] Lustre: Failing over lustre-MDT0000 [ 3649.598239] Lustre: server umount lustre-MDT0000 complete [ 3678.225716] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2179 to 0x280000400:2241) [ 3678.226346] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2217 to 0x240000400:2305) [ 3682.559516] Lustre: DEBUG MARKER: oleg233-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3682.797368] 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 [ 3682.821079] Lustre: Skipped 13 previous similar messages [ 3693.131654] Lustre: DEBUG MARKER: oleg233-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3694.734196] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3700.472371] Lustre: server umount lustre-MDT0000 complete [ 3704.439757] LustreError: 5829:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788215683 with bad export cookie 13944305733168444914 [ 3714.138247] Lustre: server umount lustre-OST0000 complete [ 3728.852239] Lustre: server umount lustre-OST0001 complete [ 3741.285213] Lustre: DEBUG MARKER: oleg233-server.virtnet: executing unload_modules_local [ 3743.805696] Key type lgssc unregistered [ 3744.082963] LNet: 66067:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 3744.088362] LNetError: 66067:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 3744.105375] LNet: Removed LNI 192.168.202.133@tcp [ 3744.969192] Key type .llcrypt unregistered [ 3744.972888] Key type ._llcrypt unregistered