[ 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 451782084 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2399.998 MHz processor [ 0.000000] last_pfn = 0x146e00 max_arch_pfn = 0x400000000 [ 0.000000] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT [ 0.000000] last_pfn = 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, 524580K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] ftrace: allocating 41240 entries in 162 pages [ 0.000000] ftrace: allocated 162 pages with 3 groups [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] rcu: RCU event tracing is enabled. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ 0.000000] rcu: RCU callback double-/use-after-free debug enabled. [ 0.000000] Rude variant of Tasks RCU enabled. [ 0.000000] Tracing variant of Tasks RCU enabled. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 0.000000] NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16 [ 0.000000] random: get_random_bytes called from start_kernel+0x622/0x9a8 with crng_init=0 [ 0.001000] Console: colour *CGA 80x25 [ 0.001000] printk: console [ttyS1] enabled [ 0.001000] ACPI: Core revision 20220331 [ 0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.001012] APIC: Switch to symmetric I/O mode setup [ 0.003356] x2apic enabled [ 0.004010] Switched APIC routing to physical x2apic. [ 0.005017] kvm-guest: setup PV IPIs [ 0.008000] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.008000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.008021] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.009012] pid_max: default: 32768 minimum: 301 [ 0.010142] LSM: Security Framework initializing [ 0.011056] Yama: becoming mindful. [ 0.012033] SELinux: Initializing. [ 0.013064] *** VALIDATE selinux *** [ 0.022365] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.027048] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.029119] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.031064] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.033133] *** VALIDATE tmpfs *** [ 0.034491] *** VALIDATE proc *** [ 0.035269] *** VALIDATE cgroup *** [ 0.036012] *** VALIDATE cgroup2 *** [ 0.037263] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.038175] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.039011] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.040033] Spectre V2 : User space: Vulnerable [ 0.041010] Speculative Store Bypass: Vulnerable [ 0.043681] debug: unmapping init [mem 0xffffffffa6059000-0xffffffffa6060fff] [ 0.045814] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.046726] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.047021] ... version: 2 [ 0.047981] ... bit width: 48 [ 0.048014] ... generic registers: 4 [ 0.049016] ... value mask: 0000ffffffffffff [ 0.050091] ... max period: 00007fffffffffff [ 0.051019] ... fixed-purpose events: 3 [ 0.052016] ... event mask: 000000070000000f [ 0.054224] rcu: Hierarchical SRCU implementation. [ 0.056523] smp: Bringing up secondary CPUs ... [ 0.057659] x86: Booting SMP configuration: [ 0.058037] .... node #0, CPUs: #1 #2 #3 [ 0.062023] smp: Brought up 1 node, 4 CPUs [ 0.064017] smpboot: Max logical packages: 1 [ 0.065026] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.215958] node 0 deferred pages initialised in 149ms [ 0.220158] devtmpfs: initialized [ 0.222386] x86/mm: Memory block size: 128MB [ 0.225222] gcov: version magic: 0x41383552 [ 0.228351] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.233114] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.236393] pinctrl core: initialized pinctrl subsystem [ 0.238256] [ 0.238940] ************************************************************* [ 0.241019] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.243011] ** ** [ 0.244014] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.246021] ** ** [ 0.248017] ** This means that this kernel is built to expose internal ** [ 0.250092] ** IOMMU data structures, which may compromise security on ** [ 0.253015] ** your system. ** [ 0.255016] ** ** [ 0.258016] ** If you see this message and you are not debugging the ** [ 0.260013] ** kernel, report this immediately to your vendor! ** [ 0.262012] ** ** [ 0.263024] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.265012] ************************************************************* [ 0.267550] NET: Registered protocol family 16 [ 0.270451] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.272087] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.275091] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.280067] cpuidle: using governor menu [ 0.281940] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.284618] PCI: Using configuration type 1 for base access [ 0.287157] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.296068] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.297022] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.299075] cryptd: max_cpu_qlen set to 1000 [ 0.301262] ACPI: Added _OSI(Module Device) [ 0.302012] ACPI: Added _OSI(Processor Device) [ 0.303016] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.304013] ACPI: Added _OSI(Processor Aggregator Device) [ 0.308831] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.316589] ACPI: Interpreter enabled [ 0.318100] ACPI: PM: (supports S0 S3 S4 S5) [ 0.320026] ACPI: Using IOAPIC for interrupt routing [ 0.322158] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.326518] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.336825] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.339071] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.342039] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.346128] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.351537] acpiphp: Slot [2] registered [ 0.354184] acpiphp: Slot [5] registered [ 0.355212] acpiphp: Slot [6] registered [ 0.357229] acpiphp: Slot [3] registered [ 0.359142] acpiphp: Slot [4] registered [ 0.360183] acpiphp: Slot [7] registered [ 0.362147] acpiphp: Slot [8] registered [ 0.364151] acpiphp: Slot [9] registered [ 0.365154] acpiphp: Slot [10] registered [ 0.367184] acpiphp: Slot [11] registered [ 0.369157] acpiphp: Slot [12] registered [ 0.370165] acpiphp: Slot [13] registered [ 0.372140] acpiphp: Slot [14] registered [ 0.374137] acpiphp: Slot [15] registered [ 0.375175] acpiphp: Slot [16] registered [ 0.377209] acpiphp: Slot [17] registered [ 0.379140] acpiphp: Slot [18] registered [ 0.381134] acpiphp: Slot [19] registered [ 0.382124] acpiphp: Slot [20] registered [ 0.384314] acpiphp: Slot [21] registered [ 0.386203] acpiphp: Slot [22] registered [ 0.388175] acpiphp: Slot [23] registered [ 0.389241] acpiphp: Slot [24] registered [ 0.391106] acpiphp: Slot [25] registered [ 0.393121] acpiphp: Slot [26] registered [ 0.395156] acpiphp: Slot [27] registered [ 0.396121] acpiphp: Slot [28] registered [ 0.398114] acpiphp: Slot [29] registered [ 0.399164] acpiphp: Slot [30] registered [ 0.401132] acpiphp: Slot [31] registered [ 0.403109] PCI host bridge to bus 0000:00 [ 0.404079] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.407075] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.410031] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.413040] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.415042] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.418038] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.420198] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.422029] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.426445] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.434565] pci 0000:00:01.1: reg 0x20: [io 0xc120-0xc12f] [ 0.440102] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.443044] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.446032] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.448035] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.451471] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.453895] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.456054] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.459890] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.465018] pci 0000:00:02.0: reg 0x10: [io 0xc100-0xc11f] [ 0.475019] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.480623] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.486492] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.493027] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.502025] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.517023] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.525537] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.533021] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.539030] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.557017] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.564420] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.568533] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.572591] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.575384] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.577236] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.582185] iommu: Default domain type: Passthrough [ 0.584645] SCSI subsystem initialized [ 0.586145] ACPI: bus type USB registered [ 0.588166] usbcore: registered new interface driver usbfs [ 0.590088] usbcore: registered new interface driver hub [ 0.592095] usbcore: registered new device driver usb [ 0.594194] pps_core: LinuxPPS API ver. 1 registered [ 0.596011] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.600075] PTP clock support registered [ 0.602291] EDAC MC: Ver: 3.0.0 [ 0.604465] PCI: Using ACPI for IRQ routing [ 0.605670] NetLabel: Initializing [ 0.607023] NetLabel: domain hash size = 128 [ 0.609014] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.610070] NetLabel: unlabeled traffic allowed by default [ 0.613176] vgaarb: loaded [ 0.614392] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.617021] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.622442] clocksource: Switched to clocksource kvm-clock [ 0.731188] VFS: Disk quotas dquot_6.6.0 [ 0.732789] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.735153] *** VALIDATE ramfs *** [ 0.736525] *** VALIDATE hugetlbfs *** [ 0.738019] pnp: PnP ACPI init [ 0.740030] pnp: PnP ACPI: found 6 devices [ 0.760315] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.764069] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.766463] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.768609] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.771185] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.773641] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.776666] NET: Registered protocol family 2 [ 0.779605] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.784787] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.787966] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.793881] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.797647] TCP: Hash tables configured (established 65536 bind 65536) [ 0.801324] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.804904] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.807537] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.810386] NET: Registered protocol family 1 [ 0.812770] RPC: Registered named UNIX socket transport module. [ 0.814933] RPC: Registered udp transport module. [ 0.816702] RPC: Registered tcp transport module. [ 0.818725] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.821428] NET: Registered protocol family 44 [ 0.823267] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.825504] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.827768] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.830313] PCI: CLS 0 bytes, default 64 [ 0.832316] Unpacking initramfs... [ 2.290889] debug: unmapping init [mem 0xffff90377cc64000-0xffff90377ffcffff] [ 2.297681] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.300090] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.304896] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 2.811491] Initialise system trusted keyrings [ 2.813484] Key type blacklist registered [ 2.815136] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.824627] zbud: loaded [ 2.827689] *** VALIDATE nfs *** [ 2.828984] *** VALIDATE nfs4 *** [ 2.831029] pstore: using deflate compression [ 2.835134] Platform Keyring initialized [ 2.937560] NET: Registered protocol family 38 [ 2.939833] Key type asymmetric registered [ 2.941768] Asymmetric key parser 'x509' registered [ 2.944176] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 2.948315] io scheduler mq-deadline registered [ 2.950374] io scheduler kyber registered [ 2.952235] io scheduler bfq registered [ 2.954063] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 2.957242] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 2.960226] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 2.963223] ACPI: Power Button [PWRF] [ 2.968311] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 2.975203] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 2.987279] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 3.015264] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.045922] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.051467] Non-volatile memory driver v1.3 [ 3.053159] Linux agpgart interface v0.103 [ 3.102346] virtio_blk virtio1: [vda] 146152 512-byte logical blocks (74.8 MB/71.4 MiB) [ 3.107018] vda: detected capacity change from 0 to 74829824 [ 3.135497] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.138873] vdb: detected capacity change from 0 to 1073741824 [ 3.150312] libphy: Fixed MDIO Bus: probed [ 3.160734] usbcore: registered new interface driver usbserial_generic [ 3.164053] usbserial: USB Serial support registered for generic [ 3.166754] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.172037] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.174463] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.177199] mousedev: PS/2 mouse device common for all mice [ 3.181660] rtc_cmos 00:05: RTC can wake from S4 [ 3.185728] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.190983] rtc_cmos 00:05: registered as rtc0 [ 3.193569] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.194502] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.200304] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.203729] intel_pstate: CPU model not supported [ 3.211646] hid: raw HID events driver (C) Jiri Kosina [ 3.214169] usbcore: registered new interface driver usbhid [ 3.216456] usbhid: USB HID core driver [ 3.218257] drop_monitor: Initializing network drop monitor service [ 3.221295] Initializing XFRM netlink socket [ 3.223580] NET: Registered protocol family 10 [ 3.226746] Segment Routing with IPv6 [ 3.228806] NET: Registered protocol family 17 [ 3.231485] mpls_gso: MPLS GSO support [ 3.237534] RAS: Correctable Errors collector initialized. [ 3.240466] AVX version of gcm_enc/dec engaged. [ 3.242471] AES CTR mode by8 optimization enabled [ 3.325805] sched_clock: Marking stable (3325774900, 0)->(4259781535, -934006635) [ 3.330436] registered taskstats version 1 [ 3.333062] Loading compiled-in X.509 certificates [ 3.335308] zswap: loaded using pool lzo/zbud [ 3.359438] Key type big_key registered [ 3.371556] Key type encrypted registered [ 3.373576] ima: No TPM chip found, activating TPM-bypass! [ 3.375972] ima: Allocated hash algorithm: sha1 [ 3.377939] ima: No architecture policies found [ 3.379936] evm: Initialising EVM extended attributes: [ 3.381767] evm: security.selinux [ 3.383277] evm: security.ima [ 3.384494] evm: security.capability [ 3.386040] evm: HMAC attrs: 0x1 [ 3.388808] rtc_cmos 00:05: setting system clock to 2026-08-24 11:51:19 UTC (1787572279) [ 3.395591] debug: unmapping init [mem 0xffffffffa7003000-0xffffffffa71fffff] [ 3.398964] debug: unmapping init [mem 0xffffffffa5d82000-0xffffffffa6058fff] [ 3.408090] Write protecting the kernel read-only data: 28672k [ 3.412079] debug: unmapping init [mem 0xffffffffa4403000-0xffffffffa45fffff] [ 3.415806] debug: unmapping init [mem 0xffffffffa4d14000-0xffffffffa4dfffff] [ 3.448941] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 3.459243] systemd[1]: Detected virtualization kvm. [ 3.461371] systemd[1]: Detected architecture x86-64. [ 3.463626] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.494532] systemd[1]: No hostname configured. [ 3.496625] systemd[1]: Set hostname to . [ 3.498981] random: systemd: uninitialized urandom read (16 bytes read) [ 3.501857] systemd[1]: Initializing machine ID from random generator. [ 3.537157] random: ln: uninitialized urandom read (6 bytes read) [ 3.637083] random: systemd: uninitialized urandom read (16 bytes read) [ 3.640031] systemd[1]: Reached target Initrd Root Device. [ OK ] Reached target Initrd Root Device. [ 3.646175] systemd[1]: Listening on Journal Socket. [ OK ] Listening on Journal Socket. [ 3.650339] systemd[1]: Reached target Swap. [ OK ] Reached target Swap. [ OK ] Listening on udev Control Socket. [ OK ] Started Memstrack Anylazing Service. Starting Create list of required st…ce nodes for the current kernel... Starting Apply Kernel Variables... [ OK ] Reached target Local File Systems. Starting Setup Virtual Console... [ OK ] Reached target Slices. [ OK ] Listening on udev Kernel Socket. Starting Create Volatile Files and Directories... [ OK ] Listening on Journal Socket (/dev/log). [ OK ] Reached target Sockets. Starting Journal Service... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Timers. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Apply Kernel Variables. [ OK ] Started Setup Virtual Console. [ OK ] Started Create Volatile Files and Directories. Starting dracut cmdline hook... Starting Create Static Device Nodes in /dev... [ OK ] Started Journal Service. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 4.603986] device-mapper: uevent: version 1.0.3 [ 4.607395] device-mapper: ioctl: 4.46.0-ioctl (2022-02-22) initialised: dm-devel@redhat.com [ OK ] Started dracut pre-udev hook. Starting udev Kernel Device Manager... [ OK ] Started udev Kernel Device Manager. Starting dracut pre-trigger hook... [ OK ] Started dracut pre-trigger hook. Starting udev Coldplug all Devices... Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. Starting dracut initqueue hook... [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ 6.249248] virtio_net virtio0 ens2: renamed from eth0 [ 6.399037] scsi host0: ata_piix [ 6.450095] scsi host1: ata_piix [ 6.616664] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc120 irq 14 [ 6.628699] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc128 irq 15 [ 11.908364] random: crng init done [ 11.913838] random: 7 urandom warning(s) missed due to ratelimiting [ 12.147583] dracut-initqueue[587]: 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. [ 14.354068] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped target Timers. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Sockets. [ OK ] Stopped target Slices. [ OK ] Stopped target Paths. [ OK ] Stopped target System Initialization. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. [ OK ] Stopped target Swap. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. Stopping udev Kernel Device Manager... [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped Apply Kernel Variables. [ 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 Control Socket. [ OK ] Closed udev Kernel Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 17.855282] printk: systemd: 25 output lines suppressed due to ratelimiting [ 18.895975] SELinux: Disabled at runtime. [ 19.064869] 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) [ 19.092515] systemd[1]: Detected virtualization kvm. [ 19.098331] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 21.175342] systemd[1]: initrd-switch-root.service: Succeeded. [ 21.184468] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 21.200630] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 21.211482] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 21.219261] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 21.237688] systemd[1]: Starting Journal Service... Starting Journal Service... [ 21.272627] systemd[1]: Mounting POSIX Message Queue File System... Mounting POSIX Message Queue File System... [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd File Systems. [ OK ] Created slice system-getty.slice. [ OK ] Listening on RPCbind Server Activation Socket. Mounting Huge Pages File System... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Listening on Process Core Dump Socket. [ OK ] Reached target RPC Port Mapper. Mounting Kernel Debug File System... [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Stopped target Initrd Root File System. [ OK ] Listening on initctl Compatibility Named Pipe. Starting Remount Root and Kernel File Systems... Activating swap /dev/disk/by-label/SWAP... [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Reached target Paths. [ OK ] Reached target Local Encrypted Volumes. Starting Create list of required st…ce nodes for the current kernel... [ 21.733675] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Reached target rpc_pipefs.target. [ OK ] Listening on udev Kernel Socket. [ OK ] Created slice User and Session Slice. [ OK ] Reached target Slices. [ OK ] Listening on udev Control Socket. Starting udev Coldplug all Devices... Starting Apply Kernel Variables... [ OK ] Started Journal Service. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Mounted Huge Pages File System. [ OK ] Mounted Kernel Debug File System. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ 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 ] Reached target Swap. Starting Configure read-only root support... Starting Create Static Device Nodes in /dev... Starting Flush Journal to Persistent Storage... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. Starting udev Kernel Device Manager... [ OK ] Reached target Local File Systems (Pre). Mounting /home/green/git/lustre-release... Mounting /mnt... [ OK ] Started udev Coldplug all Devices. [ OK ] Mounted /mnt. [ 22.944261] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 23.804735] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 24.124427] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 24.357066] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 24.449385] EDAC sbridge: Ver: 1.1.2 [ 27.914287] Key type dns_resolver registered [ 28.771964] NFS: Registering the id_resolver key type [ 28.781074] Key type id_resolver registered [ 28.786994] Key type id_legacy registered [* ] A start job is running for Configur…-only root support (7s / no limit) [** ] A start job is running for Configur…-only root support (8s / no limit) [ OK ] Started Configure read-only root support. Starting Load/Save Random Seed... [ OK ] Reached target Local File Systems. Starting Mark the need to relabel after reboot... Starting Rebuild Dynamic Linker Cache... Starting Create Volatile Files and Directories... [ OK ] Started Load/Save Random Seed. [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Create Volatile Files and Directories. Starting Update UTMP about System Boot/Shutdown... Starting RPC Bind... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting Login Service... [ OK ] Started irqbalance daemon. [ OK ] Started dnf makecache --timer. [ OK ] Reached target Timers. [ OK ] Reached target sshd-keygen.target. Starting Restore /run/initramfs on shutdown... [ 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. Starting Network Manager Wait Online... [ OK ] Reached target Network. Starting Dynamic System Tuning Daemon... Starting GSSAPI Proxy Daemon... Starting OpenSSH server daemon... Starting Hostname Service... [ OK ] Started GSSAPI Proxy Daemon. [ OK ] 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 Crash recovery kernel arming... Starting Notify NFS peers of a restart... 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 oleg413-client login: [ 93.297036] hrtimer: interrupt took 3027042 ns [ 105.312949] libcfs: loading out-of-tree module taints kernel. [ 105.424750] Key type ._llcrypt registered [ 105.438812] Key type .llcrypt registered [ 106.560388] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [ 106.571649] alg: No test for adler32 (adler32-zlib) [ 108.297735] Lustre: Lustre: Build Version: 2.17.57_80_g9b8a413 [ 109.194638] LNet: Added LNI 192.168.204.13@tcp [8/256/0/180] [ 110.999260] Key type lgssc registered [ 114.080216] Lustre: Echo OBD driver; http://www.lustre.org/ [ 307.442041] Lustre: Mounted lustre-client - version 2.17.57_80_g9b8a413 [ 312.579468] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 328.168428] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing check_logdir /tmp/testlogs/ [ 333.281943] Lustre: lustre-OST0000-osc-ffff9037e0c2b800: disconnect after 24s idle [ 333.481324] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing yml_node [ 338.708982] Lustre: DEBUG MARKER: Client: 2.17.57.80 [ 341.627068] Lustre: DEBUG MARKER: MDS: 2.17.57.80 [ 344.274478] Lustre: DEBUG MARKER: OSS: 2.17.57.80 [ 346.010781] Lustre: DEBUG MARKER: -----============= acceptance-small: replay-single ============----- Mon Aug 24 07:57:00 EDT 2026 [ 365.050713] Lustre: DEBUG MARKER: excepting tests: 59 36 [ 367.893582] Lustre: DEBUG MARKER: === replay-single: start setup 07:57:22 (1787572642) === [ 373.416395] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing check_config_client /mnt/lustre [ 395.228278] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 408.826985] Lustre: DEBUG MARKER: === replay-single: finish setup 07:58:03 (1787572683) === [ 410.831171] Lustre: DEBUG MARKER: == replay-single test 0a: empty replay =================== 07:58:05 (1787572685) [ 419.263562] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 425.447158] Lustre: lustre-MDT0000-mdc-ffff9037e0c2b800: Connection to lustre-MDT0000 (at 192.168.204.113@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 435.680397] Lustre: lustre-OST0000-osc-ffff9037e0c2b800: disconnect after 23s idle [ 435.688716] Lustre: Skipped 1 previous similar message [ 441.823466] Lustre: 2402:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787572701/real 1787572701] req@ffff9037d85cb480 x1874405501193344/t0(0) o400->MGC192.168.204.113@tcp@192.168.204.113@tcp:26/25 lens 224/224 e 0 to 1 dl 1787572717 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 441.856689] LustreError: MGC192.168.204.113@tcp: Connection to MGS (at 192.168.204.113@tcp) was lost; in progress operations using this service will fail [ 451.050276] Lustre: Evicted from MGS (at 192.168.204.113@tcp) after server handle changed from 0x3e15f5fb7c461e47 to 0x3e15f5fb7c462206 [ 451.068625] Lustre: MGC192.168.204.113@tcp: Connection restored to 192.168.204.113@tcp (at 192.168.204.113@tcp) [ 455.276429] Lustre: lustre-MDT0000-mdc-ffff9037e0c2b800: Connection restored to 192.168.204.113@tcp (at 192.168.204.113@tcp) [ 465.113954] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 466.898934] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 477.276259] Lustre: DEBUG MARKER: == replay-single test 0b: ensure object created after recover exists. (3284) ========================================================== 07:59:11 (1787572751) [ 481.770397] Lustre: lustre-OST0000-osc-ffff9037e0c2b800: Connection to lustre-OST0000 (at 192.168.204.113@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 491.999481] Lustre: lustre-OST0001-osc-ffff9037e0c2b800: disconnect after 23s idle [ 492.007563] Lustre: Skipped 1 previous similar message [ 504.392613] Lustre: lustre-OST0000-osc-ffff9037e0c2b800: Connection restored to 192.168.204.113@tcp (at 192.168.204.113@tcp) [ 520.584472] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 522.748939] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 535.092629] Lustre: DEBUG MARKER: == replay-single test 0c: check replay-barrier =========== 08:00:08 (1787572808) [ 544.497841] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 544.688579] Lustre: Unmounted lustre-client [ 584.544251] LustreError: lustre-MDT0000-mdc-ffff9037e020f000: operation mds_connect to node 192.168.204.113@tcp failed: rc = -16 [ 589.829185] LustreError: lustre-MDT0000-mdc-ffff9037e020f000: operation mds_connect to node 192.168.204.113@tcp failed: rc = -16 [ 594.982558] LustreError: lustre-MDT0000-mdc-ffff9037e020f000: operation mds_connect to node 192.168.204.113@tcp failed: rc = -16 [ 600.077414] LustreError: lustre-MDT0000-mdc-ffff9037e020f000: operation mds_connect to node 192.168.204.113@tcp failed: rc = -16 [ 605.181618] LustreError: lustre-MDT0000-mdc-ffff9037e020f000: operation mds_connect to node 192.168.204.113@tcp failed: rc = -16 [ 615.432985] LustreError: lustre-MDT0000-mdc-ffff9037e020f000: operation mds_connect to node 192.168.204.113@tcp failed: rc = -16 [ 615.449458] LustreError: Skipped 1 previous similar message [ 635.911857] LustreError: lustre-MDT0000-mdc-ffff9037e020f000: operation mds_connect to node 192.168.204.113@tcp failed: rc = -16 [ 635.920609] LustreError: Skipped 3 previous similar messages [ 656.438823] Lustre: Mounted lustre-client - version 2.17.57_80_g9b8a413 [ 665.376579] Lustre: DEBUG MARKER: == replay-single test 0d: expired recovery with no clients ========================================================== 08:02:20 (1787572940) [ 673.884983] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 674.049805] Lustre: Unmounted lustre-client [ 712.068320] LustreError: lustre-MDT0000-mdc-ffff9037c4c9c000: operation mds_connect to node 192.168.204.113@tcp failed: rc = -16 [ 712.082896] LustreError: Skipped 3 previous similar messages [ 778.755791] LustreError: lustre-MDT0000-mdc-ffff9037c4c9c000: operation mds_connect to node 192.168.204.113@tcp failed: rc = -16 [ 778.771940] LustreError: Skipped 12 previous similar messages [ 783.952713] Lustre: Mounted lustre-client - version 2.17.57_80_g9b8a413 [ 794.017624] Lustre: DEBUG MARKER: == replay-single test 1: simple create =================== 08:04:28 (1787573068) [ 802.914517] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 809.449492] Lustre: lustre-MDT0000-mdc-ffff9037c4c9c000: Connection to lustre-MDT0000 (at 192.168.204.113@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 825.631204] Lustre: 2400:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787573085/real 1787573085] req@ffff9037c5477100 x1874405501264512/t0(0) o400->MGC192.168.204.113@tcp@192.168.204.113@tcp:26/25 lens 224/224 e 0 to 1 dl 1787573101 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 825.671286] LustreError: MGC192.168.204.113@tcp: Connection to MGS (at 192.168.204.113@tcp) was lost; in progress operations using this service will fail [ 835.067038] Lustre: Evicted from MGS (at 192.168.204.113@tcp) after server handle changed from 0x3e15f5fb7c46323d to 0x3e15f5fb7c4636b9 [ 835.079105] Lustre: MGC192.168.204.113@tcp: Connection restored to 192.168.204.113@tcp (at 192.168.204.113@tcp) [ 848.020487] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 849.531236] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 858.288447] Lustre: DEBUG MARKER: == replay-single test 2a: touch ========================== 08:05:32 (1787573132) [ 866.601234] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 870.912186] Lustre: lustre-MDT0000-mdc-ffff9037c4c9c000: Connection to lustre-MDT0000 (at 192.168.204.113@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 886.239522] Lustre: 2402:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787573146/real 1787573146] req@ffff9037c4cafb80 x1874405501277312/t0(0) o400->MGC192.168.204.113@tcp@192.168.204.113@tcp:26/25 lens 224/224 e 0 to 1 dl 1787573162 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 886.313259] LustreError: MGC192.168.204.113@tcp: Connection to MGS (at 192.168.204.113@tcp) was lost; in progress operations using this service will fail [ 896.495197] Lustre: Evicted from MGS (at 192.168.204.113@tcp) after server handle changed from 0x3e15f5fb7c4636b9 to 0x3e15f5fb7c4639fa [ 896.506224] Lustre: MGC192.168.204.113@tcp: Connection restored to 192.168.204.113@tcp (at 192.168.204.113@tcp) [ 896.513073] Lustre: Skipped 1 previous similar message [ 897.643411] Lustre: 15217:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.204.113@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 906.907168] LustreError: 2399:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9037d85c8a80 x1874405501276416/t21474836484(21474836484) o101->lustre-MDT0000-mdc-ffff9037c4c9c000@192.168.204.113@tcp:12/10 lens 592/608 e 0 to 0 dl 1787573199 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'touch.0' uid:0 gid:0 projid:0 [ 907.063792] Lustre: lustre-MDT0000-mdc-ffff9037c4c9c000: Connection restored to 192.168.204.113@tcp (at 192.168.204.113@tcp) [ 916.944331] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 918.775913] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 927.291312] Lustre: DEBUG MARKER: == replay-single test 2b: touch ========================== 08:06:42 (1787573202) [ 935.248202] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 937.454411] Lustre: lustre-MDT0000-mdc-ffff9037c4c9c000: Connection to lustre-MDT0000 (at 192.168.204.113@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 957.920486] Lustre: 2402:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787573218/real 1787573218] req@ffff9037c4cad180 x1874405501291392/t0(0) o400->MGC192.168.204.113@tcp@192.168.204.113@tcp:26/25 lens 224/224 e 0 to 1 dl 1787573234 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 957.976912] LustreError: MGC192.168.204.113@tcp: Connection to MGS (at 192.168.204.113@tcp) was lost; in progress operations using this service will fail [ 968.163930] Lustre: Evicted from MGS (at 192.168.204.113@tcp) after server handle changed from 0x3e15f5fb7c4639fa to 0x3e15f5fb7c463f5d [ 968.188036] Lustre: MGC192.168.204.113@tcp: Connection restored to 192.168.204.113@tcp (at 192.168.204.113@tcp) [ 974.456488] LustreError: 2399:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9037c5476300 x1874405501289728/t25769803781(25769803781) o101->lustre-MDT0000-mdc-ffff9037c4c9c000@192.168.204.113@tcp:12/10 lens 592/608 e 0 to 0 dl 1787573266 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'touch.0' uid:0 gid:0 projid:0 [ 984.151141] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 986.010545] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 995.163650] Lustre: DEBUG MARKER: == replay-single test 2c: setstripe replay =============== 08:07:49 (1787573269) [ 1002.660204] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1006.072323] Lustre: lustre-MDT0000-mdc-ffff9037c4c9c000: Connection to lustre-MDT0000 (at 192.168.204.113@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1027.359204] Lustre: 2401:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787573287/real 1787573287] req@ffff9037c5476300 x1874405501305600/t0(0) o400->MGC192.168.204.113@tcp@192.168.204.113@tcp:26/25 lens 224/224 e 0 to 1 dl 1787573303 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1027.396435] LustreError: MGC192.168.204.113@tcp: Connection to MGS (at 192.168.204.113@tcp) was lost; in progress operations using this service will fail [ 1037.807780] Lustre: Evicted from MGS (at 192.168.204.113@tcp) after server handle changed from 0x3e15f5fb7c463f5d to 0x3e15f5fb7c464687 [ 1037.827282] Lustre: MGC192.168.204.113@tcp: Connection restored to 192.168.204.113@tcp (at 192.168.204.113@tcp) [ 1037.848589] Lustre: Skipped 1 previous similar message [ 1041.559847] LustreError: 2399:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9037d85cb100 x1874405501303680/t30064771076(30064771076) o101->lustre-MDT0000-mdc-ffff9037c4c9c000@192.168.204.113@tcp:12/10 lens 536/608 e 0 to 0 dl 1787573333 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'lfs.0' uid:0 gid:0 projid:0 [ 1052.001970] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1053.459266] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1062.763426] Lustre: DEBUG MARKER: == replay-single test 2d: setdirstripe replay ============ 08:08:57 (1787573337) [ 1070.817377] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1073.647377] Lustre: lustre-MDT0000-mdc-ffff9037c4c9c000: Connection to lustre-MDT0000 (at 192.168.204.113@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1088.992852] Lustre: 2403:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787573349/real 1787573349] req@ffff9037d85c9880 x1874405501317248/t0(0) o400->MGC192.168.204.113@tcp@192.168.204.113@tcp:26/25 lens 224/224 e 0 to 1 dl 1787573365 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1089.063217] LustreError: MGC192.168.204.113@tcp: Connection to MGS (at 192.168.204.113@tcp) was lost; in progress operations using this service will fail [ 1099.250552] Lustre: Evicted from MGS (at 192.168.204.113@tcp) after server handle changed from 0x3e15f5fb7c464687 to 0x3e15f5fb7c4649c8 [ 1100.847419] Lustre: 15217:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.204.113@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 1108.632080] Lustre: lustre-MDT0000-mdc-ffff9037c4c9c000: Connection restored to 192.168.204.113@tcp (at 192.168.204.113@tcp) [ 1108.644775] Lustre: Skipped 2 previous similar messages [ 1120.833827] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1122.762314] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1132.575874] Lustre: DEBUG MARKER: == replay-single test 2e: O_CREAT|O_EXCL create replay === 08:10:07 (1787573407) [ 1143.445378] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1150.432446] Lustre: 23307:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787573410/real 1787573410] req@ffff9037c565d880 x1874405501328512/t0(0) o35->lustre-MDT0000-mdc-ffff9037c4c9c000@192.168.204.113@tcp:23/10 lens 392/624 e 0 to 1 dl 1787573426 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'openfile.0' uid:0 gid:0 projid:0 [ 1150.457052] Lustre: lustre-MDT0000-mdc-ffff9037c4c9c000: Connection to lustre-MDT0000 (at 192.168.204.113@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1166.751328] LustreError: MGC192.168.204.113@tcp: Connection to MGS (at 192.168.204.113@tcp) was lost; in progress operations using this service will fail [ 1176.043416] Lustre: Evicted from MGS (at 192.168.204.113@tcp) after server handle changed from 0x3e15f5fb7c4649c8 to 0x3e15f5fb7c464fda [ 1188.566971] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1190.603062] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1200.425624] Lustre: DEBUG MARKER: == replay-single test 3a: replay failed open(O_DIRECTORY) ========================================================== 08:11:15 (1787573475) [ 1208.799822] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1227.237292] Lustre: 2403:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787573487/real 1787573487] req@ffff9037d85cbb80 x1874405501345152/t0(0) o400->MGC192.168.204.113@tcp@192.168.204.113@tcp:26/25 lens 224/224 e 0 to 1 dl 1787573503 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1227.284829] Lustre: 2403:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 1227.295923] LustreError: MGC192.168.204.113@tcp: Connection to MGS (at 192.168.204.113@tcp) was lost; in progress operations using this service will fail [ 1237.485265] Lustre: Evicted from MGS (at 192.168.204.113@tcp) after server handle changed from 0x3e15f5fb7c464fda to 0x3e15f5fb7c465399 [ 1237.512081] Lustre: MGC192.168.204.113@tcp: Connection restored to 192.168.204.113@tcp (at 192.168.204.113@tcp) [ 1237.525137] Lustre: Skipped 2 previous similar messages [ 1238.786909] Lustre: 15217:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.204.113@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 1258.353419] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1260.767251] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1272.810587] Lustre: DEBUG MARKER: == replay-single test 3b: replay failed open -ENOMEM ===== 08:12:26 (1787573546) [ 1281.585953] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1290.722654] Lustre: lustre-MDT0000-mdc-ffff9037c4c9c000: Connection to lustre-MDT0000 (at 192.168.204.113@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1290.742790] Lustre: Skipped 1 previous similar message [ 1306.079214] Lustre: 2402:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787573566/real 1787573566] req@ffff9037d85ca680 x1874405501360896/t0(0) o400->MGC192.168.204.113@tcp@192.168.204.113@tcp:26/25 lens 224/224 e 0 to 1 dl 1787573582 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1306.106151] LustreError: MGC192.168.204.113@tcp: Connection to MGS (at 192.168.204.113@tcp) was lost; in progress operations using this service will fail [ 1316.332182] Lustre: Evicted from MGS (at 192.168.204.113@tcp) after server handle changed from 0x3e15f5fb7c465399 to 0x3e15f5fb7c4658af [ 1334.545827] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1336.282310] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1345.661393] Lustre: DEBUG MARKER: == replay-single test 3c: replay failed open -ENOMEM ===== 08:13:40 (1787573620) [ 1352.660307] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1396.530957] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1398.085870] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1407.165872] Lustre: DEBUG MARKER: == replay-single test 4a: |x| 10 open(O_CREAT)s ========== 08:14:41 (1787573681) [ 1415.327957] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1420.805129] Lustre: lustre-MDT0000-mdc-ffff9037c4c9c000: Connection to lustre-MDT0000 (at 192.168.204.113@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1420.828703] Lustre: Skipped 1 previous similar message [ 1436.133111] Lustre: 2401:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787573696/real 1787573696] req@ffff9037c5476d80 x1874405501394176/t0(0) o400->MGC192.168.204.113@tcp@192.168.204.113@tcp:26/25 lens 224/224 e 0 to 1 dl 1787573712 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1436.156993] Lustre: 2401:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 1436.162540] LustreError: MGC192.168.204.113@tcp: Connection to MGS (at 192.168.204.113@tcp) was lost; in progress operations using this service will fail [ 1436.169234] LustreError: Skipped 1 previous similar message [ 1446.405920] Lustre: Evicted from MGS (at 192.168.204.113@tcp) after server handle changed from 0x3e15f5fb7c465d94 to 0x3e15f5fb7c46657b [ 1446.420033] Lustre: Skipped 1 previous similar message [ 1451.705103] LustreError: 2399:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9037d85cad80 x1874405501386496/t55834574851(55834574851) o101->lustre-MDT0000-mdc-ffff9037c4c9c000@192.168.204.113@tcp:12/10 lens 592/608 e 0 to 0 dl 1787573743 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'bash.0' uid:0 gid:0 projid:0 [ 1461.160355] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1462.934510] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1471.634708] Lustre: DEBUG MARKER: == replay-single test 4b: |x| rm 10 files ================ 08:15:46 (1787573746) [ 1478.777208] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1508.354665] Lustre: MGC192.168.204.113@tcp: Connection restored to 192.168.204.113@tcp (at 192.168.204.113@tcp) [ 1508.365175] Lustre: Skipped 7 previous similar messages [ 1523.130353] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1524.766931] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1536.697360] Lustre: DEBUG MARKER: == replay-single test 5: |x| 220 open(O_CREAT) =========== 08:16:50 (1787573810) [ 1548.336627] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1591.921000] LustreError: 2399:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9037c565f480 x1874405501443968/t64424509443(64424509443) o101->lustre-MDT0000-mdc-ffff9037c4c9c000@192.168.204.113@tcp:12/10 lens 592/608 e 0 to 0 dl 1787573884 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'bash.0' uid:0 gid:0 projid:0 [ 1591.946126] LustreError: 2399:0:(client.c:3448:ptlrpc_replay_interpret()) Skipped 9 previous similar messages [ 1602.299191] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1604.197907] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1629.819805] Lustre: DEBUG MARKER: == replay-single test 6a: mkdir + contained create ======= 08:18:23 (1787573903) [ 1637.749710] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1682.832671] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1684.561363] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1694.136380] Lustre: DEBUG MARKER: == replay-single test 6b: |X| rmdir ====================== 08:19:29 (1787573969) [ 1702.010309] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1704.933843] Lustre: lustre-MDT0000-mdc-ffff9037c4c9c000: Connection to lustre-MDT0000 (at 192.168.204.113@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1704.947256] Lustre: Skipped 3 previous similar messages [ 1721.311587] Lustre: 2401:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787573981/real 1787573981] req@ffff9037c7bbdc00 x1874405501934208/t0(0) o400->MGC192.168.204.113@tcp@192.168.204.113@tcp:26/25 lens 224/224 e 0 to 1 dl 1787573997 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1721.374923] Lustre: 2401:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 1721.396236] LustreError: MGC192.168.204.113@tcp: Connection to MGS (at 192.168.204.113@tcp) was lost; in progress operations using this service will fail [ 1721.414275] LustreError: Skipped 3 previous similar messages [ 1731.568537] Lustre: Evicted from MGS (at 192.168.204.113@tcp) after server handle changed from 0x3e15f5fb7c470bad to 0x3e15f5fb7c470fdc [ 1731.577097] Lustre: Skipped 3 previous similar messages [ 1732.648131] Lustre: 15217:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.204.113@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 1761.809541] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1763.605364] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1772.592504] Lustre: DEBUG MARKER: == replay-single test 7: mkdir |X| contained create ====== 08:20:47 (1787574047) [ 1780.746535] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1810.030464] Lustre: 15217:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.204.113@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 1831.569700] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1833.398980] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1843.228858] Lustre: DEBUG MARKER: == replay-single test 8: creat open |X| close ============ 08:21:57 (1787574117) [ 1851.827903] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1887.883968] LustreError: 2399:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9037d0d89f80 x1874405501966080/t81604378634(81604378634) o101->lustre-MDT0000-mdc-ffff9037c4c9c000@192.168.204.113@tcp:12/10 lens 664/608 e 0 to 0 dl 1787574179 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'multiop.0' uid:0 gid:0 projid:0 [ 1887.930113] LustreError: 2399:0:(client.c:3448:ptlrpc_replay_interpret()) Skipped 219 previous similar messages [ 1899.514373] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1901.038290] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1910.120501] Lustre: DEBUG MARKER: == replay-single test 9: |X| create (same inum/gen) ====== 08:23:04 (1787574184) [ 1918.710817] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1971.103417] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1972.991825] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1984.695696] Lustre: DEBUG MARKER: == replay-single test 10: create |X| rename unlink ======= 08:24:18 (1787574258) [ 1992.829961] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2022.379895] Lustre: MGC192.168.204.113@tcp: Connection restored to 192.168.204.113@tcp (at 192.168.204.113@tcp) [ 2022.390964] Lustre: Skipped 13 previous similar messages [ 2038.067781] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2039.523056] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2047.984469] Lustre: DEBUG MARKER: == replay-single test 11: create open write rename |X| create-old-name read ========================================================== 08:25:22 (1787574322) [ 2057.529589] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2096.273655] LustreError: 2399:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9037c7bbea00 x1874405502011264/t94489280522(94489280522) o101->lustre-MDT0000-mdc-ffff9037c4c9c000@192.168.204.113@tcp:12/10 lens 592/608 e 0 to 0 dl 1787574388 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'bash.0' uid:0 gid:0 projid:0 [ 2107.068778] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2109.237968] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2120.342150] Lustre: DEBUG MARKER: == replay-single test 12: open, unlink |X| close ========= 08:26:34 (1787574394) [ 2128.874194] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2158.105293] LustreError: 2399:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9037d0d88700 x1874405502012032/t94489280524(94489280524) o101->lustre-MDT0000-mdc-ffff9037c4c9c000@192.168.204.113@tcp:12/10 lens 576/608 e 0 to 0 dl 1787574450 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'grep.0' uid:0 gid:0 projid:0 [ 2158.156954] LustreError: 2399:0:(client.c:3448:ptlrpc_replay_interpret()) Skipped 1 previous similar message [ 2171.979323] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2174.205374] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2183.817466] Lustre: DEBUG MARKER: == replay-single test 13: open chmod 0 |x| write close === 08:27:37 (1787574457) [ 2190.588278] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2235.393909] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2236.929830] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2246.697666] Lustre: DEBUG MARKER: == replay-single test 14: open(O_CREAT), unlink |X| close ========================================================== 08:28:41 (1787574521) [ 2253.933508] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2257.387547] Lustre: lustre-MDT0000-mdc-ffff9037c4c9c000: Connection to lustre-MDT0000 (at 192.168.204.113@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 2257.414966] Lustre: Skipped 7 previous similar messages [ 2273.759284] Lustre: 2401:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787574533/real 1787574533] req@ffff9037c7bbf100 x1874405502058496/t0(0) o400->MGC192.168.204.113@tcp@192.168.204.113@tcp:26/25 lens 224/224 e 0 to 1 dl 1787574549 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2273.810607] Lustre: 2401:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 7 previous similar messages [ 2273.833492] LustreError: MGC192.168.204.113@tcp: Connection to MGS (at 192.168.204.113@tcp) was lost; in progress operations using this service will fail [ 2273.848175] LustreError: Skipped 7 previous similar messages [ 2282.994611] Lustre: Evicted from MGS (at 192.168.204.113@tcp) after server handle changed from 0x3e15f5fb7c473632 to 0x3e15f5fb7c473bbf [ 2283.015652] Lustre: Skipped 7 previous similar messages [ 2284.919531] Lustre: 15217:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.204.113@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 2288.149988] LustreError: 2399:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9037d0d88700 x1874405502012032/t94489280524(94489280524) o101->lustre-MDT0000-mdc-ffff9037c4c9c000@192.168.204.113@tcp:12/10 lens 576/608 e 0 to 0 dl 1787574580 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'grep.0' uid:0 gid:0 projid:0 [ 2288.170786] LustreError: 2399:0:(client.c:3448:ptlrpc_replay_interpret()) Skipped 3 previous similar messages [ 2306.842403] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2308.981836] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2318.723255] Lustre: DEBUG MARKER: == replay-single test 15: open(O_CREAT), unlink |X| touch new, close ========================================================== 08:29:53 (1787574593) [ 2328.739268] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2376.122122] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2378.318659] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2388.820816] Lustre: DEBUG MARKER: == replay-single test 16: |X| open(O_CREAT), unlink, touch new, unlink new ========================================================== 08:31:03 (1787574663) [ 2397.689704] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2428.682943] LustreError: 2399:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9037d0d88700 x1874405502012032/t94489280524(94489280524) o101->lustre-MDT0000-mdc-ffff9037c4c9c000@192.168.204.113@tcp:12/10 lens 576/608 e 0 to 0 dl 1787574720 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'grep.0' uid:0 gid:0 projid:0 [ 2428.702617] LustreError: 2399:0:(client.c:3448:ptlrpc_replay_interpret()) Skipped 4 previous similar messages [ 2442.955297] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2444.343331] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2452.933369] Lustre: DEBUG MARKER: == replay-single test 17: |X| open(O_CREAT), |replay| close ========================================================== 08:32:07 (1787574727) [ 2460.465419] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2503.770963] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2505.120443] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2514.177538] Lustre: DEBUG MARKER: == replay-single test 18: open(O_CREAT), unlink, touch new, close, touch, unlink ========================================================== 08:33:08 (1787574788) [ 2521.857425] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2568.012349] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2569.809219] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2579.845384] Lustre: DEBUG MARKER: == replay-single test 19: mcreate, open, write, rename === 08:34:14 (1787574854) [ 2589.330942] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2625.126276] Lustre: lustre-MDT0000-mdc-ffff9037c4c9c000: Connection restored to 192.168.204.113@tcp (at 192.168.204.113@tcp) [ 2625.151092] Lustre: Skipped 18 previous similar messages [ 2634.144217] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2635.859215] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2645.748843] Lustre: DEBUG MARKER: == replay-single test 20a: |X| open(O_CREAT), unlink, replay, close (test mds_cleanup_orphans) ========================================================== 08:35:19 (1787574919) [ 2654.028258] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2685.356264] Lustre: 15217:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.204.113@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 2693.242158] LustreError: 2399:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9037d0d8aa00 x1874405502152192/t133143986181(133143986181) o101->lustre-MDT0000-mdc-ffff9037c4c9c000@192.168.204.113@tcp:12/10 lens 592/608 e 0 to 0 dl 1787574985 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'multiop.0' uid:0 gid:0 projid:0 [ 2693.267782] LustreError: 2399:0:(client.c:3448:ptlrpc_replay_interpret()) Skipped 7 previous similar messages [ 2702.669823] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2704.078432] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2712.840101] Lustre: DEBUG MARKER: == replay-single test 20b: write, unlink, eviction, replay (test mds_cleanup_orphans) ========================================================== 08:36:27 (1787574987) [ 2719.426873] LustreError: lustre-MDT0000-mdc-ffff9037c4c9c000: operation mds_statfs to node 192.168.204.113@tcp failed: rc = -107 [ 2719.445242] LustreError: lustre-MDT0000-mdc-ffff9037c4c9c000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 2719.462477] LustreError: 57931:0:(vvp_io.c:1889:vvp_io_init()) lustre: refresh file layout [0x200001b71:0x132:0x0] error -108. [ 2758.599469] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2761.131917] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2779.144217] Lustre: DEBUG MARKER: before 3156, after 3156 [ 2787.799821] Lustre: DEBUG MARKER: == replay-single test 20c: check that client eviction does not affect file content ========================================================== 08:37:42 (1787575062) [ 2791.400459] LustreError: lustre-MDT0000-mdc-ffff9037c4c9c000: operation mds_statfs to node 192.168.204.113@tcp failed: rc = -107 [ 2791.434523] LustreError: lustre-MDT0000-mdc-ffff9037c4c9c000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 2799.273229] Lustre: DEBUG MARKER: == replay-single test 21: |X| open(O_CREAT), unlink touch new, replay, close (test mds_cleanup_orphans) ========================================================== 08:37:54 (1787575074) [ 2806.383394] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2848.559061] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2850.408655] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2859.337465] Lustre: DEBUG MARKER: == replay-single test 22: open(O_CREAT), |X| unlink, replay, close (test mds_cleanup_orphans) ========================================================== 08:38:53 (1787575133) [ 2867.001426] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2873.327551] Lustre: lustre-MDT0000-mdc-ffff9037c4c9c000: Connection to lustre-MDT0000 (at 192.168.204.113@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 2873.347456] Lustre: Skipped 10 previous similar messages [ 2889.696088] Lustre: 2400:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787575149/real 1787575149] req@ffff9037c7bbed80 x1874405502203520/t0(0) o400->MGC192.168.204.113@tcp@192.168.204.113@tcp:26/25 lens 224/224 e 0 to 1 dl 1787575165 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2889.756693] Lustre: 2400:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 8 previous similar messages [ 2889.779861] LustreError: MGC192.168.204.113@tcp: Connection to MGS (at 192.168.204.113@tcp) was lost; in progress operations using this service will fail [ 2889.799601] LustreError: Skipped 8 previous similar messages [ 2898.922277] Lustre: Evicted from MGS (at 192.168.204.113@tcp) after server handle changed from 0x3e15f5fb7c4769ee to 0x3e15f5fb7c476f90 [ 2898.947553] Lustre: Skipped 8 previous similar messages [ 2911.967675] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2913.569225] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2922.227678] Lustre: DEBUG MARKER: == replay-single test 23: open(O_CREAT), |X| unlink touch new, replay, close (test mds_cleanup_orphans) ========================================================== 08:39:57 (1787575197) [ 2931.049156] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2962.117988] Lustre: 15217:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.204.113@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 2976.897661] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2978.293173] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2986.352924] Lustre: DEBUG MARKER: == replay-single test 24: open(O_CREAT), replay, unlink, close (test mds_cleanup_orphans) ========================================================== 08:41:01 (1787575261) [ 2996.515400] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3028.024513] Lustre: 15217:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.204.113@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 3044.842418] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3046.788490] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3057.118919] Lustre: DEBUG MARKER: == replay-single test 25: open(O_CREAT), unlink, replay, close (test mds_cleanup_orphans) ========================================================== 08:42:11 (1787575331) [ 3066.423167] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3113.334298] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3114.868939] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3123.281897] Lustre: DEBUG MARKER: == replay-single test 26: |X| open(O_CREAT), unlink two, close one, replay, close one (test mds_cleanup_orphans) ========================================================== 08:43:18 (1787575398) [ 3130.496491] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3161.444432] Lustre: 15217:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.204.113@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 3181.765214] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3184.928903] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3195.172264] Lustre: DEBUG MARKER: == replay-single test 27: |X| open(O_CREAT), unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 08:44:29 (1787575469) [ 3204.131623] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3235.837480] Lustre: MGC192.168.204.113@tcp: Connection restored to 192.168.204.113@tcp (at 192.168.204.113@tcp) [ 3235.844838] Lustre: Skipped 18 previous similar messages [ 3241.566352] LustreError: 2399:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9037c7b3ea00 x1874405502282880/t167503724549(167503724549) o101->lustre-MDT0000-mdc-ffff9037c4c9c000@192.168.204.113@tcp:12/10 lens 592/608 e 0 to 0 dl 1787575533 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'multiop.0' uid:0 gid:0 projid:0 [ 3241.611043] LustreError: 2399:0:(client.c:3448:ptlrpc_replay_interpret()) Skipped 9 previous similar messages [ 3249.708319] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3251.437844] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3260.841877] Lustre: DEBUG MARKER: == replay-single test 28: open(O_CREAT), |X| unlink two, close one, replay, close one (test mds_cleanup_orphans) ========================================================== 08:45:35 (1787575535) [ 3269.844475] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3321.187706] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3322.882426] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3333.393332] Lustre: DEBUG MARKER: == replay-single test 29: open(O_CREAT), |X| unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 08:46:47 (1787575607) [ 3342.413646] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3392.342584] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3394.247863] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3404.495557] Lustre: DEBUG MARKER: == replay-single test 30: open(O_CREAT) two, unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 08:47:58 (1787575678) [ 3413.354848] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3458.720966] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3460.371836] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3468.986729] Lustre: DEBUG MARKER: == replay-single test 31: open(O_CREAT) two, unlink one, |X| unlink one, close two (test mds_cleanup_orphans) ========================================================== 08:49:03 (1787575743) [ 3477.980795] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3480.554251] Lustre: lustre-MDT0000-mdc-ffff9037c4c9c000: Connection to lustre-MDT0000 (at 192.168.204.113@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 3480.571872] Lustre: Skipped 8 previous similar messages [ 3495.905549] Lustre: 2403:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787575756/real 1787575756] req@ffff9037d85cad80 x1874405502352512/t0(0) o400->MGC192.168.204.113@tcp@192.168.204.113@tcp:26/25 lens 224/224 e 0 to 1 dl 1787575772 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3495.960803] Lustre: 2403:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 8 previous similar messages [ 3495.975407] LustreError: MGC192.168.204.113@tcp: Connection to MGS (at 192.168.204.113@tcp) was lost; in progress operations using this service will fail [ 3495.986775] LustreError: Skipped 8 previous similar messages [ 3521.710304] Lustre: Evicted from MGS (at 192.168.204.113@tcp) after server handle changed from 0x3e15f5fb7c479d64 to 0x3e15f5fb7c47a61d [ 3521.728661] Lustre: Skipped 8 previous similar messages [ 3531.126676] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3533.243938] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3542.952516] Lustre: DEBUG MARKER: == replay-single test 32: close() notices client eviction; close() after client eviction ========================================================== 08:50:17 (1787575817) [ 3546.288703] LustreError: lustre-MDT0000-mdc-ffff9037c4c9c000: operation mds_statfs to node 192.168.204.113@tcp failed: rc = -107 [ 3546.310268] LustreError: lustre-MDT0000-mdc-ffff9037c4c9c000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 3555.378838] Lustre: DEBUG MARKER: == replay-single test 33a: fid seq shouldn't be reused after abort recovery ========================================================== 08:50:30 (1787575830) [ 3562.179956] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3583.492631] LustreError: lustre-MDT0000-mdc-ffff9037c4c9c000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 3608.785092] Lustre: DEBUG MARKER: == replay-single test 33b: test fid seq allocation ======= 08:51:23 (1787575883) [ 3620.066721] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3639.793373] LustreError: lustre-MDT0000-mdc-ffff9037c4c9c000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 3662.357803] Lustre: DEBUG MARKER: == replay-single test 34: abort recovery before client does replay (test mds_cleanup_orphans) ========================================================== 08:52:17 (1787575937) [ 3669.868162] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3685.878501] LustreError: lustre-MDT0000-mdc-ffff9037c4c9c000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 3711.284139] Lustre: DEBUG MARKER: == replay-single test 35: test recovery from llog for unlink op ========================================================== 08:53:05 (1787575985) [ 3731.945959] LustreError: lustre-MDT0000-mdc-ffff9037c4c9c000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 3757.447729] Lustre: DEBUG MARKER: SKIP: replay-single test_36 skipping ALWAYS excluded test 36 [ 3759.588511] Lustre: DEBUG MARKER: == replay-single test 37: abort recovery before client does replay (test mds_cleanup_orphans for directories) ========================================================== 08:53:53 (1787576033) [ 3768.719704] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3788.275524] LustreError: lustre-MDT0000-mdc-ffff9037c4c9c000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 3817.392606] Lustre: DEBUG MARKER: == replay-single test 38: test recovery from unlink llog (test llog_gen_rec) ========================================================== 08:54:51 (1787576091) [ 3857.960464] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3891.697494] Lustre: MGC192.168.204.113@tcp: Connection restored to 192.168.204.113@tcp (at 192.168.204.113@tcp) [ 3891.709968] Lustre: Skipped 20 previous similar messages [ 3908.162851] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3910.000201] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3932.312700] Lustre: DEBUG MARKER: == replay-single test 39: test recovery from unlink llog (test llog_gen_rec) ========================================================== 08:56:46 (1787576206) [ 3958.704646] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4015.045207] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4016.420901] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4037.423123] Lustre: DEBUG MARKER: == replay-single test 41: read from a valid osc while other oscs are invalid ========================================================== 08:58:32 (1787576312) [ 4047.212301] Lustre: DEBUG MARKER: == replay-single test 42: recovery after ost failure ===== 08:58:41 (1787576321) [ 4072.985068] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-OST0000 [ 4088.327290] Lustre: lustre-OST0000-osc-ffff9037c4c9c000: Connection to lustre-OST0000 (at 192.168.204.113@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 4088.344253] Lustre: Skipped 8 previous similar messages [ 4179.496573] Lustre: DEBUG MARKER: == replay-single test 43: mds osc import failure during recovery; don't LBUG ========================================================== 09:00:53 (1787576453) [ 4188.913222] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4211.167444] Lustre: 2402:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787576471/real 1787576471] req@ffff9037c9461f80 x1874405505088896/t0(0) o400->MGC192.168.204.113@tcp@192.168.204.113@tcp:26/25 lens 224/224 e 0 to 1 dl 1787576487 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4211.205963] Lustre: 2402:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 4211.219747] LustreError: MGC192.168.204.113@tcp: Connection to MGS (at 192.168.204.113@tcp) was lost; in progress operations using this service will fail [ 4211.235268] LustreError: Skipped 7 previous similar messages [ 4221.424507] Lustre: Evicted from MGS (at 192.168.204.113@tcp) after server handle changed from 0x3e15f5fb7c4a1395 to 0x3e15f5fb7c4bed96 [ 4221.434368] Lustre: Skipped 7 previous similar messages [ 4238.230417] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4239.925691] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4260.217995] Lustre: DEBUG MARKER: == replay-single test 44a: race in target handle connect ========================================================== 09:02:14 (1787576534) [ 4347.451484] Lustre: DEBUG MARKER: == replay-single test 44b: race in target handle connect ========================================================== 09:03:41 (1787576621) [ 4369.908517] LustreError: 92436:0:(lmv_obd.c:1471:lmv_statfs()) lustre-MDT0000-mdc-ffff9037c4c9c000: can't stat MDS #0: rc = -114 [ 4392.449313] LustreError: 92459:0:(lmv_obd.c:1471:lmv_statfs()) lustre-MDT0000-mdc-ffff9037c4c9c000: can't stat MDS #0: rc = -114 [ 4415.190091] LustreError: 92481:0:(lmv_obd.c:1471:lmv_statfs()) lustre-MDT0000-mdc-ffff9037c4c9c000: can't stat MDS #0: rc = -114 [ 4437.995785] LustreError: 92504:0:(lmv_obd.c:1471:lmv_statfs()) lustre-MDT0000-mdc-ffff9037c4c9c000: can't stat MDS #0: rc = -114 [ 4460.722940] LustreError: 92526:0:(lmv_obd.c:1471:lmv_statfs()) lustre-MDT0000-mdc-ffff9037c4c9c000: can't stat MDS #0: rc = -114 [ 4483.569896] LustreError: 92549:0:(lmv_obd.c:1471:lmv_statfs()) lustre-MDT0000-mdc-ffff9037c4c9c000: can't stat MDS #0: rc = -114 [ 4505.788846] LustreError: 92571:0:(lmv_obd.c:1471:lmv_statfs()) lustre-MDT0000-mdc-ffff9037c4c9c000: can't stat MDS #0: rc = -114 [ 4551.345324] LustreError: 92616:0:(lmv_obd.c:1471:lmv_statfs()) lustre-MDT0000-mdc-ffff9037c4c9c000: can't stat MDS #0: rc = -114 [ 4551.358200] LustreError: 92616:0:(lmv_obd.c:1471:lmv_statfs()) Skipped 1 previous similar message [ 4576.369943] Lustre: lustre-MDT0000-mdc-ffff9037c4c9c000: Connection restored to 192.168.204.113@tcp (at 192.168.204.113@tcp) [ 4576.384874] Lustre: Skipped 15 previous similar messages [ 4582.161104] Lustre: DEBUG MARKER: == replay-single test 44c: race in target handle connect ========================================================== 09:07:36 (1787576856) [ 4589.663324] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4609.557166] LustreError: lustre-MDT0000-mdc-ffff9037c4c9c000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 4675.524143] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4677.080884] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4685.057933] Lustre: DEBUG MARKER: == replay-single test 45: Handle failed close ============ 09:09:19 (1787576959) [ 4685.436418] Lustre: setting import lustre-MDT0000_UUID INACTIVE by administrator request [ 4685.446654] LustreError: 95189:0:(file.c:251:ll_close_inode_openhandle()) lustre-clilmv-ffff9037c4c9c000: inode [0x20001a9e1:0x1:0x0] mdc close failed: rc = -108 [ 4685.469687] LustreError: lustre-MDT0000-mdc-ffff9037c4c9c000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 4692.549394] Lustre: DEBUG MARKER: == replay-single test 46: Don't leak file handle after open resend (3325) ========================================================== 09:09:27 (1787576967) [ 4709.856358] Lustre: lustre-MDT0000-mdc-ffff9037c4c9c000: Connection to lustre-MDT0000 (at 192.168.204.113@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 4709.905779] Lustre: Skipped 16 previous similar messages [ 4737.709175] Lustre: 15217:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.204.113@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 4737.723410] Lustre: 15217:0:(mgc_request.c:1900:mgc_process_log()) Skipped 1 previous similar message [ 4757.517950] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4759.285428] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4769.712587] Lustre: DEBUG MARKER: == replay-single test 47: MDS->OSC failure during precreate cleanup (2824) ========================================================== 09:10:44 (1787577044) [ 4810.321306] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 4811.905907] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4888.815405] Lustre: DEBUG MARKER: == replay-single test 48: MDS->OSC failure during precreate cleanup (2824) ========================================================== 09:12:42 (1787577162) [ 4901.035202] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4920.799227] Lustre: 2401:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787577180/real 1787577180] req@ffff9037c88dfb80 x1874405505277696/t0(0) o400->MGC192.168.204.113@tcp@192.168.204.113@tcp:26/25 lens 224/224 e 0 to 1 dl 1787577196 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4920.826139] Lustre: 2401:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 4920.837120] LustreError: MGC192.168.204.113@tcp: Connection to MGS (at 192.168.204.113@tcp) was lost; in progress operations using this service will fail [ 4920.848475] LustreError: Skipped 3 previous similar messages [ 4930.039735] Lustre: Evicted from MGS (at 192.168.204.113@tcp) after server handle changed from 0x3e15f5fb7c4c0433 to 0x3e15f5fb7c4c177a [ 4930.047959] Lustre: Skipped 3 previous similar messages [ 4936.308122] LustreError: 2399:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9037c951ce00 x1874405505265152/t236223201383(236223201383) o101->lustre-MDT0000-mdc-ffff9037c4c9c000@192.168.204.113@tcp:12/10 lens 592/608 e 0 to 0 dl 1787577268 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'createmany.0' uid:0 gid:0 projid:0 [ 4936.392768] LustreError: 2399:0:(client.c:3448:ptlrpc_replay_interpret()) Skipped 10 previous similar messages [ 5013.039592] Lustre: DEBUG MARKER: == replay-single test 50: Double OSC recovery, don't LASSERT (3812) ========================================================== 09:14:46 (1787577286) [ 5027.410777] Lustre: DEBUG MARKER: == replay-single test 52: time out lock replay (3764) ==== 09:15:02 (1787577302) [ 5128.256318] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5130.195141] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5140.807299] Lustre: DEBUG MARKER: == replay-single test 53a: |X| close request while two MDC requests in flight ========================================================== 09:16:55 (1787577415) [ 5153.078742] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5185.010792] Lustre: MGC192.168.204.113@tcp: Connection restored to 192.168.204.113@tcp (at 192.168.204.113@tcp) [ 5185.025052] Lustre: Skipped 13 previous similar messages [ 5200.562688] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5202.831080] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5211.836201] Lustre: DEBUG MARKER: == replay-single test 53b: |X| open request while two MDC requests in flight ========================================================== 09:18:06 (1787577486) [ 5224.142652] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5270.244361] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5271.740737] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5282.600489] Lustre: DEBUG MARKER: == replay-single test 53c: |X| open request and close request while two MDC requests in flight ========================================================== 09:19:16 (1787577556) [ 5295.067575] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5325.877656] Lustre: 15217:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.204.113@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 5344.765586] Lustre: DEBUG MARKER: == replay-single test 53d: close reply while two MDC requests in flight ========================================================== 09:20:19 (1787577619) [ 5354.992320] Lustre: lustre-MDT0000-mdc-ffff9037c4c9c000: Connection to lustre-MDT0000 (at 192.168.204.113@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 5355.016897] Lustre: Skipped 7 previous similar messages [ 5387.247584] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5389.014841] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5399.339976] Lustre: DEBUG MARKER: == replay-single test 53e: |X| open reply while two MDC requests in flight ========================================================== 09:21:14 (1787577674) [ 5410.180254] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5458.461251] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5460.093393] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5469.276407] Lustre: DEBUG MARKER: == replay-single test 53f: |X| open reply and close reply while two MDC requests in flight ========================================================== 09:22:23 (1787577743) [ 5480.131635] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5525.716943] Lustre: DEBUG MARKER: == replay-single test 53g: |X| drop open reply and close request while close and open are both in flight ========================================================== 09:23:20 (1787577800) [ 5537.399806] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5543.904979] Lustre: 109574:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787577804/real 1787577804] req@ffff9037e0481180 x1874405505444096/t0(0) o35->lustre-MDT0000-mdc-ffff9037c4c9c000@192.168.204.113@tcp:23/10 lens 392/624 e 0 to 1 dl 1787577820 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'multiop.0' uid:0 gid:0 projid:0 [ 5543.958319] Lustre: 109574:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 11 previous similar messages [ 5556.703491] LustreError: MGC192.168.204.113@tcp: Connection to MGS (at 192.168.204.113@tcp) was lost; in progress operations using this service will fail [ 5556.713669] LustreError: Skipped 7 previous similar messages [ 5581.293702] Lustre: Evicted from MGS (at 192.168.204.113@tcp) after server handle changed from 0x3e15f5fb7c4c523d to 0x3e15f5fb7c4c577d [ 5581.304974] Lustre: Skipped 7 previous similar messages [ 5599.788808] Lustre: DEBUG MARKER: == replay-single test 53h: open request and close reply while two MDC requests in flight ========================================================== 09:24:33 (1787577873) [ 5616.589038] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5667.323387] Lustre: DEBUG MARKER: == replay-single test 55: let MDS_CHECK_RESENT return the original return code instead of 0 ========================================================== 09:25:41 (1787577941) [ 5738.598375] Lustre: DEBUG MARKER: == replay-single test 56: don't replay a symlink open request (3440) ========================================================== 09:26:52 (1787578012) [ 5748.909806] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5792.120271] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5794.063596] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5814.497830] Lustre: DEBUG MARKER: == replay-single test 57: test recovery from llog for setattr op ========================================================== 09:28:09 (1787578089) [ 5822.579427] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5852.073871] Lustre: MGC192.168.204.113@tcp: Connection restored to 192.168.204.113@tcp (at 192.168.204.113@tcp) [ 5852.081224] Lustre: Skipped 18 previous similar messages [ 5866.785469] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5869.330798] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5890.978324] Lustre: DEBUG MARKER: == replay-single test 58a: test recovery from llog for setattr op (test llog_gen_rec) ========================================================== 09:29:25 (1787578165) [ 5938.854853] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5972.997854] Lustre: 15217:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.204.113@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 6001.627976] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6003.390875] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6069.090634] Lustre: DEBUG MARKER: == replay-single test 58b: test replay of setxattr op ==== 09:32:23 (1787578343) [ 6070.925737] Lustre: Mounted lustre-client - version 2.17.57_80_g9b8a413 [ 6080.729901] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 6086.631475] Lustre: lustre-MDT0000-mdc-ffff9037c4c9c000: Connection to lustre-MDT0000 (at 192.168.204.113@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 6086.643088] Lustre: Skipped 8 previous similar messages [ 6129.197842] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6131.101828] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6134.828064] Lustre: Unmounted lustre-client [ 6142.091615] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount FULL mgc.*.mgs_server_uuid 1475 0 [ 6143.590347] Lustre: DEBUG MARKER: mgc.*.mgs_server_uuid in FULL state after 0 sec [ 6151.544759] Lustre: DEBUG MARKER: == replay-single test 58c: resend/reconstruct setxattr op ========================================================== 09:33:45 (1787578425) [ 6157.691225] Lustre: Mounted lustre-client - version 2.17.57_80_g9b8a413 [ 6219.743295] Lustre: 119220:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787578435/real 1787578435] req@ffff9037d9e3e680 x1874405508274304/t0(0) o101->lustre-MDT0000-mdc-ffff9037c4c9c000@192.168.204.113@tcp:12/10 lens 592/1152 e 0 to 1 dl 1787578495 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'setfattr.0' uid:0 gid:0 projid:0 [ 6219.814751] Lustre: 119220:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 9 previous similar messages [ 6288.905158] Lustre: Unmounted lustre-client [ 6297.423540] Lustre: DEBUG MARKER: SKIP: replay-single test_59 skipping ALWAYS excluded test 59 [ 6299.142550] Lustre: DEBUG MARKER: == replay-single test 60: test llog post recovery init vs llog unlink ========================================================== 09:36:13 (1787578573) [ 6314.214785] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 6336.480634] LustreError: MGC192.168.204.113@tcp: Connection to MGS (at 192.168.204.113@tcp) was lost; in progress operations using this service will fail [ 6336.517597] LustreError: Skipped 5 previous similar messages [ 6346.736960] Lustre: Evicted from MGS (at 192.168.204.113@tcp) after server handle changed from 0x3e15f5fb7c507726 to 0x3e15f5fb7c50a604 [ 6346.748346] Lustre: Skipped 5 previous similar messages [ 6347.961891] Lustre: 15217:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.204.113@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 6373.884988] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6375.868689] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6386.454427] Lustre: DEBUG MARKER: == replay-single test 61a: test race llog recovery vs llog cleanup ========================================================== 09:37:41 (1787578661) [ 6412.119402] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-OST0000 [ 6517.567100] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 6518.786168] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 6561.181580] Lustre: DEBUG MARKER: == replay-single test 61b: test race mds llog sync vs llog cleanup ========================================================== 09:40:35 (1787578835) [ 6591.466825] Lustre: MGC192.168.204.113@tcp: Connection restored to 192.168.204.113@tcp (at 192.168.204.113@tcp) [ 6591.472742] Lustre: Skipped 10 previous similar messages [ 6660.360942] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6662.249169] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6671.021526] Lustre: DEBUG MARKER: == replay-single test 61c: test race mds llog sync vs llog cleanup ========================================================== 09:42:25 (1787578945) [ 6689.776546] Lustre: lustre-OST0000-osc-ffff9037c4c9c000: Connection to lustre-OST0000 (at 192.168.204.113@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 6689.803345] Lustre: Skipped 6 previous similar messages [ 6721.391757] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 6723.297360] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 6735.444415] Lustre: DEBUG MARKER: == replay-single test 61d: error in llog_setup should cleanup the llog context correctly ========================================================== 09:43:30 (1787579010) [ 6782.216603] Lustre: DEBUG MARKER: == replay-single test 62: don't mis-drop resent replay === 09:44:16 (1787579056) [ 6790.977693] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 6886.373434] Lustre: 2399:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787579102/real 1787579102] req@ffff9037c94fca80 x1874405509154432/t313532612610(313532612610) o36->lustre-MDT0000-mdc-ffff9037c4c9c000@192.168.204.113@tcp:12/10 lens 528/448 e 0 to 1 dl 1787579162 ref 2 fl Rpc:XQr/204/ffffffff rc 0/-1 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 6886.393281] Lustre: 2399:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 6 previous similar messages [ 6886.397653] LustreError: 2399:0:(client.c:3398:ptlrpc_replay_interpret()) @@@ request replay timed out req@ffff9037c94fca80 x1874405509154432/t313532612610(313532612610) o36->lustre-MDT0000-mdc-ffff9037c4c9c000@192.168.204.113@tcp:12/10 lens 528/448 e 0 to 1 dl 1787579162 ref 2 fl Interpret:EXQU/204/ffffffff rc -110/-1 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 6886.543870] LustreError: 2399:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9037c94fce00 x1874405509156096/t313532612612(313532612612) o101->lustre-MDT0000-mdc-ffff9037c4c9c000@192.168.204.113@tcp:12/10 lens 592/608 e 0 to 0 dl 1787579222 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'createmany.0' uid:0 gid:0 projid:0 [ 6886.569242] LustreError: 2399:0:(client.c:3448:ptlrpc_replay_interpret()) Skipped 19 previous similar messages [ 6893.126458] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6894.615555] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6904.907575] Lustre: DEBUG MARKER: == replay-single test 65a: AT: verify early replies ====== 09:46:19 (1787579179) [ 6968.913572] Lustre: DEBUG MARKER: == replay-single test 65b: AT: verify early replies on packed reply / bulk ========================================================== 09:47:23 (1787579243) [ 7024.809190] Lustre: DEBUG MARKER: == replay-single test 66a: AT: verify MDT service time adjusts with no early replies ========================================================== 09:48:19 (1787579299) [ 7092.949301] Lustre: DEBUG MARKER: == replay-single test 66b: AT: verify net latency adjusts ========================================================== 09:49:27 (1787579367) [ 7121.148910] LustreError: 132171:0:(client.c:1694:after_reply()) cfs_fail_timeout id 50c sleeping for 10000ms [ 7131.151877] LustreError: 132171:0:(client.c:1694:after_reply()) cfs_fail_timeout id 50c awake [ 7131.189880] LustreError: 132171:0:(client.c:1694:after_reply()) cfs_fail_timeout id 50c sleeping for 10000ms [ 7141.207643] LustreError: 132171:0:(client.c:1694:after_reply()) cfs_fail_timeout id 50c awake [ 7141.219988] LustreError: 132171:0:(client.c:1694:after_reply()) cfs_fail_timeout id 50c sleeping for 10000ms [ 7151.247291] LustreError: 132171:0:(client.c:1694:after_reply()) cfs_fail_timeout id 50c awake [ 7151.273443] LustreError: 132171:0:(client.c:1694:after_reply()) cfs_fail_timeout id 50c sleeping for 10000ms [ 7161.367135] LustreError: 132171:0:(client.c:1694:after_reply()) cfs_fail_timeout id 50c awake [ 7161.394315] LustreError: 2400:0:(client.c:1694:after_reply()) cfs_fail_timeout id 50c sleeping for 10000ms [ 7171.425141] LustreError: 2400:0:(client.c:1694:after_reply()) cfs_fail_timeout id 50c awake [ 7171.448679] LustreError: 132171:0:(client.c:1694:after_reply()) cfs_fail_timeout id 50c sleeping for 10000ms [ 7181.463159] LustreError: 132171:0:(client.c:1694:after_reply()) cfs_fail_timeout id 50c awake [ 7190.041588] Lustre: DEBUG MARKER: == replay-single test 67a: AT: verify slow request processing doesn't induce reconnects ========================================================== 09:51:04 (1787579464) [ 7272.771386] Lustre: DEBUG MARKER: == replay-single test 67b: AT: verify instant slowdown doesn't induce reconnects ========================================================== 09:52:27 (1787579547) [ 7308.165230] Lustre: DEBUG MARKER: phase 2 [ 7320.605234] Lustre: DEBUG MARKER: == replay-single test 68: AT: verify slowing locks ======= 09:53:14 (1787579594) [ 7353.182624] LustreError: 33468:0:(ldlm_request.c:1533:ldlm_cli_cancel_req()) cfs_fail_timeout id 312 sleeping for 19000ms [ 7372.199527] LustreError: 33468:0:(ldlm_request.c:1533:ldlm_cli_cancel_req()) cfs_fail_timeout id 312 awake [ 7406.449452] Lustre: DEBUG MARKER: == replay-single test 70a: check multi client t-f ======== 09:54:40 (1787579680) [ 7408.319357] Lustre: DEBUG MARKER: SKIP: replay-single test_70a Need two or more clients, have 1 [ 7409.970630] Lustre: DEBUG MARKER: == replay-single test 70b: dbench 2mdts recovery; 1 clients ========================================================== 09:54:44 (1787579684) [ 7415.348700] Lustre: DEBUG MARKER: Started rundbench load pid=135500 ... [ 7424.625353] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 7427.304211] Lustre: DEBUG MARKER: test_70b fail mds1 1 times [ 7429.500301] LustreError: lustre-MDT0000-mdc-ffff9037c4c9c000: operation ldlm_enqueue to node 192.168.204.113@tcp failed: rc = -19 [ 7429.511100] Lustre: lustre-MDT0000-mdc-ffff9037c4c9c000: Connection to lustre-MDT0000 (at 192.168.204.113@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 7429.547497] Lustre: Skipped 2 previous similar messages [ 7450.596925] LustreError: MGC192.168.204.113@tcp: Connection to MGS (at 192.168.204.113@tcp) was lost; in progress operations using this service will fail [ 7450.607354] LustreError: Skipped 4 previous similar messages [ 7460.852302] Lustre: Evicted from MGS (at 192.168.204.113@tcp) after server handle changed from 0x3e15f5fb7c51c638 to 0x3e15f5fb7c523d9a [ 7460.876470] Lustre: Skipped 4 previous similar messages [ 7460.884212] Lustre: MGC192.168.204.113@tcp: Connection restored to 192.168.204.113@tcp (at 192.168.204.113@tcp) [ 7460.889796] Lustre: Skipped 7 previous similar messages [ 7462.375488] LustreError: 2399:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9037e0480380 x1874405509387776/t317827580264(317827580264) o101->lustre-MDT0000-mdc-ffff9037c4c9c000@192.168.204.113@tcp:12/10 lens 576/608 e 0 to 0 dl 1787579754 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'dbench.0' uid:0 gid:0 projid:0 [ 7462.405287] LustreError: 2399:0:(client.c:3448:ptlrpc_replay_interpret()) Skipped 24 previous similar messages [ 7478.760361] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 7480.538869] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7492.689285] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 7495.447959] Lustre: DEBUG MARKER: test_70b fail mds2 2 times [ 7537.271864] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 7539.124365] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7566.661574] Lustre: DEBUG MARKER: == replay-single test 70c: tar 2mdts recovery ============ 09:57:21 (1787579841) [ 7696.557439] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 7708.412338] Lustre: DEBUG MARKER: test_70c fail mds1 1 times [ 7711.774673] LustreError: lustre-MDT0000-mdc-ffff9037c4c9c000: operation mds_reint to node 192.168.204.113@tcp failed: rc = -19 [ 7735.775247] Lustre: 2401:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787579995/real 1787579995] req@ffff9037c7a7a300 x1874405515374464/t0(0) o400->MGC192.168.204.113@tcp@192.168.204.113@tcp:26/25 lens 224/224 e 0 to 1 dl 1787580011 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 7735.801176] Lustre: 2401:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 7746.158234] Lustre: 15217:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.204.113@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 7746.174196] Lustre: 15217:0:(mgc_request.c:1900:mgc_process_log()) Skipped 1 previous similar message [ 7754.353116] LustreError: 2399:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9037c7636a00 x1874405514932864/t322122554985(322122554985) o101->lustre-MDT0000-mdc-ffff9037c4c9c000@192.168.204.113@tcp:12/10 lens 592/608 e 0 to 0 dl 1787580046 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'tar.0' uid:0 gid:0 projid:0 [ 7754.378444] LustreError: 2399:0:(client.c:3448:ptlrpc_replay_interpret()) Skipped 30 previous similar messages [ 7763.913845] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 7766.056273] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7809.287822] Lustre: DEBUG MARKER: == replay-single test 70d: mkdir/rmdir striped dir 2mdts recovery ========================================================== 10:01:23 (1787580083) [ 7938.181148] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 7949.556204] Lustre: DEBUG MARKER: test_70d fail mds1 1 times [ 7952.558804] LustreError: lustre-MDT0000-mdc-ffff9037c4c9c000: operation ldlm_enqueue to node 192.168.204.113@tcp failed: rc = -19 [ 7990.386910] LustreError: 2399:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9037c7c14700 x1874405518534528/t326417519445(326417519445) o101->lustre-MDT0000-mdc-ffff9037c4c9c000@192.168.204.113@tcp:12/10 lens 576/608 e 0 to 0 dl 1787580282 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'touch.0' uid:0 gid:0 projid:0 [ 7990.405743] LustreError: 2399:0:(client.c:3448:ptlrpc_replay_interpret()) Skipped 90 previous similar messages [ 7999.314816] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 8000.843933] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8010.118934] Lustre: DEBUG MARKER: == replay-single test 70e: rename cross-MDT with random fails ========================================================== 10:04:45 (1787580285) [ 8140.089641] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 8151.619117] Lustre: DEBUG MARKER: test_70e fail mds1 1 times [ 8154.978524] LustreError: lustre-MDT0000-mdc-ffff9037c4c9c000: operation ldlm_enqueue to node 192.168.204.113@tcp failed: rc = -107 [ 8154.990240] Lustre: lustre-MDT0000-mdc-ffff9037c4c9c000: Connection to lustre-MDT0000 (at 192.168.204.113@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 8155.004284] Lustre: Skipped 3 previous similar messages [ 8170.975831] LustreError: MGC192.168.204.113@tcp: Connection to MGS (at 192.168.204.113@tcp) was lost; in progress operations using this service will fail [ 8170.993473] LustreError: Skipped 2 previous similar messages [ 8181.234146] Lustre: Evicted from MGS (at 192.168.204.113@tcp) after server handle changed from 0x3e15f5fb7c5c9e13 to 0x3e15f5fb7c60b05d [ 8181.242906] Lustre: Skipped 2 previous similar messages [ 8181.256788] Lustre: MGC192.168.204.113@tcp: Connection restored to 192.168.204.113@tcp (at 192.168.204.113@tcp) [ 8181.264678] Lustre: Skipped 6 previous similar messages [ 8188.499229] LustreError: 2399:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status -116, old was 0 req@ffff9037c7dfc000 x1874405520822144/t330712486215(330712486215) o35->lustre-MDT0000-mdc-ffff9037c4c9c000@192.168.204.113@tcp:23/10 lens 392/456 e 0 to 0 dl 1787580476 ref 2 fl Interpret:RQU/604/0 rc -116/-116 job:'touch.0' uid:0 gid:0 projid:0 [ 8188.524574] LustreError: 2399:0:(client.c:3448:ptlrpc_replay_interpret()) Skipped 25 previous similar messages [ 8199.250473] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 8200.951995] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8209.651799] Lustre: DEBUG MARKER: == replay-single test 70f: OSS O_DIRECT recovery with 1 clients ========================================================== 10:08:04 (1787580484) [ 8220.662953] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-OST0000 [ 8222.985807] Lustre: DEBUG MARKER: test_70f failing OST 1 times [ 8266.817563] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 8269.121164] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 8280.209236] Lustre: DEBUG MARKER: == replay-single test 71a: mkdir/rmdir striped dir with 2 mdts recovery ========================================================== 10:09:14 (1787580554) [ 8408.384750] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 8416.042044] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 8427.702777] Lustre: DEBUG MARKER: fail mds2 mds1 1 times [ 8436.221788] LustreError: lustre-MDT0000-mdc-ffff9037c4c9c000: operation mds_reint to node 192.168.204.113@tcp failed: rc = -19 [ 8461.791126] Lustre: 2401:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787580721/real 1787580721] req@ffff9037c549a680 x1874405523176192/t0(0) o400->MGC192.168.204.113@tcp@192.168.204.113@tcp:26/25 lens 224/224 e 0 to 1 dl 1787580737 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 8461.827488] Lustre: 2401:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 8490.644300] LustreError: 2399:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9037d0109f80 x1874405521401216/t335007449505(335007449505) o101->lustre-MDT0000-mdc-ffff9037c4c9c000@192.168.204.113@tcp:12/10 lens 520/664 e 0 to 0 dl 1787580782 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'lfs.0' uid:0 gid:0 projid:0 [ 8490.666718] LustreError: 2399:0:(client.c:3448:ptlrpc_replay_interpret()) Skipped 119 previous similar messages [ 8502.124333] Lustre: DEBUG MARKER: oleg413-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 [ 8503.719550] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8505.997442] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8514.092501] Lustre: DEBUG MARKER: == replay-single test 73a: open(O_CREAT), unlink, replay, reconnect before open replay, close ========================================================== 10:13:08 (1787580788) [ 8521.422527] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 8569.823277] LustreError: 2399:0:(client.c:3398:ptlrpc_replay_interpret()) @@@ request replay timed out req@ffff9037d0109f80 x1874405521401216/t335007449505(335007449505) o101->lustre-MDT0000-mdc-ffff9037c4c9c000@192.168.204.113@tcp:12/10 lens 520/664 e 0 to 1 dl 1787580845 ref 2 fl Interpret:EXPQU/604/ffffffff rc -110/-1 job:'lfs.0' uid:0 gid:0 projid:0 [ 8575.816761] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 8577.231987] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8584.397459] Lustre: DEBUG MARKER: == replay-single test 73b: open(O_CREAT), unlink, replay, reconnect at open_replay reply, close ========================================================== 10:14:19 (1787580859) [ 8591.412945] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 8640.991373] LustreError: 2399:0:(client.c:3398:ptlrpc_replay_interpret()) @@@ request replay timed out req@ffff9037d0109f80 x1874405521401216/t335007449505(335007449505) o101->lustre-MDT0000-mdc-ffff9037c4c9c000@192.168.204.113@tcp:12/10 lens 520/664 e 0 to 1 dl 1787580917 ref 2 fl Interpret:EXPQU/604/ffffffff rc -110/-1 job:'lfs.0' uid:0 gid:0 projid:0 [ 8647.109228] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 8648.402459] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8656.348662] Lustre: DEBUG MARKER: == replay-single test 74: Ensure applications don't fail waiting for OST recovery ========================================================== 10:15:30 (1787580930) [ 8659.069539] Lustre: Unmounted lustre-client [ 8690.387145] Lustre: Mounted lustre-client - version 2.17.57_80_g9b8a413 [ 8697.157068] LustreError: lustre-OST0000-osc-ffff9037d9e83000: operation ost_connect to node 192.168.204.113@tcp failed: rc = -16 [ 8710.488872] Lustre: DEBUG MARKER: == replay-single test 80a: DNE: create remote dir, drop update rep from MDT0, fail MDT0 ========================================================== 10:16:25 (1787580985) [ 8719.762689] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 8766.379691] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 8768.220515] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8777.260416] Lustre: DEBUG MARKER: == replay-single test 80b: DNE: create remote dir, drop update rep from MDT0, fail MDT1 ========================================================== 10:17:32 (1787581052) [ 8785.779778] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 8793.067968] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 8798.199369] Lustre: lustre-MDT0001-mdc-ffff9037d9e83000: Connection to lustre-MDT0001 (at 192.168.204.113@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 8798.214228] Lustre: Skipped 6 previous similar messages [ 8830.016663] Lustre: lustre-MDT0001-mdc-ffff9037d9e83000: Connection restored to 192.168.204.113@tcp (at 192.168.204.113@tcp) [ 8830.023864] Lustre: Skipped 10 previous similar messages [ 8838.072985] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 8839.579296] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8848.940781] Lustre: DEBUG MARKER: == replay-single test 80c: DNE: create remote dir, drop update rep from MDT1, fail MDT[0,1] ========================================================== 10:18:43 (1787581123) [ 8857.049606] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 8864.601320] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 8883.167955] LustreError: MGC192.168.204.113@tcp: Connection to MGS (at 192.168.204.113@tcp) was lost; in progress operations using this service will fail [ 8883.188333] LustreError: Skipped 4 previous similar messages [ 8893.417635] Lustre: Evicted from MGS (at 192.168.204.113@tcp) after server handle changed from 0x3e15f5fb7c654412 to 0x3e15f5fb7c655974 [ 8893.436216] Lustre: Skipped 4 previous similar messages [ 8895.210278] Lustre: 161253:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.204.113@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 8910.693732] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 8912.170106] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8954.070498] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 8955.828326] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8965.505600] Lustre: DEBUG MARKER: == replay-single test 80d: DNE: create remote dir, drop update rep from MDT1, fail 2 MDTs ========================================================== 10:20:39 (1787581239) [ 8978.143976] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 8986.342480] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 9036.933929] Lustre: DEBUG MARKER: oleg413-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 [ 9038.748628] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 9040.549356] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 9051.730883] Lustre: DEBUG MARKER: == replay-single test 80e: DNE: create remote dir, drop MDT1 rep, fail MDT0 ========================================================== 10:22:06 (1787581326) [ 9065.640056] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 9069.535312] Lustre: 169627:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787581329/real 1787581329] req@ffff9037e05b5c00 x1874405523482880/t0(0) o36->lustre-MDT0001-mdc-ffff9037d9e83000@192.168.204.113@tcp:12/10 lens 560/576 e 0 to 1 dl 1787581345 ref 2 fl Rpc:XQr/200/ffffffff rc 0/-1 job:'lfs.0' uid:0 gid:0 projid:4294967295 [ 9069.568365] Lustre: 169627:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 11 previous similar messages [ 9096.318788] Lustre: 161253:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.204.113@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 9113.118326] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 9115.200938] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 9126.110127] Lustre: DEBUG MARKER: == replay-single test 80f: DNE: create remote dir, drop MDT1 rep, fail MDT1 ========================================================== 10:23:20 (1787581400) [ 9137.024152] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 9179.135812] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 9180.775182] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 9189.697144] Lustre: DEBUG MARKER: == replay-single test 80g: DNE: create remote dir, drop MDT1 rep, fail MDT0, then MDT1 ========================================================== 10:24:24 (1787581464) [ 9202.848505] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 9212.324436] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 9244.096077] Lustre: 161253:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.204.113@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 9261.479397] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 9263.639226] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 9307.584804] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 9309.550499] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 9320.688493] Lustre: DEBUG MARKER: == replay-single test 80h: DNE: create remote dir, drop MDT1 rep, fail 2 MDTs ========================================================== 10:26:35 (1787581595) [ 9332.525704] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 9341.983411] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 9390.187733] Lustre: 161253:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.204.113@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 9422.047066] Lustre: DEBUG MARKER: oleg413-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 [ 9424.119157] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 9426.106805] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 9437.871798] Lustre: DEBUG MARKER: == replay-single test 81a: DNE: unlink remote dir, drop MDT0 update rep, fail MDT1 ========================================================== 10:28:32 (1787581712) [ 9447.480794] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 9449.448772] Lustre: lustre-MDT0001-mdc-ffff9037d9e83000: Connection to lustre-MDT0001 (at 192.168.204.113@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 9449.452935] LustreError: lustre-MDT0001-mdc-ffff9037d9e83000: operation mds_reint to node 192.168.204.113@tcp failed: rc = -19 [ 9449.462223] Lustre: Skipped 13 previous similar messages [ 9449.490387] LustreError: Skipped 1 previous similar message [ 9484.372677] Lustre: lustre-MDT0001-mdc-ffff9037d9e83000: Connection restored to 192.168.204.113@tcp (at 192.168.204.113@tcp) [ 9484.396660] Lustre: Skipped 18 previous similar messages [ 9498.562628] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 9500.419514] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 9509.816208] Lustre: DEBUG MARKER: == replay-single test 81b: DNE: unlink remote dir, drop MDT0 update reply, fail MDT0 ========================================================== 10:29:44 (1787581784) [ 9519.805791] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 9542.623519] LustreError: MGC192.168.204.113@tcp: Connection to MGS (at 192.168.204.113@tcp) was lost; in progress operations using this service will fail [ 9542.630668] LustreError: Skipped 4 previous similar messages [ 9552.873528] Lustre: Evicted from MGS (at 192.168.204.113@tcp) after server handle changed from 0x3e15f5fb7c659e71 to 0x3e15f5fb7c65b2c9 [ 9552.890128] Lustre: Skipped 4 previous similar messages [ 9566.932652] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 9569.204925] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 9578.198311] Lustre: DEBUG MARKER: == replay-single test 81c: DNE: unlink remote dir, drop MDT0 update reply, fail MDT0,MDT1 ========================================================== 10:30:52 (1787581852) [ 9587.123502] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 9595.695725] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 9646.514177] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 9648.386579] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 9691.775164] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 9693.124644] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 9702.620975] Lustre: DEBUG MARKER: == replay-single test 81d: DNE: unlink remote dir, drop MDT0 update reply, fail 2 MDTs ========================================================== 10:32:57 (1787581977) [ 9712.975611] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 9720.570224] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 9742.304657] Lustre: 2402:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787582002/real 1787582002] req@ffff9037c549a300 x1874405523698432/t0(0) o400->MGC192.168.204.113@tcp@192.168.204.113@tcp:26/25 lens 224/224 e 0 to 1 dl 1787582018 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 9742.340813] Lustre: 2402:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 13 previous similar messages [ 9773.138442] Lustre: DEBUG MARKER: oleg413-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 [ 9775.330533] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 9777.292649] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 9787.352957] Lustre: DEBUG MARKER: == replay-single test 81e: DNE: unlink remote dir, drop MDT1 req reply, fail MDT0 ========================================================== 10:34:22 (1787582062) [ 9799.255307] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 9843.380319] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 9845.399895] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 9856.216491] Lustre: DEBUG MARKER: == replay-single test 81f: DNE: unlink remote dir, drop MDT1 req reply, fail MDT1 ========================================================== 10:35:30 (1787582130) [ 9866.557236] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 9905.946294] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 9907.435231] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 9915.480505] Lustre: DEBUG MARKER: == replay-single test 81g: DNE: unlink remote dir, drop req reply, fail M0, then M1 ========================================================== 10:36:30 (1787582190) [ 9924.965638] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 9932.369339] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 9964.083592] Lustre: 161253:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.204.113@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 9979.729753] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 9981.342044] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [10031.111881] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [10033.518413] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [10044.415246] Lustre: DEBUG MARKER: == replay-single test 81h: DNE: unlink remote dir, drop request reply, fail 2 MDTs ========================================================== 10:38:38 (1787582318) [10054.866945] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [10062.303242] Lustre: lustre-MDT0001-mdc-ffff9037d9e83000: Connection to lustre-MDT0001 (at 192.168.204.113@tcp) was lost; in progress operations using this service will wait for recovery to complete [10062.320678] Lustre: Skipped 11 previous similar messages [10063.624097] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [10108.402363] Lustre: MGC192.168.204.113@tcp: Connection restored to 192.168.204.113@tcp (at 192.168.204.113@tcp) [10108.417746] Lustre: Skipped 17 previous similar messages [10110.077187] Lustre: 161253:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.204.113@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [10132.739317] Lustre: DEBUG MARKER: oleg413-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 [10134.519203] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [10136.115226] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [10145.771456] Lustre: DEBUG MARKER: == replay-single test 84a: stale open during export disconnect ========================================================== 10:40:19 (1787582419) [10150.982808] LustreError: lustre-MDT0000-mdc-ffff9037d9e83000: operation ldlm_enqueue to node 192.168.204.113@tcp failed: rc = -107 [10151.002457] LustreError: lustre-MDT0000-mdc-ffff9037d9e83000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [10151.034902] LustreError: 192010:0:(file.c:6167:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -5 [10164.564139] Lustre: DEBUG MARKER: == replay-single test 85a: check the cancellation of unused locks during recovery(IBITS) ========================================================== 10:40:38 (1787582438) [10190.303250] LustreError: MGC192.168.204.113@tcp: Connection to MGS (at 192.168.204.113@tcp) was lost; in progress operations using this service will fail [10190.316454] LustreError: Skipped 5 previous similar messages [10195.553137] LustreError: 2399:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9037c5499880 x1874405523790080/t403726925836(403726925836) o101->lustre-MDT0000-mdc-ffff9037d9e83000@192.168.204.113@tcp:12/10 lens 576/608 e 0 to 0 dl 1787582487 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'grep.0' uid:0 gid:0 projid:0 [10195.577119] LustreError: 2399:0:(client.c:3448:ptlrpc_replay_interpret()) Skipped 5 previous similar messages [10200.743146] Lustre: Evicted from MGS (at 192.168.204.113@tcp) after server handle changed from 0x3e15f5fb7c65df4d to 0x3e15f5fb7c6614fa [10200.755476] Lustre: Skipped 5 previous similar messages [10208.496735] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [10210.465443] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [10219.846852] Lustre: DEBUG MARKER: == replay-single test 85b: check the cancellation of unused locks during recovery(EXTENT) ========================================================== 10:41:34 (1787582494) [10273.664900] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [10275.186501] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [10284.914463] Lustre: DEBUG MARKER: == replay-single test 86: umount server after clear nid_stats should not hit LBUG ========================================================== 10:42:39 (1787582559) [10287.489306] Lustre: Unmounted lustre-client [10306.705389] Lustre: Mounted lustre-client - version 2.17.57_80_g9b8a413 [10313.539282] Lustre: DEBUG MARKER: == replay-single test 87a: write replay ================== 10:43:08 (1787582588) [10321.401432] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-OST0000 [10362.619168] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [10363.970275] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [10371.960566] Lustre: DEBUG MARKER: == replay-single test 87b: write replay with changed data (checksum resend) ========================================================== 10:44:06 (1787582646) [10380.099457] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-OST0000 [10424.778349] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [10426.843666] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [10436.424447] Lustre: DEBUG MARKER: == replay-single test 88: MDS should not assign same objid to different files ========================================================== 10:45:10 (1787582710) [10444.999146] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-OST0000 [10453.104768] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [10481.631166] Lustre: 2402:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787582741/real 1787582741] req@ffff9037c7791f80 x1874405524264704/t0(0) o400->MGC192.168.204.113@tcp@192.168.204.113@tcp:26/25 lens 224/224 e 0 to 1 dl 1787582757 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [10481.687604] Lustre: 2402:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 20 previous similar messages [10493.244327] Lustre: 195993:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.204.113@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [10511.986435] LustreError: 2399:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9037c5e15500 x1874405524220416/t412316860433(412316860433) o101->lustre-MDT0000-mdc-ffff9037e0262800@192.168.204.113@tcp:12/10 lens 576/608 e 0 to 0 dl 1787582804 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'md5sum.0' uid:0 gid:0 projid:0 [10512.016734] LustreError: 2399:0:(client.c:3448:ptlrpc_replay_interpret()) Skipped 99 previous similar messages [10565.302568] Lustre: DEBUG MARKER: == replay-single test 89: no disk space leak on late ost connection ========================================================== 10:47:19 (1787582839) [10607.651336] LustreError: 2399:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9037c5e15500 x1874405524220416/t412316860433(412316860433) o101->lustre-MDT0000-mdc-ffff9037e0262800@192.168.204.113@tcp:12/10 lens 576/608 e 0 to 0 dl 1787582899 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'md5sum.0' uid:0 gid:0 projid:0 [10607.692570] LustreError: 2399:0:(client.c:3448:ptlrpc_replay_interpret()) Skipped 40 previous similar messages [10613.088851] Lustre: Unmounted lustre-client [10629.285846] Lustre: Mounted lustre-client - version 2.17.57_80_g9b8a413 [10629.317536] LustreError: lustre-OST0000-osc-ffff9037d84a5800: operation ost_connect to node 192.168.204.113@tcp failed: rc = -16 [10634.753995] LustreError: lustre-OST0000-osc-ffff9037d84a5800: operation ost_connect to node 192.168.204.113@tcp failed: rc = -16 [10639.887697] LustreError: lustre-OST0000-osc-ffff9037d84a5800: operation ost_connect to node 192.168.204.113@tcp failed: rc = -16 [10644.967569] LustreError: lustre-OST0000-osc-ffff9037d84a5800: operation ost_connect to node 192.168.204.113@tcp failed: rc = -16 [10655.232583] LustreError: lustre-OST0000-osc-ffff9037d84a5800: operation ost_connect to node 192.168.204.113@tcp failed: rc = -16 [10655.246483] LustreError: Skipped 1 previous similar message [10675.691512] LustreError: lustre-OST0000-osc-ffff9037d84a5800: operation ost_connect to node 192.168.204.113@tcp failed: rc = -16 [10675.706458] LustreError: Skipped 3 previous similar messages [10698.327523] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 60 sec [10708.183835] Lustre: DEBUG MARKER: free_before: 7646268 free_after: 7646268 [10714.602520] Lustre: DEBUG MARKER: == replay-single test 90: lfs find identifies the missing striped file segments ========================================================== 10:49:49 (1787582989) [10721.764132] Lustre: lustre-OST0000-osc-ffff9037d84a5800: Connection to lustre-OST0000 (at 192.168.204.113@tcp) was lost; in progress operations using this service will wait for recovery to complete [10721.794422] Lustre: Skipped 11 previous similar messages [10740.123947] Lustre: lustre-OST0000-osc-ffff9037d84a5800: Connection restored to 192.168.204.113@tcp (at 192.168.204.113@tcp) [10740.141338] Lustre: Skipped 12 previous similar messages [10754.745052] Lustre: DEBUG MARKER: == replay-single test 93a: replay + reconnect ============ 10:50:29 (1787583029) [10760.178308] LustreError: lustre-OST0000-osc-ffff9037d84a5800: operation ost_write to node 192.168.204.113@tcp failed: rc = -107 [10760.186515] LustreError: Skipped 3 previous similar messages [10823.369158] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [10825.044747] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [10831.995983] Lustre: DEBUG MARKER: == replay-single test 93b: replay + reconnect on mds ===== 10:51:46 (1787583106) [10855.903205] LustreError: MGC192.168.204.113@tcp: Connection to MGS (at 192.168.204.113@tcp) was lost; in progress operations using this service will fail [10855.916721] LustreError: Skipped 2 previous similar messages [10866.238730] Lustre: Evicted from MGS (at 192.168.204.113@tcp) after server handle changed from 0x3e15f5fb7c6668d0 to 0x3e15f5fb7c667453 [10866.245375] Lustre: Skipped 2 previous similar messages [10948.954804] Lustre: DEBUG MARKER: oleg413-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [10950.654455] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [10961.273520] Lustre: DEBUG MARKER: == replay-single test complete, duration 10613 sec ======= 10:53:55 (1787583235) [10963.214572] Lustre: DEBUG MARKER: === replay-single: start cleanup 10:53:57 (1787583237) === [10975.864122] Lustre: DEBUG MARKER: === replay-single: finish cleanup 10:54:10 (1787583250) === [11002.187887] Lustre: Unmounted lustre-client [11062.415636] Key type lgssc unregistered [11062.808628] LNet: 208452:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [11062.814622] LNetError: 208452:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [11062.853095] LNet: Removed LNI 192.168.204.13@tcp [11063.817146] Key type .llcrypt unregistered [11063.823878] Key type ._llcrypt unregistered