[ 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-0x00000000bffd9fff] usable [ 0.000000] BIOS-e820: [mem 0x00000000bffda000-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 688191910 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2400.000 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 = 0xbffda max_arch_pfn = 0x400000000 [ 0.000000] found SMP MP-table at [mem 0x000f54d0-0x000f54df] [ 0.000000] RAMDISK: [mem 0xbcc64000-0xbffcffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F52F0 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE2464 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE2300 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 0022C0 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE2374 000090 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE2404 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE243C 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe2300-0xbffe2373] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe22ff] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe2374-0xbffe2403] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe2404-0xbffe243b] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe243c-0xbffe2463] [ 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-0x00000000bffd9fff] [ 0.000000] node 0: [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Zeroed struct page in unavailable ranges: 4744 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 0xbffda000-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: 1059618 [ 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: 2829700K/4306400K 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.001013] APIC: Switch to symmetric I/O mode setup [ 0.002411] x2apic enabled [ 0.003011] Switched APIC routing to physical x2apic. [ 0.004015] kvm-guest: setup PV IPIs [ 0.007707] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.008000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x22983777dd9, max_idle_ns: 440795300422 ns [ 0.008025] Calibrating delay loop (skipped) preset value.. 4800.00 BogoMIPS (lpj=2400000) [ 0.009014] pid_max: default: 32768 minimum: 301 [ 0.010151] LSM: Security Framework initializing [ 0.011074] Yama: becoming mindful. [ 0.012052] SELinux: Initializing. [ 0.013084] *** VALIDATE selinux *** [ 0.025048] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.035340] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.037155] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.038114] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.039132] *** VALIDATE tmpfs *** [ 0.040532] *** VALIDATE proc *** [ 0.041000] *** VALIDATE cgroup *** [ 0.041018] *** VALIDATE cgroup2 *** [ 0.043025] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.044155] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.045011] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.046032] Spectre V2 : User space: Vulnerable [ 0.047016] Speculative Store Bypass: Vulnerable [ 0.050406] debug: unmapping init [mem 0xffffffff90a59000-0xffffffff90a60fff] [ 0.053611] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.055124] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.057027] ... version: 2 [ 0.058019] ... bit width: 48 [ 0.059017] ... generic registers: 4 [ 0.060020] ... value mask: 0000ffffffffffff [ 0.061019] ... max period: 00007fffffffffff [ 0.062018] ... fixed-purpose events: 3 [ 0.063021] ... event mask: 000000070000000f [ 0.064273] rcu: Hierarchical SRCU implementation. [ 0.067083] smp: Bringing up secondary CPUs ... [ 0.069329] x86: Booting SMP configuration: [ 0.070025] .... node #0, CPUs: #1 #2 #3 [ 0.082105] smp: Brought up 1 node, 4 CPUs [ 0.084015] smpboot: Max logical packages: 1 [ 0.085015] smpboot: Total of 4 processors activated (19200.00 BogoMIPS) [ 0.162022] node 0 deferred pages initialised in 72ms [ 0.171308] devtmpfs: initialized [ 0.174494] x86/mm: Memory block size: 128MB [ 0.192854] gcov: version magic: 0x41383552 [ 0.195461] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.196341] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.203533] pinctrl core: initialized pinctrl subsystem [ 0.209250] [ 0.212014] ************************************************************* [ 0.219016] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.226014] ** ** [ 0.234021] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.240021] ** ** [ 0.248016] ** This means that this kernel is built to expose internal ** [ 0.254020] ** IOMMU data structures, which may compromise security on ** [ 0.258015] ** your system. ** [ 0.260015] ** ** [ 0.262012] ** If you see this message and you are not debugging the ** [ 0.273022] ** kernel, report this immediately to your vendor! ** [ 0.279014] ** ** [ 0.285014] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.289019] ************************************************************* [ 0.296094] NET: Registered protocol family 16 [ 0.302000] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.308072] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.312000] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.322135] cpuidle: using governor menu [ 0.327227] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.334085] PCI: Using configuration type 1 for base access [ 0.337476] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.355773] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.358000] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.367000] cryptd: max_cpu_qlen set to 1000 [ 0.369031] ACPI: Added _OSI(Module Device) [ 0.370014] ACPI: Added _OSI(Processor Device) [ 0.371049] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.373023] ACPI: Added _OSI(Processor Aggregator Device) [ 0.383046] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.395258] ACPI: Interpreter enabled [ 0.401074] ACPI: PM: (supports S0 S3 S4 S5) [ 0.405021] ACPI: Using IOAPIC for interrupt routing [ 0.408280] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.416520] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.435244] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.438053] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.441021] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.445083] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.451898] acpiphp: Slot [2] registered [ 0.454140] acpiphp: Slot [5] registered [ 0.456207] acpiphp: Slot [6] registered [ 0.457416] acpiphp: Slot [3] registered [ 0.459132] acpiphp: Slot [4] registered [ 0.461119] acpiphp: Slot [7] registered [ 0.463130] acpiphp: Slot [8] registered [ 0.465137] acpiphp: Slot [9] registered [ 0.467142] acpiphp: Slot [10] registered [ 0.469403] acpiphp: Slot [11] registered [ 0.471275] acpiphp: Slot [12] registered [ 0.473316] acpiphp: Slot [13] registered [ 0.475147] acpiphp: Slot [14] registered [ 0.477126] acpiphp: Slot [15] registered [ 0.479136] acpiphp: Slot [16] registered [ 0.481217] acpiphp: Slot [17] registered [ 0.483151] acpiphp: Slot [18] registered [ 0.485126] acpiphp: Slot [19] registered [ 0.487224] acpiphp: Slot [20] registered [ 0.488104] acpiphp: Slot [21] registered [ 0.490141] acpiphp: Slot [22] registered [ 0.492164] acpiphp: Slot [23] registered [ 0.494158] acpiphp: Slot [24] registered [ 0.496133] acpiphp: Slot [25] registered [ 0.498147] acpiphp: Slot [26] registered [ 0.500131] acpiphp: Slot [27] registered [ 0.503233] acpiphp: Slot [28] registered [ 0.505136] acpiphp: Slot [29] registered [ 0.508156] acpiphp: Slot [30] registered [ 0.510777] acpiphp: Slot [31] registered [ 0.513079] PCI host bridge to bus 0000:00 [ 0.514024] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.518024] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.524026] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.531025] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.536025] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.541029] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.545000] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.549873] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.553000] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.575015] pci 0000:00:01.1: reg 0x20: [io 0xc120-0xc12f] [ 0.586059] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.591021] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.601020] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.609020] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.617779] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.624569] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.632590] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.636085] pci 0000:00:01.3: quirk_piix4_acpi+0x0/0x1e0 took 11718 usecs [ 0.644776] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.657022] pci 0000:00:02.0: reg 0x10: [io 0xc100-0xc11f] [ 0.687017] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.697015] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.712222] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.724016] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.738019] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.768014] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.782000] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.788014] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.800018] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.819019] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.832259] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.834411] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.838400] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.840464] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.842187] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.846106] iommu: Default domain type: Passthrough [ 0.848318] SCSI subsystem initialized [ 0.849301] ACPI: bus type USB registered [ 0.851105] usbcore: registered new interface driver usbfs [ 0.852172] usbcore: registered new interface driver hub [ 0.855098] usbcore: registered new device driver usb [ 0.857240] pps_core: LinuxPPS API ver. 1 registered [ 0.860011] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.864087] PTP clock support registered [ 0.866158] EDAC MC: Ver: 3.0.0 [ 0.867212] PCI: Using ACPI for IRQ routing [ 0.870020] NetLabel: Initializing [ 0.871009] NetLabel: domain hash size = 128 [ 0.873012] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.875087] NetLabel: unlabeled traffic allowed by default [ 0.878377] vgaarb: loaded [ 0.880276] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.882012] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.887000] clocksource: Switched to clocksource kvm-clock [ 1.015689] VFS: Disk quotas dquot_6.6.0 [ 1.018766] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 1.024530] *** VALIDATE ramfs *** [ 1.027110] *** VALIDATE hugetlbfs *** [ 1.029623] pnp: PnP ACPI init [ 1.032709] pnp: PnP ACPI: found 6 devices [ 1.051228] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 1.056438] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 1.059983] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 1.063302] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 1.066911] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 1.070623] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 1.075147] NET: Registered protocol family 2 [ 1.078607] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 1.084933] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 1.090221] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 1.097360] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 1.102446] TCP: Hash tables configured (established 65536 bind 65536) [ 1.106599] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 1.110710] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 1.114477] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 1.118796] NET: Registered protocol family 1 [ 1.122352] RPC: Registered named UNIX socket transport module. [ 1.126052] RPC: Registered udp transport module. [ 1.128734] RPC: Registered tcp transport module. [ 1.131446] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 1.134613] NET: Registered protocol family 44 [ 1.137150] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 1.140360] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 1.143548] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 1.146756] PCI: CLS 0 bytes, default 64 [ 1.149876] Unpacking initramfs... [ 4.163933] debug: unmapping init [mem 0xffff91f6fcc64000-0xffff91f6fffcffff] [ 4.174466] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 4.181057] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 4.189348] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x22983777dd9, max_idle_ns: 440795300422 ns [ 6.003165] Initialise system trusted keyrings [ 6.009912] Key type blacklist registered [ 6.016558] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 6.032165] zbud: loaded [ 6.036701] *** VALIDATE nfs *** [ 6.039314] *** VALIDATE nfs4 *** [ 6.041225] pstore: using deflate compression [ 6.045140] Platform Keyring initialized [ 6.432318] NET: Registered protocol family 38 [ 6.434201] Key type asymmetric registered [ 6.442439] Asymmetric key parser 'x509' registered [ 6.445008] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 6.452886] io scheduler mq-deadline registered [ 6.455523] io scheduler kyber registered [ 6.458159] io scheduler bfq registered [ 6.460564] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 6.465748] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 6.472972] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 6.482493] ACPI: Power Button [PWRF] [ 6.510795] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 6.537491] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 6.568566] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 6.616188] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 6.657277] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 6.670625] Non-volatile memory driver v1.3 [ 6.675766] Linux agpgart interface v0.103 [ 6.758274] virtio_blk virtio1: [vda] 145904 512-byte logical blocks (74.7 MB/71.2 MiB) [ 6.770181] vda: detected capacity change from 0 to 74702848 [ 6.813691] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 6.818203] vdb: detected capacity change from 0 to 1073741824 [ 6.833345] libphy: Fixed MDIO Bus: probed [ 6.842740] usbcore: registered new interface driver usbserial_generic [ 6.846943] usbserial: USB Serial support registered for generic [ 6.851054] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 6.857178] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 6.859933] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 6.863199] mousedev: PS/2 mouse device common for all mice [ 6.867671] rtc_cmos 00:05: RTC can wake from S4 [ 6.871852] rtc_cmos 00:05: registered as rtc0 [ 6.873593] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 6.877862] intel_pstate: CPU model not supported [ 6.881781] hid: raw HID events driver (C) Jiri Kosina [ 6.884418] usbcore: registered new interface driver usbhid [ 6.886913] usbhid: USB HID core driver [ 6.887147] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 6.891133] drop_monitor: Initializing network drop monitor service [ 6.897851] Initializing XFRM netlink socket [ 6.900523] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 6.907286] NET: Registered protocol family 10 [ 6.911907] Segment Routing with IPv6 [ 6.913453] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 6.914626] NET: Registered protocol family 17 [ 6.930321] mpls_gso: MPLS GSO support [ 6.942469] RAS: Correctable Errors collector initialized. [ 6.945237] AVX version of gcm_enc/dec engaged. [ 6.946859] AES CTR mode by8 optimization enabled [ 7.062846] sched_clock: Marking stable (7062822500, 0)->(8472185296, -1409362796) [ 7.070267] registered taskstats version 1 [ 7.074631] Loading compiled-in X.509 certificates [ 7.079650] zswap: loaded using pool lzo/zbud [ 7.119288] Key type big_key registered [ 7.137412] Key type encrypted registered [ 7.143630] ima: No TPM chip found, activating TPM-bypass! [ 7.146650] ima: Allocated hash algorithm: sha1 [ 7.150934] ima: No architecture policies found [ 7.153524] evm: Initialising EVM extended attributes: [ 7.156530] evm: security.selinux [ 7.158756] evm: security.ima [ 7.160463] evm: security.capability [ 7.162236] evm: HMAC attrs: 0x1 [ 7.165430] rtc_cmos 00:05: setting system clock to 2026-08-10 04:58:20 UTC (1786337900) [ 7.187270] debug: unmapping init [mem 0xffffffff91a03000-0xffffffff91bfffff] [ 7.200030] debug: unmapping init [mem 0xffffffff90782000-0xffffffff90a58fff] [ 7.212233] Write protecting the kernel read-only data: 28672k [ 7.219309] debug: unmapping init [mem 0xffffffff8ee03000-0xffffffff8effffff] [ 7.227304] debug: unmapping init [mem 0xffffffff8f714000-0xffffffff8f7fffff] [ 7.308388] 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) [ 7.344045] systemd[1]: Detected virtualization kvm. [ 7.350663] systemd[1]: Detected architecture x86-64. [ 7.357976] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 7.415073] systemd[1]: No hostname configured. [ 7.417593] systemd[1]: Set hostname to . [ 7.421369] random: systemd: uninitialized urandom read (16 bytes read) [ 7.425615] systemd[1]: Initializing machine ID from random generator. [ 7.555108] random: ln: uninitialized urandom read (6 bytes read) [ 7.809542] random: systemd: uninitialized urandom read (16 bytes read) [ 7.813261] systemd[1]: Reached target Slices. [ OK ] Reached target Slices. [ 7.826550] systemd[1]: Reached target Initrd Root Device. [ OK ] Reached target Initrd Root Device. [ 7.838421] systemd[1]: Reached target Timers. [ OK ] Reached target Timers. [ OK ] Reached target Local File Systems. [ OK ] Listening on udev Control Socket. [ OK ] Listening on Journal Socket. [ OK ] Started Memstrack Anylazing Service. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Listening on Journal Socket (/dev/log). [ OK ] Listening on udev Kernel Socket. Starting Journal Service... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Paths. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Sockets. Starting Setup Virtual Console... [ OK ] Reached target Swap. Starting Create Volatile Files and Directories... Starting Apply Kernel Variables... [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Setup Virtual Console. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Apply Kernel Variables. Starting dracut cmdline hook... Starting Create Static Device Nodes in /dev... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started Journal Service. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 9.285918] device-mapper: uevent: version 1.0.3 [ 9.288990] 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 [ 11.143815] virtio_net virtio0 ens2: renamed from eth0 ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting dracut initqueue hook... [ 11.454276] scsi host0: ata_piix [ 11.593877] scsi host1: ata_piix [ 11.599404] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc120 irq 14 [ 11.603236] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc128 irq 15 [ 16.691746] random: crng init done [ 16.700621] random: 7 urandom warning(s) missed due to ratelimiting [ 18.840766] dracut-initqueue[586]: RTNETLINK answers: File exists Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. Mounting /sysroot... [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. [ 20.893120] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped target Timers. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Sockets. [ OK ] Stopped target System Initialization. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. [ OK ] Stopped target Swap. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. Stopping udev Kernel Device Manager... [ OK ] Stopped target Slices. [ OK ] Stopped target Paths. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ 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... [ 24.118463] printk: systemd: 26 output lines suppressed due to ratelimiting [ 25.092734] SELinux: Disabled at runtime. [ 25.201969] 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) [ 25.213210] systemd[1]: Detected virtualization kvm. [ 25.215567] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 27.195685] systemd[1]: initrd-switch-root.service: Succeeded. [ 27.215087] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 27.235159] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 27.254388] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 27.264741] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 27.296956] systemd[1]: Starting Journal Service... Starting Journal Service... [ 27.323469] systemd[1]: Created slice system-sshd\x2dkeygen.slice. [ OK ] Created slice system-sshd\x2dkeygen.slice. [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Listening on Process Core Dump Socket. [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Listening on udev Control Socket. [ OK ] Reached target rpc_pipefs.target. [ OK ] Created slice system-getty.slice. [ OK ] Listening on RPCbind Server Activation Socket. Activating swap /dev/disk/by-label/SWAP... [ OK ] Reached target RPC Port Mapper. [ OK ] Started Forward Password Requests to Wall Directory Watch. [ 27.722596] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS Starting Create list of required st…ce nodes for the current kernel... Starting Apply Kernel Variables... [ OK ] Stopped target Switch Root. Mounting Kernel Debug File System... Mounting POSIX Message Queue File System... [ OK ] Reached target Paths. [ OK ] Listening on udev Kernel Socket. Starting udev Coldplug all Devices... [ OK ] Reached target Local Encrypted Volumes. [ OK ] Created slice User and Session Slice. [ OK ] Reached target Slices. [ OK ] Stopped target Initrd Root File System. Starting Remount Root and Kernel File Systems... [ OK ] Listening on initctl Compatibility Named Pipe. Mounting Huge Pages File System... [ OK ] Stopped target Initrd File Systems. [ OK ] Started Journal Service. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Apply Kernel Variables. [ OK ] Mounted Kernel Debug File System. [ OK ] Mounted POSIX Message Queue File System. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Mounted Huge Pages File System. Starting Configure read-only root support... Starting Create Static Device Nodes in /dev... [ OK ] Reached target Swap. Starting Flush Journal to Persistent Storage... [ OK ] Started udev Coldplug all Devices. [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Reached target Local File Systems (Pre). Mounting /mnt... Mounting /home/green/git/lustre-release... Starting udev Kernel Device Manager... [ OK ] Mounted /mnt. [ 29.731041] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 31.212747] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 31.236896] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 32.553110] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 32.590128] EDAC sbridge: Ver: 1.1.2 [* ] A start job is running for Configur…-only root support (9s / no limit)[ 36.145619] Key type dns_resolver registered [** ] A start job is running for Configur…-only root support (9s / no limit)[ 36.992235] NFS: Registering the id_resolver key type [ 36.993937] Key type id_resolver registered [ 36.995668] Key type id_legacy registered [*** ] A start job is running for Configur…only root support (10s / no limit) [ *** ] A start job is running for Configur…only root support (10s / no limit) [ OK ] Started Configure read-only root support. [ OK ] Reached target Local File Systems. Starting Mark the need to relabel after reboot... Starting Rebuild Dynamic Linker Cache... Starting Load/Save Random Seed... Starting Create Volatile Files and Directories... [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Load/Save Random Seed. [ OK ] Started Create Volatile Files and Directories. Starting RPC Bind... Starting Update UTMP about System Boot/Shutdown... [ OK ] Started 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 dnf makecache --timer. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Reached target Timers. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. Starting Login Service... Starting Restore /run/initramfs on shutdown... [ OK ] Started irqbalance daemon. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Reached target sshd-keygen.target. [ OK ] Started D-Bus System Message Bus. Starting Network Manager... [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Login Service. [ OK ] Started Network Manager. [ OK ] Reached target Network. Starting Dynamic System Tuning Daemon... Starting GSSAPI Proxy Daemon... Starting OpenSSH server daemon... Starting Network Manager Wait Online... Starting Hostname Service... [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Started OpenSSH server 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 Getty on tty1. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Serial Getty on ttyS1. [ 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. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg449-client login: [ 106.611641] libcfs: loading out-of-tree module taints kernel. [ 106.851402] Key type ._llcrypt registered [ 106.868264] Key type .llcrypt registered [ 107.416978] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [ 107.430332] alg: No test for adler32 (adler32-zlib) [ 108.839794] Lustre: Lustre: Build Version: 2.17.56_50_g8cc021f [ 109.539897] LNet: Added LNI 192.168.204.49@tcp [8/256/0/180] [ 111.376232] Key type lgssc registered [ 114.357916] Lustre: Echo OBD driver; http://www.lustre.org/ [ 149.574371] hrtimer: interrupt took 9435036 ns [ 310.452689] Lustre: Mounted lustre-client - version 2.17.56_50_g8cc021f [ 316.567749] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 335.763677] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing check_logdir /tmp/testlogs/ [ 336.351314] Lustre: lustre-OST0000-osc-ffff91f7621cf800: disconnect after 23s idle [ 343.351969] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing yml_node [ 349.876487] Lustre: DEBUG MARKER: Client: 2.17.56.50 [ 353.255625] Lustre: DEBUG MARKER: MDS: 2.17.56.50 [ 356.451098] Lustre: DEBUG MARKER: OSS: 2.17.56.50 [ 359.440194] Lustre: DEBUG MARKER: -----============= acceptance-small: replay-single ============----- Mon Aug 10 01:04:10 EDT 2026 [ 382.732841] Lustre: DEBUG MARKER: excepting tests: 59 36 [ 385.727498] Lustre: DEBUG MARKER: === replay-single: start setup 01:04:37 (1786338277) === [ 392.623675] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing check_config_client /mnt/lustre [ 414.497951] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 430.217185] Lustre: DEBUG MARKER: === replay-single: finish setup 01:05:21 (1786338321) === [ 433.407863] Lustre: DEBUG MARKER: == replay-single test 0a: empty replay =================== 01:05:24 (1786338324) [ 443.626791] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 449.021251] Lustre: lustre-MDT0000-mdc-ffff91f7621cf800: Connection to lustre-MDT0000 (at 192.168.204.149@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 459.234566] Lustre: lustre-OST0000-osc-ffff91f7621cf800: disconnect after 24s idle [ 459.243913] Lustre: Skipped 1 previous similar message [ 465.254679] Lustre: 2406:0:(client.c:2506:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786338342/real 1786338342] req@ffff91f7600a2680 x1873111156805888/t0(0) o400->MGC192.168.204.149@tcp@192.168.204.149@tcp:26/25 lens 224/224 e 0 to 1 dl 1786338358 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 465.323100] LustreError: MGC192.168.204.149@tcp: Connection to MGS (at 192.168.204.149@tcp) was lost; in progress operations using this service will fail [ 475.625386] Lustre: Evicted from MGS (at 192.168.204.149@tcp) after server handle changed from 0x47560188d4ec1a05 to 0x47560188d4ec1cc1 [ 475.640255] Lustre: MGC192.168.204.149@tcp: Connection restored to 192.168.204.149@tcp (at 192.168.204.149@tcp) [ 481.306345] Lustre: lustre-MDT0000-mdc-ffff91f7621cf800: Connection restored to 192.168.204.149@tcp (at 192.168.204.149@tcp) [ 491.840604] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 493.411682] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 502.513616] Lustre: DEBUG MARKER: == replay-single test 0b: ensure object created after recover exists. (3284) ========================================================== 01:06:34 (1786338394) [ 508.392596] Lustre: lustre-OST0000-osc-ffff91f7621cf800: Connection to lustre-OST0000 (at 192.168.204.149@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 518.625444] Lustre: lustre-OST0001-osc-ffff91f7621cf800: disconnect after 23s idle [ 518.633397] Lustre: Skipped 1 previous similar message [ 527.119915] Lustre: lustre-OST0000-osc-ffff91f7621cf800: Connection restored to 192.168.204.149@tcp (at 192.168.204.149@tcp) [ 541.558080] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 543.675726] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 555.083395] Lustre: DEBUG MARKER: == replay-single test 0c: check replay-barrier =========== 01:07:26 (1786338446) [ 564.014935] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 564.299657] Lustre: Unmounted lustre-client [ 605.085935] LustreError: lustre-MDT0000-mdc-ffff91f748e52800: operation mds_connect to node 192.168.204.149@tcp failed: rc = -16 [ 610.300083] LustreError: lustre-MDT0000-mdc-ffff91f748e52800: operation mds_connect to node 192.168.204.149@tcp failed: rc = -16 [ 615.457891] LustreError: lustre-MDT0000-mdc-ffff91f748e52800: operation mds_connect to node 192.168.204.149@tcp failed: rc = -16 [ 620.539091] LustreError: lustre-MDT0000-mdc-ffff91f748e52800: operation mds_connect to node 192.168.204.149@tcp failed: rc = -16 [ 625.681586] LustreError: lustre-MDT0000-mdc-ffff91f748e52800: operation mds_connect to node 192.168.204.149@tcp failed: rc = -16 [ 635.909931] LustreError: lustre-MDT0000-mdc-ffff91f748e52800: operation mds_connect to node 192.168.204.149@tcp failed: rc = -16 [ 635.918529] LustreError: Skipped 1 previous similar message [ 656.376365] LustreError: lustre-MDT0000-mdc-ffff91f748e52800: operation mds_connect to node 192.168.204.149@tcp failed: rc = -16 [ 656.392397] LustreError: Skipped 3 previous similar messages [ 676.934561] Lustre: Mounted lustre-client - version 2.17.56_50_g8cc021f [ 689.846822] Lustre: DEBUG MARKER: == replay-single test 0d: expired recovery with no clients ========================================================== 01:09:40 (1786338580) [ 699.753729] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 700.022617] Lustre: Unmounted lustre-client [ 741.727169] LustreError: lustre-MDT0000-mdc-ffff91f762155000: operation mds_connect to node 192.168.204.149@tcp failed: rc = -16 [ 741.754208] LustreError: Skipped 3 previous similar messages [ 808.473698] Lustre: Mounted lustre-client - version 2.17.56_50_g8cc021f [ 819.545241] Lustre: DEBUG MARKER: == replay-single test 1: simple create =================== 01:11:51 (1786338711) [ 828.991874] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 834.024650] Lustre: lustre-MDT0000-mdc-ffff91f762155000: Connection to lustre-MDT0000 (at 192.168.204.149@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 850.207243] Lustre: 2403:0:(client.c:2506:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786338727/real 1786338727] req@ffff91f759568e00 x1873111156876544/t0(0) o400->MGC192.168.204.149@tcp@192.168.204.149@tcp:26/25 lens 224/224 e 0 to 1 dl 1786338743 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 850.243946] LustreError: MGC192.168.204.149@tcp: Connection to MGS (at 192.168.204.149@tcp) was lost; in progress operations using this service will fail [ 860.652784] Lustre: Evicted from MGS (at 192.168.204.149@tcp) after server handle changed from 0x47560188d4ec2e02 to 0x47560188d4ec309b [ 860.667973] Lustre: MGC192.168.204.149@tcp: Connection restored to 192.168.204.149@tcp (at 192.168.204.149@tcp) [ 866.863479] Lustre: lustre-MDT0000-mdc-ffff91f762155000: Connection restored to 192.168.204.149@tcp (at 192.168.204.149@tcp) [ 880.478583] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 883.623626] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 895.401344] Lustre: DEBUG MARKER: == replay-single test 2a: touch ========================== 01:13:06 (1786338786) [ 906.530841] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 913.895444] Lustre: lustre-MDT0000-mdc-ffff91f762155000: Connection to lustre-MDT0000 (at 192.168.204.149@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 930.271132] Lustre: 2403:0:(client.c:2506:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786338807/real 1786338807] req@ffff91f747486680 x1873111156891136/t0(0) o400->MGC192.168.204.149@tcp@192.168.204.149@tcp:26/25 lens 224/224 e 0 to 1 dl 1786338823 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 930.319661] LustreError: MGC192.168.204.149@tcp: Connection to MGS (at 192.168.204.149@tcp) was lost; in progress operations using this service will fail [ 940.525978] Lustre: Evicted from MGS (at 192.168.204.149@tcp) after server handle changed from 0x47560188d4ec309b to 0x47560188d4ec37a2 [ 940.574870] Lustre: MGC192.168.204.149@tcp: Connection restored to 192.168.204.149@tcp (at 192.168.204.149@tcp) [ 944.063962] LustreError: 2402:0:(client.c:3451:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff91f75956bb80 x1873111156889600/t21474836484(21474836484) o101->lustre-MDT0000-mdc-ffff91f762155000@192.168.204.149@tcp:12/10 lens 592/608 e 0 to 0 dl 1786338853 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'touch.0' uid:0 gid:0 projid:0 [ 956.824767] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 959.442307] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 971.657429] Lustre: DEBUG MARKER: == replay-single test 2b: touch ========================== 01:14:22 (1786338862) [ 981.808329] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 986.603356] Lustre: lustre-MDT0000-mdc-ffff91f762155000: Connection to lustre-MDT0000 (at 192.168.204.149@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1001.951212] Lustre: 2406:0:(client.c:2506:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786338879/real 1786338879] req@ffff91f7600a0a80 x1873111156906112/t0(0) o400->MGC192.168.204.149@tcp@192.168.204.149@tcp:26/25 lens 224/224 e 0 to 1 dl 1786338895 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1001.982905] LustreError: MGC192.168.204.149@tcp: Connection to MGS (at 192.168.204.149@tcp) was lost; in progress operations using this service will fail [ 1012.213414] Lustre: Evicted from MGS (at 192.168.204.149@tcp) after server handle changed from 0x47560188d4ec37a2 to 0x47560188d4ec3b4c [ 1012.229920] Lustre: MGC192.168.204.149@tcp: Connection restored to 192.168.204.149@tcp (at 192.168.204.149@tcp) [ 1012.240906] Lustre: Skipped 1 previous similar message [ 1017.930246] LustreError: 2402:0:(client.c:3451:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff91f7600a2d80 x1873111156905216/t25769803781(25769803781) o101->lustre-MDT0000-mdc-ffff91f762155000@192.168.204.149@tcp:12/10 lens 592/608 e 0 to 0 dl 1786338927 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'touch.0' uid:0 gid:0 projid:0 [ 1032.484990] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1035.021939] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1047.801319] Lustre: DEBUG MARKER: == replay-single test 2c: setstripe replay =============== 01:15:39 (1786338939) [ 1058.165909] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1064.424386] Lustre: lustre-MDT0000-mdc-ffff91f762155000: Connection to lustre-MDT0000 (at 192.168.204.149@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1080.676816] Lustre: 2406:0:(client.c:2506:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786338957/real 1786338957] req@ffff91f7600a2300 x1873111156921344/t0(0) o400->MGC192.168.204.149@tcp@192.168.204.149@tcp:26/25 lens 224/224 e 0 to 1 dl 1786338973 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1080.744869] LustreError: MGC192.168.204.149@tcp: Connection to MGS (at 192.168.204.149@tcp) was lost; in progress operations using this service will fail [ 1091.049529] Lustre: Evicted from MGS (at 192.168.204.149@tcp) after server handle changed from 0x47560188d4ec3b4c to 0x47560188d4ec423e [ 1091.061075] Lustre: MGC192.168.204.149@tcp: Connection restored to 192.168.204.149@tcp (at 192.168.204.149@tcp) [ 1091.064980] Lustre: Skipped 1 previous similar message [ 1095.127112] LustreError: 2402:0:(client.c:3451:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff91f747486a00 x1873111156919552/t30064771076(30064771076) o101->lustre-MDT0000-mdc-ffff91f762155000@192.168.204.149@tcp:12/10 lens 536/608 e 0 to 0 dl 1786339004 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'lfs.0' uid:0 gid:0 projid:0 [ 1107.200878] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1109.031450] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1121.130842] Lustre: DEBUG MARKER: == replay-single test 2d: setdirstripe replay ============ 01:16:52 (1786339012) [ 1134.363387] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1137.147847] Lustre: lustre-MDT0000-mdc-ffff91f762155000: Connection to lustre-MDT0000 (at 192.168.204.149@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1158.624000] Lustre: 2405:0:(client.c:2506:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786339035/real 1786339035] req@ffff91f7620b8700 x1873111156934912/t0(0) o400->MGC192.168.204.149@tcp@192.168.204.149@tcp:26/25 lens 224/224 e 0 to 1 dl 1786339051 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1158.676488] LustreError: MGC192.168.204.149@tcp: Connection to MGS (at 192.168.204.149@tcp) was lost; in progress operations using this service will fail [ 1168.893461] Lustre: Evicted from MGS (at 192.168.204.149@tcp) after server handle changed from 0x47560188d4ec423e to 0x47560188d4ec4769 [ 1168.913398] Lustre: MGC192.168.204.149@tcp: Connection restored to 192.168.204.149@tcp (at 192.168.204.149@tcp) [ 1168.924585] Lustre: Skipped 1 previous similar message [ 1187.291485] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1189.744697] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1201.755917] Lustre: DEBUG MARKER: == replay-single test 2e: O_CREAT|O_EXCL create replay === 01:18:13 (1786339093) [ 1215.477300] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1219.039228] Lustre: 23318:0:(client.c:2506:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786339096/real 1786339096] req@ffff91f747485c00 x1873111156946304/t0(0) o35->lustre-MDT0000-mdc-ffff91f762155000@192.168.204.149@tcp:23/10 lens 392/624 e 0 to 1 dl 1786339112 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'openfile.0' uid:0 gid:0 projid:0 [ 1219.073550] Lustre: lustre-MDT0000-mdc-ffff91f762155000: Connection to lustre-MDT0000 (at 192.168.204.149@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1235.423285] LustreError: MGC192.168.204.149@tcp: Connection to MGS (at 192.168.204.149@tcp) was lost; in progress operations using this service will fail [ 1245.683961] Lustre: Evicted from MGS (at 192.168.204.149@tcp) after server handle changed from 0x47560188d4ec4769 to 0x47560188d4ec4a80 [ 1263.911146] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1265.902910] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1278.663332] Lustre: DEBUG MARKER: == replay-single test 3a: replay failed open(O_DIRECTORY) ========================================================== 01:19:29 (1786339169) [ 1290.517780] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1297.899620] Lustre: lustre-MDT0000-mdc-ffff91f762155000: Connection to lustre-MDT0000 (at 192.168.204.149@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1314.272301] Lustre: 2405:0:(client.c:2506:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786339191/real 1786339191] req@ffff91f7600a1f80 x1873111156964736/t0(0) o400->MGC192.168.204.149@tcp@192.168.204.149@tcp:26/25 lens 224/224 e 0 to 1 dl 1786339207 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1314.337759] Lustre: 2405:0:(client.c:2506:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 1314.356509] LustreError: MGC192.168.204.149@tcp: Connection to MGS (at 192.168.204.149@tcp) was lost; in progress operations using this service will fail [ 1324.544498] Lustre: Evicted from MGS (at 192.168.204.149@tcp) after server handle changed from 0x47560188d4ec4a80 to 0x47560188d4ec5076 [ 1324.575485] Lustre: MGC192.168.204.149@tcp: Connection restored to 192.168.204.149@tcp (at 192.168.204.149@tcp) [ 1324.595843] Lustre: Skipped 3 previous similar messages [ 1342.242822] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1344.820754] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1356.006720] Lustre: DEBUG MARKER: == replay-single test 3b: replay failed open -ENOMEM ===== 01:20:47 (1786339247) [ 1365.821638] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1385.890618] Lustre: 2406:0:(client.c:2506:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786339263/real 1786339263] req@ffff91f7620ba300 x1873111156979328/t0(0) o400->MGC192.168.204.149@tcp@192.168.204.149@tcp:26/25 lens 224/224 e 0 to 1 dl 1786339279 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1385.976440] LustreError: MGC192.168.204.149@tcp: Connection to MGS (at 192.168.204.149@tcp) was lost; in progress operations using this service will fail [ 1411.590072] Lustre: Evicted from MGS (at 192.168.204.149@tcp) after server handle changed from 0x47560188d4ec5076 to 0x47560188d4ec5802 [ 1421.028457] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1423.452088] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1434.982423] Lustre: DEBUG MARKER: == replay-single test 3c: replay failed open -ENOMEM ===== 01:22:05 (1786339325) [ 1445.395027] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1452.529667] Lustre: lustre-MDT0000-mdc-ffff91f762155000: Connection to lustre-MDT0000 (at 192.168.204.149@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1452.551116] Lustre: Skipped 1 previous similar message [ 1501.998260] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1504.952946] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1518.981951] Lustre: DEBUG MARKER: == replay-single test 4a: |x| 10 open(O_CREAT)s ========== 01:23:30 (1786339410) [ 1528.644445] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1549.796342] Lustre: 2404:0:(client.c:2506:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786339427/real 1786339427] req@ffff91f747484000 x1873111157018624/t0(0) o400->MGC192.168.204.149@tcp@192.168.204.149@tcp:26/25 lens 224/224 e 0 to 1 dl 1786339443 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1549.834734] Lustre: 2404:0:(client.c:2506:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 1549.846020] LustreError: MGC192.168.204.149@tcp: Connection to MGS (at 192.168.204.149@tcp) was lost; in progress operations using this service will fail [ 1549.864303] LustreError: Skipped 1 previous similar message [ 1560.040384] Lustre: Evicted from MGS (at 192.168.204.149@tcp) after server handle changed from 0x47560188d4ec5cbd to 0x47560188d4ec60c2 [ 1560.049810] Lustre: Skipped 1 previous similar message [ 1564.677939] LustreError: 2402:0:(client.c:3451:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff91f759569f80 x1873111157008256/t55834574851(55834574851) o101->lustre-MDT0000-mdc-ffff91f762155000@192.168.204.149@tcp:12/10 lens 592/608 e 0 to 0 dl 1786339473 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'bash.0' uid:0 gid:0 projid:0 [ 1576.710805] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1578.809715] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1591.055309] Lustre: DEBUG MARKER: == replay-single test 4b: |x| rm 10 files ================ 01:24:42 (1786339482) [ 1601.144786] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1631.723605] Lustre: MGC192.168.204.149@tcp: Connection restored to 192.168.204.149@tcp (at 192.168.204.149@tcp) [ 1631.736828] Lustre: Skipped 7 previous similar messages [ 1651.026682] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1653.135294] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1664.433896] Lustre: DEBUG MARKER: == replay-single test 5: |x| 220 open(O_CREAT) =========== 01:25:55 (1786339555) [ 1675.669509] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1721.933189] LustreError: 2402:0:(client.c:3451:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff91f7600a1880 x1873111157068672/t64424509443(64424509443) o101->lustre-MDT0000-mdc-ffff91f762155000@192.168.204.149@tcp:12/10 lens 592/608 e 0 to 0 dl 1786339631 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'bash.0' uid:0 gid:0 projid:0 [ 1721.967807] LustreError: 2402:0:(client.c:3451:ptlrpc_replay_interpret()) Skipped 9 previous similar messages [ 1733.583399] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1735.888922] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1764.091976] Lustre: DEBUG MARKER: == replay-single test 6a: mkdir + contained create ======= 01:27:35 (1786339655) [ 1772.591913] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1779.180741] Lustre: lustre-MDT0000-mdc-ffff91f762155000: Connection to lustre-MDT0000 (at 192.168.204.149@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1779.201302] Lustre: Skipped 3 previous similar messages [ 1823.221743] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1826.044840] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1839.591829] Lustre: DEBUG MARKER: == replay-single test 6b: |X| rmdir ====================== 01:28:51 (1786339731) [ 1850.123241] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1869.279214] Lustre: 2405:0:(client.c:2506:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786339746/real 1786339746] req@ffff91f7486c5880 x1873111157564416/t0(0) o400->MGC192.168.204.149@tcp@192.168.204.149@tcp:26/25 lens 224/224 e 0 to 1 dl 1786339762 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1869.303150] Lustre: 2405:0:(client.c:2506:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 1869.310485] LustreError: MGC192.168.204.149@tcp: Connection to MGS (at 192.168.204.149@tcp) was lost; in progress operations using this service will fail [ 1869.319426] LustreError: Skipped 3 previous similar messages [ 1879.535122] Lustre: Evicted from MGS (at 192.168.204.149@tcp) after server handle changed from 0x47560188d4ed0702 to 0x47560188d4ed0be7 [ 1879.549838] Lustre: Skipped 3 previous similar messages [ 1881.198462] Lustre: 15225:0:(mgc_request.c:1899:mgc_process_log()) MGC192.168.204.149@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 1902.479891] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1904.589593] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1916.696726] Lustre: DEBUG MARKER: == replay-single test 7: mkdir |X| contained create ====== 01:30:08 (1786339808) [ 1927.809127] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1981.909577] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1984.736440] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2000.083990] Lustre: DEBUG MARKER: == replay-single test 8: creat open |X| close ============ 01:31:31 (1786339891) [ 2010.412456] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2048.977871] LustreError: 2402:0:(client.c:3451:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff91f747a84a80 x1873111157596416/t81604378634(81604378634) o101->lustre-MDT0000-mdc-ffff91f762155000@192.168.204.149@tcp:12/10 lens 664/608 e 0 to 0 dl 1786339958 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'multiop.0' uid:0 gid:0 projid:0 [ 2049.009289] LustreError: 2402:0:(client.c:3451:ptlrpc_replay_interpret()) Skipped 219 previous similar messages [ 2063.175877] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2065.956554] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2077.993353] Lustre: DEBUG MARKER: == replay-single test 9: |X| create (same inum/gen) ====== 01:32:49 (1786339969) [ 2088.599858] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2138.746816] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2140.883798] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2153.714242] Lustre: DEBUG MARKER: == replay-single test 10: create |X| rename unlink ======= 01:34:04 (1786340044) [ 2164.485331] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2198.003493] Lustre: MGC192.168.204.149@tcp: Connection restored to 192.168.204.149@tcp (at 192.168.204.149@tcp) [ 2198.023340] Lustre: Skipped 13 previous similar messages [ 2217.107058] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2219.748161] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2232.027610] Lustre: DEBUG MARKER: == replay-single test 11: create open write rename |X| create-old-name read ========================================================== 01:35:23 (1786340123) [ 2243.940787] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2280.879644] LustreError: 2402:0:(client.c:3451:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff91f748553b80 x1873111157643776/t94489280522(94489280522) o101->lustre-MDT0000-mdc-ffff91f762155000@192.168.204.149@tcp:12/10 lens 592/608 e 0 to 0 dl 1786340185 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'bash.0' uid:0 gid:0 projid:0 [ 2294.021312] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2296.010527] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2307.701083] Lustre: DEBUG MARKER: == replay-single test 12: open, unlink |X| close ========= 01:36:39 (1786340199) [ 2317.208475] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2321.914650] Lustre: lustre-MDT0000-mdc-ffff91f762155000: Connection to lustre-MDT0000 (at 192.168.204.149@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 2321.940080] Lustre: Skipped 6 previous similar messages [ 2348.593191] LustreError: 2402:0:(client.c:3451:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff91f747a84e00 x1873111157644544/t94489280524(94489280524) o101->lustre-MDT0000-mdc-ffff91f762155000@192.168.204.149@tcp:12/10 lens 576/608 e 0 to 0 dl 1786340257 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'grep.0' uid:0 gid:0 projid:0 [ 2348.625056] LustreError: 2402:0:(client.c:3451:ptlrpc_replay_interpret()) Skipped 1 previous similar message [ 2365.170467] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2367.985398] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2378.215705] Lustre: DEBUG MARKER: == replay-single test 13: open chmod 0 |x| write close === 01:37:50 (1786340270) [ 2387.223802] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2407.905952] Lustre: 2404:0:(client.c:2506:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786340285/real 1786340285] req@ffff91f747a87480 x1873111157678336/t0(0) o400->MGC192.168.204.149@tcp@192.168.204.149@tcp:26/25 lens 224/224 e 0 to 1 dl 1786340301 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2407.931219] Lustre: 2404:0:(client.c:2506:ptlrpc_expire_one_request()) Skipped 6 previous similar messages [ 2407.944284] LustreError: MGC192.168.204.149@tcp: Connection to MGS (at 192.168.204.149@tcp) was lost; in progress operations using this service will fail [ 2407.963318] LustreError: Skipped 6 previous similar messages [ 2418.152922] Lustre: Evicted from MGS (at 192.168.204.149@tcp) after server handle changed from 0x47560188d4ed2df9 to 0x47560188d4ed3228 [ 2418.164707] Lustre: Skipped 6 previous similar messages [ 2421.485147] LustreError: 2402:0:(client.c:3451:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff91f747a84e00 x1873111157644544/t94489280524(94489280524) o101->lustre-MDT0000-mdc-ffff91f762155000@192.168.204.149@tcp:12/10 lens 576/608 e 0 to 0 dl 1786340330 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'grep.0' uid:0 gid:0 projid:0 [ 2421.538067] LustreError: 2402:0:(client.c:3451:ptlrpc_replay_interpret()) Skipped 1 previous similar message [ 2436.783024] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2438.293711] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2449.965136] Lustre: DEBUG MARKER: == replay-single test 14: open(O_CREAT), unlink |X| close ========================================================== 01:39:01 (1786340341) [ 2459.575905] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2513.314409] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2515.353261] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2526.145553] Lustre: DEBUG MARKER: == replay-single test 15: open(O_CREAT), unlink |X| touch new, close ========================================================== 01:40:17 (1786340417) [ 2536.540291] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2571.940909] LustreError: 2402:0:(client.c:3451:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff91f747a84e00 x1873111157644544/t94489280524(94489280524) o101->lustre-MDT0000-mdc-ffff91f762155000@192.168.204.149@tcp:12/10 lens 576/608 e 0 to 0 dl 1786340481 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'grep.0' uid:0 gid:0 projid:0 [ 2571.998958] LustreError: 2402:0:(client.c:3451:ptlrpc_replay_interpret()) Skipped 3 previous similar messages [ 2588.464342] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2590.670753] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2601.630868] Lustre: DEBUG MARKER: == replay-single test 16: |X| open(O_CREAT), unlink, touch new, unlink new ========================================================== 01:41:32 (1786340492) [ 2611.470971] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2663.424497] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2665.475509] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2675.414756] Lustre: DEBUG MARKER: == replay-single test 17: |X| open(O_CREAT), |replay| close ========================================================== 01:42:47 (1786340567) [ 2682.794052] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2728.407089] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2730.432937] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2740.319715] Lustre: DEBUG MARKER: == replay-single test 18: open(O_CREAT), unlink, touch new, close, touch, unlink ========================================================== 01:43:51 (1786340631) [ 2747.878333] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2795.352503] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2797.205761] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2807.660456] Lustre: DEBUG MARKER: == replay-single test 19: mcreate, open, write, rename === 01:44:59 (1786340699) [ 2817.381308] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2850.800919] Lustre: MGC192.168.204.149@tcp: Connection restored to 192.168.204.149@tcp (at 192.168.204.149@tcp) [ 2850.812449] Lustre: Skipped 17 previous similar messages [ 2856.409165] LustreError: 2402:0:(client.c:3451:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff91f748553480 x1873111157772800/t128849018889(128849018889) o101->lustre-MDT0000-mdc-ffff91f762155000@192.168.204.149@tcp:12/10 lens 592/608 e 0 to 0 dl 1786340765 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'bash.0' uid:0 gid:0 projid:0 [ 2856.439442] LustreError: 2402:0:(client.c:3451:ptlrpc_replay_interpret()) Skipped 8 previous similar messages [ 2869.431561] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2871.657805] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2881.819635] Lustre: DEBUG MARKER: == replay-single test 20a: |X| open(O_CREAT), unlink, replay, close (test mds_cleanup_orphans) ========================================================== 01:46:13 (1786340773) [ 2891.780428] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2927.537912] Lustre: 15225:0:(mgc_request.c:1899:mgc_process_log()) MGC192.168.204.149@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 2956.966918] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2958.851873] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2970.940074] Lustre: DEBUG MARKER: == replay-single test 20b: write, unlink, eviction, replay (test mds_cleanup_orphans) ========================================================== 01:47:42 (1786340862) [ 2978.843322] LustreError: lustre-MDT0000-mdc-ffff91f762155000: operation mds_statfs to node 192.168.204.149@tcp failed: rc = -107 [ 2978.852355] LustreError: Skipped 12 previous similar messages [ 2978.856902] Lustre: lustre-MDT0000-mdc-ffff91f762155000: Connection to lustre-MDT0000 (at 192.168.204.149@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 2978.875388] Lustre: Skipped 8 previous similar messages [ 2978.894377] LustreError: lustre-MDT0000-mdc-ffff91f762155000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 2978.917244] LustreError: 57951:0:(vvp_io.c:1889:vvp_io_init()) lustre: refresh file layout [0x200001b71:0x132:0x0] error -108. [ 3028.293950] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3030.555359] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3054.688526] Lustre: DEBUG MARKER: before 3156, after 3156 [ 3065.454262] Lustre: DEBUG MARKER: == replay-single test 20c: check that client eviction does not affect file content ========================================================== 01:49:17 (1786340957) [ 3068.910954] LustreError: lustre-MDT0000-mdc-ffff91f762155000: operation mds_statfs to node 192.168.204.149@tcp failed: rc = -107 [ 3068.942802] LustreError: lustre-MDT0000-mdc-ffff91f762155000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 3081.336947] Lustre: DEBUG MARKER: == replay-single test 21: |X| open(O_CREAT), unlink touch new, replay, close (test mds_cleanup_orphans) ========================================================== 01:49:32 (1786340972) [ 3090.660953] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3110.882443] Lustre: 2403:0:(client.c:2506:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786340988/real 1786340988] req@ffff91f747a86d80 x1873111157833344/t0(0) o400->MGC192.168.204.149@tcp@192.168.204.149@tcp:26/25 lens 224/224 e 0 to 1 dl 1786341004 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3110.970394] Lustre: 2403:0:(client.c:2506:ptlrpc_expire_one_request()) Skipped 8 previous similar messages [ 3110.997762] LustreError: MGC192.168.204.149@tcp: Connection to MGS (at 192.168.204.149@tcp) was lost; in progress operations using this service will fail [ 3111.023569] LustreError: Skipped 8 previous similar messages [ 3121.639355] Lustre: Evicted from MGS (at 192.168.204.149@tcp) after server handle changed from 0x47560188d4ed6129 to 0x47560188d4ed64b7 [ 3121.663169] Lustre: Skipped 8 previous similar messages [ 3123.438244] Lustre: 15225:0:(mgc_request.c:1899:mgc_process_log()) MGC192.168.204.149@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 3145.028869] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3146.956403] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3157.667203] Lustre: DEBUG MARKER: == replay-single test 22: open(O_CREAT), |X| unlink, replay, close (test mds_cleanup_orphans) ========================================================== 01:50:48 (1786341048) [ 3167.630932] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3216.918510] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3219.409611] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3230.171915] Lustre: DEBUG MARKER: == replay-single test 23: open(O_CREAT), |X| unlink touch new, replay, close (test mds_cleanup_orphans) ========================================================== 01:52:01 (1786341121) [ 3240.774712] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3290.959214] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3294.183659] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3305.936489] Lustre: DEBUG MARKER: == replay-single test 24: open(O_CREAT), replay, unlink, close (test mds_cleanup_orphans) ========================================================== 01:53:17 (1786341197) [ 3316.049986] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3368.715776] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3370.719570] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3382.322150] Lustre: DEBUG MARKER: == replay-single test 25: open(O_CREAT), unlink, replay, close (test mds_cleanup_orphans) ========================================================== 01:54:33 (1786341273) [ 3392.493830] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3422.773223] LustreError: 2402:0:(client.c:3451:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff91f747a84000 x1873111157896320/t158913789956(158913789956) o101->lustre-MDT0000-mdc-ffff91f762155000@192.168.204.149@tcp:12/10 lens 592/608 e 0 to 0 dl 1786341332 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'multiop.0' uid:0 gid:0 projid:0 [ 3422.830021] LustreError: 2402:0:(client.c:3451:ptlrpc_replay_interpret()) Skipped 7 previous similar messages [ 3439.257304] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3441.749605] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3452.954864] Lustre: DEBUG MARKER: == replay-single test 26: |X| open(O_CREAT), unlink two, close one, replay, close one (test mds_cleanup_orphans) ========================================================== 01:55:44 (1786341344) [ 3461.455995] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3495.424212] Lustre: MGC192.168.204.149@tcp: Connection restored to 192.168.204.149@tcp (at 192.168.204.149@tcp) [ 3495.431085] Lustre: Skipped 17 previous similar messages [ 3509.800176] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3511.940804] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3524.275737] Lustre: DEBUG MARKER: == replay-single test 27: |X| open(O_CREAT), unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 01:56:55 (1786341415) [ 3533.003947] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3563.114847] Lustre: 15225:0:(mgc_request.c:1899:mgc_process_log()) MGC192.168.204.149@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 3585.226992] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3586.828610] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3594.662333] Lustre: DEBUG MARKER: == replay-single test 28: open(O_CREAT), |X| unlink two, close one, replay, close one (test mds_cleanup_orphans) ========================================================== 01:58:06 (1786341486) [ 3601.669595] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3604.972648] Lustre: lustre-MDT0000-mdc-ffff91f762155000: Connection to lustre-MDT0000 (at 192.168.204.149@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 3604.991133] Lustre: Skipped 9 previous similar messages [ 3632.937967] Lustre: 15225:0:(mgc_request.c:1899:mgc_process_log()) MGC192.168.204.149@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 3648.441826] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3650.335238] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3658.752183] Lustre: DEBUG MARKER: == replay-single test 29: open(O_CREAT), |X| unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 01:59:10 (1786341550) [ 3665.697764] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3699.612487] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3700.981698] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3708.643989] Lustre: DEBUG MARKER: == replay-single test 30: open(O_CREAT) two, unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 02:00:00 (1786341600) [ 3714.756330] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3735.519324] Lustre: 2405:0:(client.c:2506:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786341612/real 1786341612] req@ffff91f7486c4380 x1873111157979776/t0(0) o400->MGC192.168.204.149@tcp@192.168.204.149@tcp:26/25 lens 224/224 e 0 to 1 dl 1786341628 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3735.541813] Lustre: 2405:0:(client.c:2506:ptlrpc_expire_one_request()) Skipped 8 previous similar messages [ 3735.549541] LustreError: MGC192.168.204.149@tcp: Connection to MGS (at 192.168.204.149@tcp) was lost; in progress operations using this service will fail [ 3735.562841] LustreError: Skipped 8 previous similar messages [ 3744.751042] Lustre: Evicted from MGS (at 192.168.204.149@tcp) after server handle changed from 0x47560188d4ed9643 to 0x47560188d4ed9896 [ 3744.767727] Lustre: Skipped 8 previous similar messages [ 3755.679578] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3757.013519] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3765.193782] Lustre: DEBUG MARKER: == replay-single test 31: open(O_CREAT) two, unlink one, |X| unlink one, close two (test mds_cleanup_orphans) ========================================================== 02:00:57 (1786341657) [ 3771.446457] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3811.286432] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3812.394496] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3818.844469] Lustre: DEBUG MARKER: == replay-single test 32: close() notices client eviction; close() after client eviction ========================================================== 02:01:51 (1786341711) [ 3821.205360] LustreError: lustre-MDT0000-mdc-ffff91f762155000: operation mds_statfs to node 192.168.204.149@tcp failed: rc = -107 [ 3821.216689] LustreError: lustre-MDT0000-mdc-ffff91f762155000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 3827.242583] Lustre: DEBUG MARKER: == replay-single test 33a: fid seq shouldn't be reused after abort recovery ========================================================== 02:01:59 (1786341719) [ 3831.725050] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3844.074822] LustreError: lustre-MDT0000-mdc-ffff91f762155000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 3861.368763] Lustre: DEBUG MARKER: == replay-single test 33b: test fid seq allocation ======= 02:02:33 (1786341753) [ 3866.158308] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3879.931875] LustreError: lustre-MDT0000-mdc-ffff91f762155000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 3896.249762] Lustre: DEBUG MARKER: == replay-single test 34: abort recovery before client does replay (test mds_cleanup_orphans) ========================================================== 02:03:08 (1786341788) [ 3901.942260] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3915.764753] LustreError: lustre-MDT0000-mdc-ffff91f762155000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 3933.326728] Lustre: DEBUG MARKER: == replay-single test 35: test recovery from llog for unlink op ========================================================== 02:03:45 (1786341825) [ 3946.471272] LustreError: lustre-MDT0000-mdc-ffff91f762155000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 3964.080467] Lustre: DEBUG MARKER: SKIP: replay-single test_36 skipping ALWAYS excluded test 36 [ 3965.227814] Lustre: DEBUG MARKER: == replay-single test 37: abort recovery before client does replay (test mds_cleanup_orphans for directories) ========================================================== 02:04:17 (1786341857) [ 3971.351499] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3987.431140] LustreError: lustre-MDT0000-mdc-ffff91f762155000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 4004.834701] Lustre: DEBUG MARKER: == replay-single test 38: test recovery from unlink llog (test llog_gen_rec) ========================================================== 02:04:56 (1786341896) [ 4032.709353] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4055.466877] Lustre: 15225:0:(mgc_request.c:1899:mgc_process_log()) MGC192.168.204.149@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 4073.432472] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4074.744498] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4092.189846] Lustre: DEBUG MARKER: == replay-single test 39: test recovery from unlink llog (test llog_gen_rec) ========================================================== 02:06:24 (1786341984) [ 4112.407331] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4141.030331] Lustre: MGC192.168.204.149@tcp: Connection restored to 192.168.204.149@tcp (at 192.168.204.149@tcp) [ 4141.038216] Lustre: Skipped 24 previous similar messages [ 4149.713925] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4150.786309] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4166.781513] Lustre: DEBUG MARKER: == replay-single test 41: read from a valid osc while other oscs are invalid ========================================================== 02:07:39 (1786342059) [ 4172.583888] Lustre: DEBUG MARKER: == replay-single test 42: recovery after ost failure ===== 02:07:45 (1786342065) [ 4190.387772] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-OST0000 [ 4270.219688] Lustre: DEBUG MARKER: == replay-single test 43: mds osc import failure during recovery; don't LBUG ========================================================== 02:09:22 (1786342162) [ 4274.839796] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4279.268353] Lustre: lustre-MDT0000-mdc-ffff91f762155000: Connection to lustre-MDT0000 (at 192.168.204.149@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 4279.278843] Lustre: Skipped 12 previous similar messages [ 4296.553429] Lustre: 15225:0:(mgc_request.c:1899:mgc_process_log()) MGC192.168.204.149@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 4311.548660] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4312.583247] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4328.377565] Lustre: DEBUG MARKER: == replay-single test 44a: race in target handle connect ========================================================== 02:10:20 (1786342220) [ 4398.044982] Lustre: DEBUG MARKER: == replay-single test 44b: race in target handle connect ========================================================== 02:11:30 (1786342290) [ 4419.559807] LustreError: 92421:0:(lmv_obd.c:1471:lmv_statfs()) lustre-MDT0000-mdc-ffff91f762155000: can't stat MDS #0: rc = -114 [ 4441.068506] LustreError: 92443:0:(lmv_obd.c:1471:lmv_statfs()) lustre-MDT0000-mdc-ffff91f762155000: can't stat MDS #0: rc = -114 [ 4462.572182] LustreError: 92465:0:(lmv_obd.c:1471:lmv_statfs()) lustre-MDT0000-mdc-ffff91f762155000: can't stat MDS #0: rc = -114 [ 4484.082401] LustreError: 92488:0:(lmv_obd.c:1471:lmv_statfs()) lustre-MDT0000-mdc-ffff91f762155000: can't stat MDS #0: rc = -114 [ 4505.581678] LustreError: 92510:0:(lmv_obd.c:1471:lmv_statfs()) lustre-MDT0000-mdc-ffff91f762155000: can't stat MDS #0: rc = -114 [ 4527.078400] LustreError: 92532:0:(lmv_obd.c:1471:lmv_statfs()) lustre-MDT0000-mdc-ffff91f762155000: can't stat MDS #0: rc = -114 [ 4548.133868] LustreError: 92554:0:(lmv_obd.c:1471:lmv_statfs()) lustre-MDT0000-mdc-ffff91f762155000: can't stat MDS #0: rc = -114 [ 4590.629432] LustreError: 92599:0:(lmv_obd.c:1471:lmv_statfs()) lustre-MDT0000-mdc-ffff91f762155000: can't stat MDS #0: rc = -114 [ 4590.634259] LustreError: 92599:0:(lmv_obd.c:1471:lmv_statfs()) Skipped 1 previous similar message [ 4615.047917] Lustre: DEBUG MARKER: == replay-single test 44c: race in target handle connect ========================================================== 02:15:07 (1786342507) [ 4618.119940] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4629.476711] LustreError: MGC192.168.204.149@tcp: Connection to MGS (at 192.168.204.149@tcp) was lost; in progress operations using this service will fail [ 4629.482383] LustreError: Skipped 9 previous similar messages [ 4629.482929] LustreError: lustre-MDT0000-mdc-ffff91f762155000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 4629.496297] Lustre: Evicted from MGS (at 192.168.204.149@tcp) after server handle changed from 0x47560188d4f1e4f4 to 0x47560188d4f1f842 [ 4629.501285] Lustre: Skipped 9 previous similar messages [ 4662.777901] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4663.567069] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4668.454427] Lustre: DEBUG MARKER: == replay-single test 45: Handle failed close ============ 02:16:01 (1786342561) [ 4668.583718] Lustre: setting import lustre-MDT0000_UUID INACTIVE by administrator request [ 4668.589805] LustreError: 95163:0:(file.c:251:ll_close_inode_openhandle()) lustre-clilmv-ffff91f762155000: inode [0x20001a9e1:0x1:0x0] mdc close failed: rc = -108 [ 4668.602822] LustreError: lustre-MDT0000-mdc-ffff91f762155000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 4672.915322] Lustre: DEBUG MARKER: == replay-single test 46: Don't leak file handle after open resend (3325) ========================================================== 02:16:05 (1786342565) [ 4688.863141] Lustre: 95754:0:(client.c:2506:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786342566/real 1786342566] req@ffff91f7486fca80 x1873111160793856/t0(0) o700->lustre-MDT0000-mdc-ffff91f762155000@192.168.204.149@tcp:30/10 lens 264/248 e 0 to 1 dl 1786342582 ref 2 fl Rpc:XQr/200/ffffffff rc 0/-1 job:'touch.0' uid:0 gid:0 projid:4294967295 [ 4688.879407] Lustre: 95754:0:(client.c:2506:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 4711.779352] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4712.476256] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4717.287558] Lustre: DEBUG MARKER: == replay-single test 47: MDS->OSC failure during precreate cleanup (2824) ========================================================== 02:16:49 (1786342609) [ 4739.822192] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 4740.487212] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4807.653420] Lustre: DEBUG MARKER: == replay-single test 48: MDS->OSC failure during precreate cleanup (2824) ========================================================== 02:18:20 (1786342700) [ 4811.480351] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4829.160645] Lustre: MGC192.168.204.149@tcp: Connection restored to 192.168.204.149@tcp (at 192.168.204.149@tcp) [ 4829.164759] Lustre: Skipped 23 previous similar messages [ 4834.205781] LustreError: 2402:0:(client.c:3451:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff91f74781d880 x1873111160853632/t236223201383(236223201383) o101->lustre-MDT0000-mdc-ffff91f762155000@192.168.204.149@tcp:12/10 lens 592/608 e 0 to 0 dl 1786342787 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'createmany.0' uid:0 gid:0 projid:0 [ 4834.219545] LustreError: 2402:0:(client.c:3451:ptlrpc_replay_interpret()) Skipped 13 previous similar messages [ 4897.557474] Lustre: DEBUG MARKER: == replay-single test 50: Double OSC recovery, don't LASSERT (3812) ========================================================== 02:19:50 (1786342790) [ 4906.046064] Lustre: DEBUG MARKER: == replay-single test 52: time out lock replay (3764) ==== 02:19:58 (1786342798) [ 4911.072581] Lustre: lustre-MDT0000-mdc-ffff91f762155000: Connection to lustre-MDT0000 (at 192.168.204.149@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 4911.077935] Lustre: Skipped 19 previous similar messages [ 4983.187241] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4983.789658] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4987.980631] Lustre: DEBUG MARKER: == replay-single test 53a: |X| close request while two MDC requests in flight ========================================================== 02:21:20 (1786342880) [ 4992.361811] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5015.861551] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5016.590838] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5020.853788] Lustre: DEBUG MARKER: == replay-single test 53b: |X| open request while two MDC requests in flight ========================================================== 02:21:53 (1786342913) [ 5026.116218] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5051.261894] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5051.939731] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5056.384731] Lustre: DEBUG MARKER: == replay-single test 53c: |X| open request and close request while two MDC requests in flight ========================================================== 02:22:29 (1786342949) [ 5061.185693] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5086.750173] Lustre: DEBUG MARKER: == replay-single test 53d: close reply while two MDC requests in flight ========================================================== 02:22:59 (1786342979) [ 5110.899582] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5111.525100] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5115.689062] Lustre: DEBUG MARKER: == replay-single test 53e: |X| open reply while two MDC requests in flight ========================================================== 02:23:28 (1786343008) [ 5120.628320] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5143.242975] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5143.821369] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5147.497022] Lustre: DEBUG MARKER: == replay-single test 53f: |X| open reply and close reply while two MDC requests in flight ========================================================== 02:24:00 (1786343040) [ 5152.305960] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5178.765455] Lustre: DEBUG MARKER: == replay-single test 53g: |X| drop open reply and close request while close and open are both in flight ========================================================== 02:24:31 (1786343071) [ 5183.733014] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5208.835202] Lustre: DEBUG MARKER: == replay-single test 53h: open request and close reply while two MDC requests in flight ========================================================== 02:25:01 (1786343101) [ 5214.269322] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5233.632588] LustreError: MGC192.168.204.149@tcp: Connection to MGS (at 192.168.204.149@tcp) was lost; in progress operations using this service will fail [ 5233.636790] LustreError: Skipped 11 previous similar messages [ 5233.640068] Lustre: Evicted from MGS (at 192.168.204.149@tcp) after server handle changed from 0x47560188d4f252a8 to 0x47560188d4f258f9 [ 5233.643398] Lustre: Skipped 11 previous similar messages [ 5239.706351] Lustre: DEBUG MARKER: == replay-single test 55: let MDS_CHECK_RESENT return the original return code instead of 0 ========================================================== 02:25:32 (1786343132) [ 5300.191188] Lustre: 111459:0:(client.c:2506:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786343133/real 1786343133] req@ffff91f74781e680 x1873111161025792/t0(0) o101->lustre-MDT0000-mdc-ffff91f762155000@192.168.204.149@tcp:12/10 lens 664/66320 e 0 to 1 dl 1786343193 ref 2 fl Rpc:XPQr/600/ffffffff rc 0/-1 job:'touch.0' uid:0 gid:0 projid:0 [ 5300.201822] Lustre: 111459:0:(client.c:2506:ptlrpc_expire_one_request()) Skipped 8 previous similar messages [ 5302.592968] Lustre: DEBUG MARKER: == replay-single test 56: don't replay a symlink open request (3440) ========================================================== 02:26:35 (1786343195) [ 5305.301151] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5327.369411] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5327.829044] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5341.238983] Lustre: DEBUG MARKER: == replay-single test 57: test recovery from llog for setattr op ========================================================== 02:27:14 (1786343234) [ 5343.933608] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5366.019221] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5366.525654] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5373.780389] Lustre: DEBUG MARKER: == replay-single test 58a: test recovery from llog for setattr op (test llog_gen_rec) ========================================================== 02:27:46 (1786343266) [ 5385.064741] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5407.532273] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5408.059176] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5424.236724] Lustre: DEBUG MARKER: == replay-single test 58b: test replay of setxattr op ==== 02:28:37 (1786343317) [ 5424.729429] Lustre: Mounted lustre-client - version 2.17.56_50_g8cc021f [ 5427.596425] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5445.604578] Lustre: MGC192.168.204.149@tcp: Connection restored to 192.168.204.149@tcp (at 192.168.204.149@tcp) [ 5445.608162] Lustre: Skipped 26 previous similar messages [ 5450.002604] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5450.556355] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5452.251090] Lustre: Unmounted lustre-client [ 5454.116616] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount FULL mgc.*.mgs_server_uuid 1475 0 [ 5454.636612] Lustre: DEBUG MARKER: mgc.*.mgs_server_uuid in FULL state after 0 sec [ 5456.836421] Lustre: DEBUG MARKER: == replay-single test 58c: resend/reconstruct setxattr op ========================================================== 02:29:09 (1786343349) [ 5462.306919] Lustre: Mounted lustre-client - version 2.17.56_50_g8cc021f [ 5523.423218] Lustre: lustre-MDT0000-mdc-ffff91f762155000: Connection to lustre-MDT0000 (at 192.168.204.149@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 5523.430716] Lustre: Skipped 14 previous similar messages [ 5584.594302] Lustre: Unmounted lustre-client [ 5586.553668] Lustre: DEBUG MARKER: SKIP: replay-single test_59 skipping ALWAYS excluded test 59 [ 5587.088446] Lustre: DEBUG MARKER: == replay-single test 60: test llog post recovery init vs llog unlink ========================================================== 02:31:19 (1786343479) [ 5591.206307] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5613.318203] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5613.841029] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5617.480100] Lustre: DEBUG MARKER: == replay-single test 61a: test race llog recovery vs llog cleanup ========================================================== 02:31:50 (1786343510) [ 5623.396854] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-OST0000 [ 5673.544126] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 5674.126294] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 5708.161593] Lustre: DEBUG MARKER: == replay-single test 61b: test race mds llog sync vs llog cleanup ========================================================== 02:33:20 (1786343600) [ 5754.886297] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5755.356067] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5758.650265] Lustre: DEBUG MARKER: == replay-single test 61c: test race mds llog sync vs llog cleanup ========================================================== 02:34:11 (1786343651) [ 5788.218392] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 5788.732845] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 5792.281786] Lustre: DEBUG MARKER: == replay-single test 61d: error in llog_setup should cleanup the llog context correctly ========================================================== 02:34:45 (1786343685) [ 5802.705017] Lustre: DEBUG MARKER: == replay-single test 62: don't mis-drop resent replay === 02:34:55 (1786343695) [ 5806.773522] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5885.919227] LustreError: 2402:0:(client.c:3401:ptlrpc_replay_interpret()) @@@ request replay timed out req@ffff91f7522ece00 x1873111164654464/t313532612610(313532612610) o36->lustre-MDT0000-mdc-ffff91f762155000@192.168.204.149@tcp:12/10 lens 528/448 e 0 to 1 dl 1786343779 ref 2 fl Interpret:EXQU/204/ffffffff rc -110/-1 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 5885.947808] LustreError: 2402:0:(client.c:3451:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff91f7523fa680 x1873111164656128/t313532612612(313532612612) o101->lustre-MDT0000-mdc-ffff91f762155000@192.168.204.149@tcp:12/10 lens 592/608 e 0 to 0 dl 1786343839 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'createmany.0' uid:0 gid:0 projid:0 [ 5885.957103] LustreError: 2402:0:(client.c:3451:ptlrpc_replay_interpret()) Skipped 19 previous similar messages [ 5887.843580] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5888.339584] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5892.058701] Lustre: DEBUG MARKER: == replay-single test 65a: AT: verify early replies ====== 02:36:24 (1786343784) [ 5938.145658] Lustre: DEBUG MARKER: == replay-single test 65b: AT: verify early replies on packed reply / bulk ========================================================== 02:37:11 (1786343831) [ 5975.662689] Lustre: DEBUG MARKER: == replay-single test 66a: AT: verify MDT service time adjusts with no early replies ========================================================== 02:37:48 (1786343868) [ 6026.246413] Lustre: DEBUG MARKER: == replay-single test 66b: AT: verify net latency adjusts ========================================================== 02:38:39 (1786343919) [ 6048.341992] LustreError: 131973:0:(client.c:1681:after_reply()) cfs_fail_timeout id 50c sleeping for 10000ms [ 6058.431078] LustreError: 131973:0:(client.c:1681:after_reply()) cfs_fail_timeout id 50c awake [ 6058.436690] LustreError: 131973:0:(client.c:1681:after_reply()) cfs_fail_timeout id 50c sleeping for 10000ms [ 6068.527144] LustreError: 131973:0:(client.c:1681:after_reply()) cfs_fail_timeout id 50c awake [ 6068.532585] LustreError: 131973:0:(client.c:1681:after_reply()) cfs_fail_timeout id 50c sleeping for 10000ms [ 6078.623103] LustreError: 131973:0:(client.c:1681:after_reply()) cfs_fail_timeout id 50c awake [ 6078.627039] LustreError: 131973:0:(client.c:1681:after_reply()) cfs_fail_timeout id 50c sleeping for 10000ms [ 6088.719228] LustreError: 131973:0:(client.c:1681:after_reply()) cfs_fail_timeout id 50c awake [ 6088.723733] LustreError: 2403:0:(client.c:1681:after_reply()) cfs_fail_timeout id 50c sleeping for 10000ms [ 6098.799129] LustreError: 2403:0:(client.c:1681:after_reply()) cfs_fail_timeout id 50c awake [ 6098.803903] LustreError: 131973:0:(client.c:1681:after_reply()) cfs_fail_timeout id 50c sleeping for 10000ms [ 6108.895140] LustreError: 131973:0:(client.c:1681:after_reply()) cfs_fail_timeout id 50c awake [ 6110.941867] Lustre: DEBUG MARKER: == replay-single test 67a: AT: verify slow request processing doesn't induce reconnects ========================================================== 02:40:03 (1786344003) [ 6178.155461] Lustre: DEBUG MARKER: == replay-single test 67b: AT: verify instant slowdown doesn't induce reconnects ========================================================== 02:41:10 (1786344070) [ 6202.834990] Lustre: DEBUG MARKER: phase 2 [ 6205.831934] Lustre: DEBUG MARKER: == replay-single test 68: AT: verify slowing locks ======= 02:41:38 (1786344098) [ 6228.930408] LustreError: 33406:0:(ldlm_request.c:1533:ldlm_cli_cancel_req()) cfs_fail_timeout id 312 sleeping for 19000ms [ 6247.967121] LustreError: 33406:0:(ldlm_request.c:1533:ldlm_cli_cancel_req()) cfs_fail_timeout id 312 awake [ 6275.621802] Lustre: DEBUG MARKER: == replay-single test 70a: check multi client t-f ======== 02:42:48 (1786344168) [ 6276.125720] Lustre: DEBUG MARKER: SKIP: replay-single test_70a Need two or more clients, have 1 [ 6276.652857] Lustre: DEBUG MARKER: == replay-single test 70b: dbench 2mdts recovery; 1 clients ========================================================== 02:42:49 (1786344169) [ 6278.434958] Lustre: DEBUG MARKER: Started rundbench load pid=135293 ... [ 6282.207172] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 6283.786205] Lustre: DEBUG MARKER: test_70b fail mds1 1 times [ 6286.077727] LustreError: lustre-MDT0000-mdc-ffff91f762155000: operation mds_statfs to node 192.168.204.149@tcp failed: rc = -107 [ 6286.081921] Lustre: lustre-MDT0000-mdc-ffff91f762155000: Connection to lustre-MDT0000 (at 192.168.204.149@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 6286.089864] Lustre: Skipped 9 previous similar messages [ 6286.092189] LustreError: 135320:0:(lmv_obd.c:1471:lmv_statfs()) lustre-MDT0000-mdc-ffff91f762155000: can't stat MDS #0: rc = -107 [ 6286.097272] LustreError: 135320:0:(lmv_obd.c:1471:lmv_statfs()) Skipped 1 previous similar message [ 6295.004186] LustreError: 135320:0:(lmv_obd.c:1471:lmv_statfs()) lustre-MDT0000-mdc-ffff91f762155000: can't stat MDS #0: rc = -19 [ 6295.007336] LustreError: 135320:0:(lmv_obd.c:1471:lmv_statfs()) Skipped 3 previous similar messages [ 6302.688866] LustreError: MGC192.168.204.149@tcp: Connection to MGS (at 192.168.204.149@tcp) was lost; in progress operations using this service will fail [ 6302.692160] LustreError: Skipped 9 previous similar messages [ 6302.694816] Lustre: Evicted from MGS (at 192.168.204.149@tcp) after server handle changed from 0x47560188d4f7b7fb to 0x47560188d4fab930 [ 6302.698167] Lustre: Skipped 9 previous similar messages [ 6302.700985] Lustre: MGC192.168.204.149@tcp: Connection restored to 192.168.204.149@tcp (at 192.168.204.149@tcp) [ 6302.703163] Lustre: Skipped 15 previous similar messages [ 6306.710175] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6307.303922] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6312.366058] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 6313.924237] Lustre: DEBUG MARKER: test_70b fail mds2 2 times [ 6314.579982] LustreError: lustre-MDT0001-mdc-ffff91f762155000: operation ldlm_enqueue to node 192.168.204.149@tcp failed: rc = -19 [ 6330.539171] LustreError: 2402:0:(client.c:3451:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff91f7523f8000 x1873111164871296/t4294969852(4294969852) o101->lustre-MDT0001-mdc-ffff91f762155000@192.168.204.149@tcp:12/10 lens 576/608 e 0 to 0 dl 1786344239 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'dbench.0' uid:0 gid:0 projid:0 [ 6330.547349] LustreError: 2402:0:(client.c:3451:ptlrpc_replay_interpret()) Skipped 24 previous similar messages [ 6336.593768] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 6337.188835] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6342.211406] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 6343.774152] Lustre: DEBUG MARKER: test_70b fail mds1 3 times [ 6345.090639] LustreError: lustre-MDT0000-mdc-ffff91f762155000: operation mds_statfs to node 192.168.204.149@tcp failed: rc = -107 [ 6345.094623] LustreError: 135320:0:(lmv_obd.c:1471:lmv_statfs()) lustre-MDT0000-mdc-ffff91f762155000: can't stat MDS #0: rc = -107 [ 6345.097716] LustreError: 135320:0:(lmv_obd.c:1471:lmv_statfs()) Skipped 4 previous similar messages [ 6366.427170] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6367.022738] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6372.116157] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 6373.705804] Lustre: DEBUG MARKER: test_70b fail mds2 4 times [ 6374.332236] LustreError: lustre-MDT0001-mdc-ffff91f762155000: operation ldlm_enqueue to node 192.168.204.149@tcp failed: rc = -19 [ 6390.443285] LustreError: 2402:0:(client.c:3451:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff91f7523f8000 x1873111164871296/t4294969852(4294969852) o101->lustre-MDT0001-mdc-ffff91f762155000@192.168.204.149@tcp:12/10 lens 576/608 e 0 to 0 dl 1786344299 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'dbench.0' uid:0 gid:0 projid:0 [ 6390.454578] LustreError: 2402:0:(client.c:3451:ptlrpc_replay_interpret()) Skipped 69 previous similar messages [ 6395.702714] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 6396.205964] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6424.163500] Lustre: DEBUG MARKER: == replay-single test 70c: tar 2mdts recovery ============ 02:45:17 (1786344317) [ 6547.269895] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 6557.787088] Lustre: DEBUG MARKER: test_70c fail mds1 1 times [ 6558.821866] LustreError: lustre-MDT0000-mdc-ffff91f762155000: operation ldlm_enqueue to node 192.168.204.149@tcp failed: rc = -19 [ 6575.084703] LustreError: 2402:0:(client.c:3451:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff91f752108380 x1873111185318400/t326417524759(326417524759) o101->lustre-MDT0000-mdc-ffff91f762155000@192.168.204.149@tcp:12/10 lens 608/664 e 0 to 0 dl 1786344484 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'lfs.0' uid:0 gid:0 projid:0 [ 6575.092263] LustreError: 2402:0:(client.c:3451:ptlrpc_replay_interpret()) Skipped 66 previous similar messages [ 6582.970977] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6583.500879] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6707.587814] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 6718.111632] Lustre: DEBUG MARKER: test_70c fail mds1 2 times [ 6723.553191] LustreError: lustre-MDT0000-mdc-ffff91f762155000: operation mds_batch to node 192.168.204.149@tcp failed: rc = -107 [ 6744.041746] LustreError: 2402:0:(client.c:3451:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff91f752108380 x1873111185318400/t326417524759(326417524759) o101->lustre-MDT0000-mdc-ffff91f762155000@192.168.204.149@tcp:12/10 lens 608/664 e 0 to 0 dl 1786344653 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'lfs.0' uid:0 gid:0 projid:0 [ 6744.052288] LustreError: 2402:0:(client.c:3451:ptlrpc_replay_interpret()) Skipped 235 previous similar messages [ 6748.237487] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6748.797160] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6766.262195] Lustre: DEBUG MARKER: == replay-single test 70d: mkdir/rmdir striped dir 2mdts recovery ========================================================== 02:50:59 (1786344659) [ 6889.241880] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 6899.815609] Lustre: DEBUG MARKER: test_70d fail mds1 1 times [ 6902.752762] Lustre: lustre-MDT0000-mdc-ffff91f762155000: Connection to lustre-MDT0000 (at 192.168.204.149@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 6902.757867] Lustre: Skipped 5 previous similar messages [ 6923.233241] LustreError: MGC192.168.204.149@tcp: Connection to MGS (at 192.168.204.149@tcp) was lost; in progress operations using this service will fail [ 6923.236616] LustreError: Skipped 3 previous similar messages [ 6923.241128] Lustre: Evicted from MGS (at 192.168.204.149@tcp) after server handle changed from 0x47560188d52d4f8b to 0x47560188d53d136d [ 6923.246399] Lustre: Skipped 3 previous similar messages [ 6923.248785] Lustre: MGC192.168.204.149@tcp: Connection restored to 192.168.204.149@tcp (at 192.168.204.149@tcp) [ 6923.251435] Lustre: Skipped 9 previous similar messages [ 6926.239895] LustreError: 2402:0:(client.c:3451:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff91f747538380 x1873111226465920/t335007465628(335007465628) o101->lustre-MDT0000-mdc-ffff91f762155000@192.168.204.149@tcp:12/10 lens 576/608 e 0 to 0 dl 1786344835 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'touch.0' uid:0 gid:0 projid:0 [ 6926.246322] LustreError: 2402:0:(client.c:3451:ptlrpc_replay_interpret()) Skipped 232 previous similar messages [ 6928.787113] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6929.288687] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7053.456733] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 7064.047141] Lustre: DEBUG MARKER: test_70d fail mds2 2 times [ 7064.978912] LustreError: lustre-MDT0001-mdc-ffff91f762155000: operation mds_reint to node 192.168.204.149@tcp failed: rc = -19 [ 7087.149102] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 7087.712783] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7091.018980] Lustre: DEBUG MARKER: == replay-single test 70e: rename cross-MDT with random fails ========================================================== 02:56:23 (1786344983) [ 7214.286238] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 7224.828433] Lustre: DEBUG MARKER: test_70e fail mds1 1 times [ 7225.706066] LustreError: lustre-MDT0000-mdc-ffff91f762155000: operation mds_close to node 192.168.204.149@tcp failed: rc = -19 [ 7244.767140] Lustre: 2403:0:(client.c:2506:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786345122/real 1786345122] req@ffff91f751f2ed80 x1873111248552320/t0(0) o400->MGC192.168.204.149@tcp@192.168.204.149@tcp:26/25 lens 224/224 e 0 to 1 dl 1786345138 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 7244.777631] Lustre: 2403:0:(client.c:2506:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 7244.778355] LustreError: 2402:0:(client.c:3451:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff91f7520dbb80 x1873111239618816/t339302434395(339302434395) o101->lustre-MDT0000-mdc-ffff91f762155000@192.168.204.149@tcp:12/10 lens 648/608 e 0 to 0 dl 1786345154 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'lfs.0' uid:0 gid:0 projid:0 [ 7244.791403] LustreError: 2402:0:(client.c:3451:ptlrpc_replay_interpret()) Skipped 156 previous similar messages [ 7250.288879] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 7250.847120] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7375.064387] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 7385.643422] Lustre: DEBUG MARKER: test_70e fail mds1 2 times [ 7386.454655] LustreError: lustre-MDT0000-mdc-ffff91f762155000: operation ldlm_enqueue to node 192.168.204.149@tcp failed: rc = -19 [ 7410.487326] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 7411.104875] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7414.905168] Lustre: DEBUG MARKER: == replay-single test 70f: OSS O_DIRECT recovery with 1 clients ========================================================== 03:01:47 (1786345307) [ 7420.666240] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-OST0000 [ 7422.137121] Lustre: DEBUG MARKER: test_70f failing OST 1 times [ 7435.231081] Lustre: 2406:0:(client.c:2506:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786345312/real 1786345312] req@ffff91f771fc8000 x1873111257983360/t0(0) o4->lustre-OST0000-osc-ffff91f762155000@192.168.204.149@tcp:6/4 lens 488/448 e 0 to 1 dl 1786345328 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'dd.0' uid:0 gid:0 projid:0 [ 7442.840979] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 7443.515871] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 7452.374814] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-OST0000 [ 7453.862101] Lustre: DEBUG MARKER: test_70f failing OST 2 times [ 7474.510918] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 7475.060263] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 7480.638709] Lustre: DEBUG MARKER: == replay-single test 71a: mkdir/rmdir striped dir with 2 mdts recovery ========================================================== 03:02:53 (1786345373) [ 7603.524646] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 7606.107406] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 7616.626091] Lustre: DEBUG MARKER: fail mds1 mds2 1 times [ 7617.479155] LustreError: lustre-MDT0000-mdc-ffff91f762155000: operation mds_reint to node 192.168.204.149@tcp failed: rc = -19 [ 7617.483357] Lustre: lustre-MDT0000-mdc-ffff91f762155000: Connection to lustre-MDT0000 (at 192.168.204.149@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 7617.488033] Lustre: Skipped 5 previous similar messages [ 7633.887108] Lustre: 2405:0:(client.c:2506:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786345511/real 1786345511] req@ffff91f751edbb80 x1873111265227520/t0(0) o400->MGC192.168.204.149@tcp@192.168.204.149@tcp:26/25 lens 224/224 e 0 to 1 dl 1786345527 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 7633.893872] Lustre: 2405:0:(client.c:2506:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 7633.895628] LustreError: MGC192.168.204.149@tcp: Connection to MGS (at 192.168.204.149@tcp) was lost; in progress operations using this service will fail [ 7633.898361] LustreError: Skipped 2 previous similar messages [ 7644.129308] Lustre: Evicted from MGS (at 192.168.204.149@tcp) after server handle changed from 0x47560188d56ea2a7 to 0x47560188d57d9e30 [ 7644.133249] Lustre: Skipped 2 previous similar messages [ 7644.135176] Lustre: MGC192.168.204.149@tcp: Connection restored to 192.168.204.149@tcp (at 192.168.204.149@tcp) [ 7644.137272] Lustre: Skipped 7 previous similar messages [ 7658.932886] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 7659.529332] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7660.139933] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7663.569469] Lustre: DEBUG MARKER: == replay-single test 73a: open(O_CREAT), unlink, replay, reconnect before open replay, close ========================================================== 03:05:56 (1786345556) [ 7666.105176] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 7702.495170] LustreError: 2402:0:(client.c:3401:ptlrpc_replay_interpret()) @@@ request replay timed out req@ffff91f771c3b480 x1873111258330624/t347892351733(347892351733) o101->lustre-MDT0000-mdc-ffff91f762155000@192.168.204.149@tcp:12/10 lens 520/664 e 0 to 1 dl 1786345595 ref 2 fl Interpret:EXPQU/604/ffffffff rc -110/-1 job:'lfs.0' uid:0 gid:0 projid:0 [ 7704.604843] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 7705.152336] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7708.495570] Lustre: DEBUG MARKER: == replay-single test 73b: open(O_CREAT), unlink, replay, reconnect at open_replay reply, close ========================================================== 03:06:41 (1786345601) [ 7711.115914] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 7743.455168] LustreError: 2402:0:(client.c:3401:ptlrpc_replay_interpret()) @@@ request replay timed out req@ffff91f771c3b480 x1873111258330624/t347892351733(347892351733) o101->lustre-MDT0000-mdc-ffff91f762155000@192.168.204.149@tcp:12/10 lens 520/664 e 0 to 1 dl 1786345636 ref 2 fl Interpret:EXPQU/604/ffffffff rc -110/-1 job:'lfs.0' uid:0 gid:0 projid:0 [ 7745.472288] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 7746.006993] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7749.738960] Lustre: DEBUG MARKER: == replay-single test 74: Ensure applications don't fail waiting for OST recovery ========================================================== 03:07:22 (1786345642) [ 7750.742087] Lustre: Unmounted lustre-client [ 7773.165322] Lustre: Mounted lustre-client - version 2.17.56_50_g8cc021f [ 7781.696548] Lustre: DEBUG MARKER: == replay-single test 80a: DNE: create remote dir, drop update rep from MDT0, fail MDT0 ========================================================== 03:07:54 (1786345674) [ 7784.658639] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 7810.450661] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 7811.328433] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7817.790457] Lustre: DEBUG MARKER: == replay-single test 80b: DNE: create remote dir, drop update rep from MDT0, fail MDT1 ========================================================== 03:08:30 (1786345710) [ 7822.987167] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 7826.116163] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 7855.216812] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 7855.739842] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7859.320532] Lustre: DEBUG MARKER: == replay-single test 80c: DNE: create remote dir, drop update rep from MDT1, fail MDT[0,1] ========================================================== 03:09:12 (1786345752) [ 7862.217860] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 7864.734312] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 7885.219649] LustreError: 2402:0:(client.c:3451:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff91f7574c1180 x1873111265547264/t369367187488(369367187488) o101->lustre-MDT0000-mdc-ffff91f7519ce800@192.168.204.149@tcp:12/10 lens 520/664 e 0 to 0 dl 1786345794 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'lfs.0' uid:0 gid:0 projid:0 [ 7885.227244] LustreError: 2402:0:(client.c:3451:ptlrpc_replay_interpret()) Skipped 802 previous similar messages [ 7887.231769] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 7887.845376] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7911.568319] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 7912.083880] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7915.598448] Lustre: DEBUG MARKER: == replay-single test 80d: DNE: create remote dir, drop update rep from MDT1, fail 2 MDTs ========================================================== 03:10:08 (1786345808) [ 7921.277982] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 7923.920801] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 7926.335665] LustreError: lustre-MDT0001-mdc-ffff91f7519ce800: operation mds_reint to node 192.168.204.149@tcp failed: rc = -19 [ 7926.340151] LustreError: Skipped 4 previous similar messages [ 7942.111255] Lustre: 2403:0:(client.c:2506:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786345819/real 1786345819] req@ffff91f7575c2300 x1873111265587328/t0(0) o400->MGC192.168.204.149@tcp@192.168.204.149@tcp:26/25 lens 224/224 e 0 to 1 dl 1786345835 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 7942.121893] Lustre: 2403:0:(client.c:2506:ptlrpc_expire_one_request()) Skipped 6 previous similar messages [ 7959.166347] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 7959.829473] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7960.495703] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7964.857785] Lustre: DEBUG MARKER: == replay-single test 80e: DNE: create remote dir, drop MDT1 rep, fail MDT0 ========================================================== 03:10:57 (1786345857) [ 7971.341535] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 7993.976210] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 7994.467631] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8022.254054] Lustre: DEBUG MARKER: == replay-single test 80f: DNE: create remote dir, drop MDT1 rep, fail MDT1 ========================================================== 03:11:55 (1786345915) [ 8024.981112] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 8046.548301] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 8047.020762] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8050.318350] Lustre: DEBUG MARKER: == replay-single test 80g: DNE: create remote dir, drop MDT1 rep, fail MDT0, then MDT1 ========================================================== 03:12:23 (1786345943) [ 8055.930196] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 8058.296687] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 8080.129790] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 8080.697516] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8104.082544] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 8104.599929] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8108.223396] Lustre: DEBUG MARKER: == replay-single test 80h: DNE: create remote dir, drop MDT1 rep, fail 2 MDTs ========================================================== 03:13:21 (1786346001) [ 8114.091268] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 8116.552500] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 8135.777329] Lustre: 231322:0:(mgc_request.c:1899:mgc_process_log()) MGC192.168.204.149@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 8152.272759] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 8152.787106] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8153.271211] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8156.778435] Lustre: DEBUG MARKER: == replay-single test 81a: DNE: unlink remote dir, drop MDT0 update rep, fail MDT1 ========================================================== 03:14:09 (1786346049) [ 8159.586588] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 8186.962275] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 8187.452734] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8190.837187] Lustre: DEBUG MARKER: == replay-single test 81b: DNE: unlink remote dir, drop MDT0 update reply, fail MDT0 ========================================================== 03:14:43 (1786346083) [ 8193.590243] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 8215.708225] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 8216.247475] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8219.754737] Lustre: DEBUG MARKER: == replay-single test 81c: DNE: unlink remote dir, drop MDT0 update reply, fail MDT0,MDT1 ========================================================== 03:15:12 (1786346112) [ 8222.456768] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 8224.929700] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 8227.296652] Lustre: lustre-MDT0000-mdc-ffff91f7519ce800: Connection to lustre-MDT0000 (at 192.168.204.149@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 8227.300749] Lustre: Skipped 19 previous similar messages [ 8242.657364] LustreError: MGC192.168.204.149@tcp: Connection to MGS (at 192.168.204.149@tcp) was lost; in progress operations using this service will fail [ 8242.661177] LustreError: Skipped 9 previous similar messages [ 8245.146655] Lustre: lustre-MDT0000-mdc-ffff91f7519ce800: Connection restored to 192.168.204.149@tcp (at 192.168.204.149@tcp) [ 8245.150235] Lustre: Skipped 30 previous similar messages [ 8246.895512] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 8247.372642] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8270.541512] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 8271.092804] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8274.595192] Lustre: DEBUG MARKER: == replay-single test 81d: DNE: unlink remote dir, drop MDT0 update reply, fail 2 MDTs ========================================================== 03:16:07 (1786346167) [ 8277.377891] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 8279.861941] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 8311.265941] Lustre: Evicted from MGS (at 192.168.204.149@tcp) after server handle changed from 0x47560188d57f1486 to 0x47560188d57f1eea [ 8311.270425] Lustre: Skipped 10 previous similar messages [ 8313.801644] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 8314.318370] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8314.811337] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8318.299329] Lustre: DEBUG MARKER: == replay-single test 81e: DNE: unlink remote dir, drop MDT1 req reply, fail MDT0 ========================================================== 03:16:51 (1786346211) [ 8321.464527] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 8343.133611] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 8343.650519] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8347.185375] Lustre: DEBUG MARKER: == replay-single test 81f: DNE: unlink remote dir, drop MDT1 req reply, fail MDT1 ========================================================== 03:17:20 (1786346240) [ 8350.119684] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 8371.926323] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 8372.461155] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8376.008546] Lustre: DEBUG MARKER: == replay-single test 81g: DNE: unlink remote dir, drop req reply, fail M0, then M1 ========================================================== 03:17:48 (1786346268) [ 8378.927978] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 8381.434519] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 8403.654194] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 8404.188965] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8427.170288] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 8427.719404] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8431.164444] Lustre: DEBUG MARKER: == replay-single test 81h: DNE: unlink remote dir, drop request reply, fail 2 MDTs ========================================================== 03:18:44 (1786346324) [ 8433.979680] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 8436.430576] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 8458.209536] Lustre: 231322:0:(mgc_request.c:1899:mgc_process_log()) MGC192.168.204.149@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 8472.321960] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid,mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 8472.813051] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8473.315165] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8476.979353] Lustre: DEBUG MARKER: == replay-single test 84a: stale open during export disconnect ========================================================== 03:19:29 (1786346369) [ 8478.903861] LustreError: lustre-MDT0000-mdc-ffff91f7519ce800: operation ldlm_enqueue to node 192.168.204.149@tcp failed: rc = -107 [ 8478.906878] LustreError: Skipped 2 previous similar messages [ 8478.910030] LustreError: lustre-MDT0000-mdc-ffff91f7519ce800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 8478.914217] LustreError: 261935:0:(file.c:6154:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -5 [ 8482.406403] Lustre: DEBUG MARKER: == replay-single test 85a: check the cancellation of unused locks during recovery(IBITS) ========================================================== 03:19:35 (1786346375) [ 8501.225965] LustreError: 2402:0:(client.c:3451:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff91f751a0e300 x1873111265863040/t416611827720(416611827720) o101->lustre-MDT0000-mdc-ffff91f7519ce800@192.168.204.149@tcp:12/10 lens 576/608 e 0 to 0 dl 1786346410 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'grep.0' uid:0 gid:0 projid:0 [ 8501.236943] LustreError: 2402:0:(client.c:3451:ptlrpc_replay_interpret()) Skipped 3 previous similar messages [ 8504.438215] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 8504.995558] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8509.048872] Lustre: DEBUG MARKER: == replay-single test 85b: check the cancellation of unused locks during recovery(EXTENT) ========================================================== 03:20:01 (1786346401) [ 8533.446668] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 8533.964043] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 8537.395440] Lustre: DEBUG MARKER: == replay-single test 86: umount server after clear nid_stats should not hit LBUG ========================================================== 03:20:30 (1786346430) [ 8537.798416] Lustre: Unmounted lustre-client [ 8548.850786] Lustre: Mounted lustre-client - version 2.17.56_50_g8cc021f [ 8550.996082] Lustre: DEBUG MARKER: == replay-single test 87a: write replay ================== 03:20:43 (1786346443) [ 8553.800019] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-OST0000 [ 8574.214334] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 8574.693179] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 8578.044151] Lustre: DEBUG MARKER: == replay-single test 87b: write replay with changed data (checksum resend) ========================================================== 03:21:10 (1786346470) [ 8580.802617] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-OST0000 [ 8602.120271] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 8602.597463] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 8605.859348] Lustre: DEBUG MARKER: == replay-single test 88: MDS should not assign same objid to different files ========================================================== 03:21:38 (1786346498) [ 8608.292672] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-OST0000 [ 8610.736926] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 8630.751136] Lustre: 2404:0:(client.c:2506:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786346508/real 1786346508] req@ffff91f750cafb80 x1873111266316672/t0(0) o400->MGC192.168.204.149@tcp@192.168.204.149@tcp:26/25 lens 224/224 e 0 to 1 dl 1786346524 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 8630.758737] Lustre: 2404:0:(client.c:2506:ptlrpc_expire_one_request()) Skipped 15 previous similar messages [ 8632.161490] Lustre: 265883:0:(mgc_request.c:1899:mgc_process_log()) MGC192.168.204.149@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 8663.397792] Lustre: DEBUG MARKER: == replay-single test 89: no disk space leak on late ost connection ========================================================== 03:22:36 (1786346556) [ 8691.922855] Lustre: Unmounted lustre-client [ 8696.189196] Lustre: Mounted lustre-client - version 2.17.56_50_g8cc021f [ 8768.634660] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 69 sec [ 8776.955358] Lustre: DEBUG MARKER: free_before: 7646268 free_after: 7646268 [ 8778.953852] Lustre: DEBUG MARKER: == replay-single test 90: lfs find identifies the missing striped file segments ========================================================== 03:24:31 (1786346671) [ 8799.821866] Lustre: DEBUG MARKER: == replay-single test 93a: replay + reconnect ============ 03:24:52 (1786346692) [ 8856.520553] Lustre: lustre-OST0000-osc-ffff91f762156000: Connection restored to 192.168.204.149@tcp (at 192.168.204.149@tcp) [ 8856.523914] Lustre: Skipped 26 previous similar messages [ 8858.889733] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 8859.444569] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 8862.787408] Lustre: DEBUG MARKER: == replay-single test 93b: replay + reconnect on mds ===== 03:25:55 (1786346755) [ 8868.320508] Lustre: lustre-MDT0000-mdc-ffff91f762156000: Connection to lustre-MDT0000 (at 192.168.204.149@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 8868.324358] Lustre: Skipped 22 previous similar messages [ 8878.560711] LustreError: MGC192.168.204.149@tcp: Connection to MGS (at 192.168.204.149@tcp) was lost; in progress operations using this service will fail [ 8878.564217] LustreError: Skipped 7 previous similar messages [ 8964.692573] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 8965.270574] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8968.938833] Lustre: DEBUG MARKER: == replay-single test complete, duration 8608 sec ======== 03:27:41 (1786346861) [ 8969.522175] Lustre: DEBUG MARKER: === replay-single: start cleanup 03:27:42 (1786346862) === [ 8972.111438] Lustre: DEBUG MARKER: === replay-single: finish cleanup 03:27:44 (1786346864) === [ 8995.552908] Lustre: Evicted from MGS (at 192.168.204.149@tcp) after server handle changed from 0x47560188d57fcb90 to 0x47560188d5801c10 [ 8995.555927] Lustre: Skipped 7 previous similar messages [ 9001.733917] Lustre: DEBUG MARKER: oleg449-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 9002.307350] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 9003.868899] Lustre: Unmounted lustre-client [ 9039.357481] Key type lgssc unregistered [ 9039.477609] LNet: 279359:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 9039.481034] LNetError: 279359:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 9039.489432] LNet: Removed LNI 192.168.204.49@tcp [ 9039.781121] Key type .llcrypt unregistered [ 9039.782454] Key type ._llcrypt unregistered