[ 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 478727675 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: 2895288K/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.001010] APIC: Switch to symmetric I/O mode setup [ 0.003184] x2apic enabled [ 0.004007] Switched APIC routing to physical x2apic. [ 0.005012] kvm-guest: setup PV IPIs [ 0.008357] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.009000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.009020] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.010010] pid_max: default: 32768 minimum: 301 [ 0.012030] LSM: Security Framework initializing [ 0.013043] Yama: becoming mindful. [ 0.014034] SELinux: Initializing. [ 0.015062] *** VALIDATE selinux *** [ 0.023641] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.028244] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.029140] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.030094] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.031094] *** VALIDATE tmpfs *** [ 0.033077] *** VALIDATE proc *** [ 0.034198] *** VALIDATE cgroup *** [ 0.035019] *** VALIDATE cgroup2 *** [ 0.036246] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.037165] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.038009] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.039027] Spectre V2 : User space: Vulnerable [ 0.040009] Speculative Store Bypass: Vulnerable [ 0.043515] debug: unmapping init [mem 0xffffffffb8459000-0xffffffffb8460fff] [ 0.045252] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.046742] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.047023] ... version: 2 [ 0.048011] ... bit width: 48 [ 0.049011] ... generic registers: 4 [ 0.050013] ... value mask: 0000ffffffffffff [ 0.051015] ... max period: 00007fffffffffff [ 0.052013] ... fixed-purpose events: 3 [ 0.053009] ... event mask: 000000070000000f [ 0.054288] rcu: Hierarchical SRCU implementation. [ 0.056522] smp: Bringing up secondary CPUs ... [ 0.057583] x86: Booting SMP configuration: [ 0.058027] .... node #0, CPUs: #1 #2 #3 [ 0.062010] smp: Brought up 1 node, 4 CPUs [ 0.064016] smpboot: Max logical packages: 1 [ 0.065014] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.131381] node 0 deferred pages initialised in 64ms [ 0.133129] devtmpfs: initialized [ 0.137345] x86/mm: Memory block size: 128MB [ 0.141137] gcov: version magic: 0x41383552 [ 0.146049] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.150082] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.152313] pinctrl core: initialized pinctrl subsystem [ 0.155223] [ 0.155779] ************************************************************* [ 0.158013] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.161013] ** ** [ 0.163010] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.166013] ** ** [ 0.168012] ** This means that this kernel is built to expose internal ** [ 0.170014] ** IOMMU data structures, which may compromise security on ** [ 0.172014] ** your system. ** [ 0.175012] ** ** [ 0.178013] ** If you see this message and you are not debugging the ** [ 0.180010] ** kernel, report this immediately to your vendor! ** [ 0.182012] ** ** [ 0.185061] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.187009] ************************************************************* [ 0.189870] NET: Registered protocol family 16 [ 0.192505] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.194055] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.197070] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.201064] cpuidle: using governor menu [ 0.203902] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.206677] PCI: Using configuration type 1 for base access [ 0.209119] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.220060] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.222019] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.226238] cryptd: max_cpu_qlen set to 1000 [ 0.227248] ACPI: Added _OSI(Module Device) [ 0.228012] ACPI: Added _OSI(Processor Device) [ 0.230011] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.232013] ACPI: Added _OSI(Processor Aggregator Device) [ 0.237925] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.245364] ACPI: Interpreter enabled [ 0.247051] ACPI: PM: (supports S0 S3 S4 S5) [ 0.248013] ACPI: Using IOAPIC for interrupt routing [ 0.250091] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.255384] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.266000] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.269043] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.272018] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.276071] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.282488] acpiphp: Slot [2] registered [ 0.283204] acpiphp: Slot [5] registered [ 0.285154] acpiphp: Slot [6] registered [ 0.286196] acpiphp: Slot [3] registered [ 0.288095] acpiphp: Slot [4] registered [ 0.289094] acpiphp: Slot [7] registered [ 0.290133] acpiphp: Slot [8] registered [ 0.292097] acpiphp: Slot [9] registered [ 0.293105] acpiphp: Slot [10] registered [ 0.296160] acpiphp: Slot [11] registered [ 0.298098] acpiphp: Slot [12] registered [ 0.299095] acpiphp: Slot [13] registered [ 0.301098] acpiphp: Slot [14] registered [ 0.302092] acpiphp: Slot [15] registered [ 0.304089] acpiphp: Slot [16] registered [ 0.305095] acpiphp: Slot [17] registered [ 0.306096] acpiphp: Slot [18] registered [ 0.308095] acpiphp: Slot [19] registered [ 0.309095] acpiphp: Slot [20] registered [ 0.310119] acpiphp: Slot [21] registered [ 0.312103] acpiphp: Slot [22] registered [ 0.313089] acpiphp: Slot [23] registered [ 0.314112] acpiphp: Slot [24] registered [ 0.316090] acpiphp: Slot [25] registered [ 0.317090] acpiphp: Slot [26] registered [ 0.318113] acpiphp: Slot [27] registered [ 0.320087] acpiphp: Slot [28] registered [ 0.321099] acpiphp: Slot [29] registered [ 0.323116] acpiphp: Slot [30] registered [ 0.324100] acpiphp: Slot [31] registered [ 0.326084] PCI host bridge to bus 0000:00 [ 0.327016] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.329021] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.331023] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.334022] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.336032] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.340027] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.342163] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.346104] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.350474] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.359014] pci 0000:00:01.1: reg 0x20: [io 0xc120-0xc12f] [ 0.363057] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.369025] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.371017] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.373017] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.376554] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.378216] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.380150] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.383978] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.389014] pci 0000:00:02.0: reg 0x10: [io 0xc100-0xc11f] [ 0.400015] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.404016] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.409882] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.416015] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.421016] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.439023] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.448000] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.455017] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.462019] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.487024] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.499040] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.503576] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.506414] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.509483] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.511312] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.517133] iommu: Default domain type: Passthrough [ 0.519500] SCSI subsystem initialized [ 0.520188] ACPI: bus type USB registered [ 0.522195] usbcore: registered new interface driver usbfs [ 0.524285] usbcore: registered new interface driver hub [ 0.527161] usbcore: registered new device driver usb [ 0.529296] pps_core: LinuxPPS API ver. 1 registered [ 0.531019] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.535090] PTP clock support registered [ 0.538097] EDAC MC: Ver: 3.0.0 [ 0.540201] PCI: Using ACPI for IRQ routing [ 0.543252] NetLabel: Initializing [ 0.545015] NetLabel: domain hash size = 128 [ 0.547015] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.549504] NetLabel: unlabeled traffic allowed by default [ 0.552178] vgaarb: loaded [ 0.555023] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.557016] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.562004] clocksource: Switched to clocksource kvm-clock [ 0.690950] VFS: Disk quotas dquot_6.6.0 [ 0.693022] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.696994] *** VALIDATE ramfs *** [ 0.701482] *** VALIDATE hugetlbfs *** [ 0.703982] pnp: PnP ACPI init [ 0.706404] pnp: PnP ACPI: found 6 devices [ 0.729179] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.732702] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.735219] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.738293] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.741367] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.745173] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.749130] NET: Registered protocol family 2 [ 0.751695] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.757584] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.761620] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.767590] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.772217] TCP: Hash tables configured (established 65536 bind 65536) [ 0.776197] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.779971] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.783471] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.787797] NET: Registered protocol family 1 [ 0.792247] RPC: Registered named UNIX socket transport module. [ 0.794557] RPC: Registered udp transport module. [ 0.796275] RPC: Registered tcp transport module. [ 0.797702] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.799909] NET: Registered protocol family 44 [ 0.801353] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.804472] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.807617] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.810456] PCI: CLS 0 bytes, default 64 [ 0.812440] Unpacking initramfs... [ 2.248500] debug: unmapping init [mem 0xffff8a673cc64000-0xffff8a673ffcffff] [ 2.252850] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.255251] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.258542] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 2.795150] Initialise system trusted keyrings [ 2.797553] Key type blacklist registered [ 2.799719] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.810851] zbud: loaded [ 2.814347] *** VALIDATE nfs *** [ 2.817136] *** VALIDATE nfs4 *** [ 2.818933] pstore: using deflate compression [ 2.822474] Platform Keyring initialized [ 2.934518] NET: Registered protocol family 38 [ 2.936323] Key type asymmetric registered [ 2.937816] Asymmetric key parser 'x509' registered [ 2.939791] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 2.942725] io scheduler mq-deadline registered [ 2.944684] io scheduler kyber registered [ 2.946243] io scheduler bfq registered [ 2.948556] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 2.951776] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 2.955382] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 2.958903] ACPI: Power Button [PWRF] [ 2.964241] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 2.971522] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 2.989905] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 3.019950] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.052897] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.058826] Non-volatile memory driver v1.3 [ 3.061163] Linux agpgart interface v0.103 [ 3.098961] virtio_blk virtio1: [vda] 146864 512-byte logical blocks (75.2 MB/71.7 MiB) [ 3.101968] vda: detected capacity change from 0 to 75194368 [ 3.117814] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.121252] vdb: detected capacity change from 0 to 1073741824 [ 3.129031] libphy: Fixed MDIO Bus: probed [ 3.137635] usbcore: registered new interface driver usbserial_generic [ 3.140335] usbserial: USB Serial support registered for generic [ 3.143082] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.147146] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.149375] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.152570] mousedev: PS/2 mouse device common for all mice [ 3.155757] rtc_cmos 00:05: RTC can wake from S4 [ 3.158604] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.163354] rtc_cmos 00:05: registered as rtc0 [ 3.164867] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.165687] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.169166] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.171179] intel_pstate: CPU model not supported [ 3.176647] hid: raw HID events driver (C) Jiri Kosina [ 3.178974] usbcore: registered new interface driver usbhid [ 3.180586] usbhid: USB HID core driver [ 3.182919] drop_monitor: Initializing network drop monitor service [ 3.185574] Initializing XFRM netlink socket [ 3.187794] NET: Registered protocol family 10 [ 3.191606] Segment Routing with IPv6 [ 3.193146] NET: Registered protocol family 17 [ 3.195180] mpls_gso: MPLS GSO support [ 3.201357] RAS: Correctable Errors collector initialized. [ 3.204635] AVX version of gcm_enc/dec engaged. [ 3.206924] AES CTR mode by8 optimization enabled [ 3.283316] sched_clock: Marking stable (3283292771, 0)->(4188445726, -905152955) [ 3.286966] registered taskstats version 1 [ 3.288930] Loading compiled-in X.509 certificates [ 3.291211] zswap: loaded using pool lzo/zbud [ 3.319708] Key type big_key registered [ 3.333659] Key type encrypted registered [ 3.335724] ima: No TPM chip found, activating TPM-bypass! [ 3.338602] ima: Allocated hash algorithm: sha1 [ 3.340749] ima: No architecture policies found [ 3.342758] evm: Initialising EVM extended attributes: [ 3.345183] evm: security.selinux [ 3.346638] evm: security.ima [ 3.348086] evm: security.capability [ 3.349566] evm: HMAC attrs: 0x1 [ 3.352454] rtc_cmos 00:05: setting system clock to 2026-08-27 17:41:44 UTC (1787852504) [ 3.359960] debug: unmapping init [mem 0xffffffffb9403000-0xffffffffb95fffff] [ 3.363742] debug: unmapping init [mem 0xffffffffb8182000-0xffffffffb8458fff] [ 3.378233] Write protecting the kernel read-only data: 28672k [ 3.382119] debug: unmapping init [mem 0xffffffffb6803000-0xffffffffb69fffff] [ 3.385378] debug: unmapping init [mem 0xffffffffb7114000-0xffffffffb71fffff] [ 3.419118] 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.429532] systemd[1]: Detected virtualization kvm. [ 3.432208] systemd[1]: Detected architecture x86-64. [ 3.434610] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.465631] systemd[1]: No hostname configured. [ 3.467660] systemd[1]: Set hostname to . [ 3.469878] random: systemd: uninitialized urandom read (16 bytes read) [ 3.472620] systemd[1]: Initializing machine ID from random generator. [ 3.538227] random: ln: uninitialized urandom read (6 bytes read) [ 3.634858] random: systemd: uninitialized urandom read (16 bytes read) [ 3.637390] systemd[1]: Reached target Initrd Root Device. [ OK ] Reached target Initrd Root Device. [ 3.642693] systemd[1]: Reached target Local File Systems. [ OK ] Reached target Local File Systems. [ 3.648225] systemd[1]: Listening on udev Kernel Socket. [ OK ] Listening on udev Kernel Socket. [ OK ] Reached target Slices. [ OK ] Listening on udev Control Socket. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Paths. [ OK ] Reached target Timers. [ OK ] Listening on Journal Socket (/dev/log). [ OK ] Reached target Swap. [ OK ] Listening on Journal Socket. Starting Setup Virtual Console... [ OK ] Started Memstrack Anylazing Service. Starting Create Volatile Files and Directories... Starting Apply Kernel Variables... [ OK ] Reached target Sockets. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Reached target Local Encrypted Volumes. Starting Journal Service... [ OK ] Started Setup Virtual Console. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Apply Kernel Variables. [ OK ] Started Create list of required sta…vice nodes for the current kernel. Starting Create Static Device Nodes in /dev... Starting dracut cmdline hook... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started Journal Service. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 4.305664] device-mapper: uevent: version 1.0.3 [ 4.307869] device-mapper: ioctl: 4.46.0-ioctl (2022-02-22) initialised: dm-devel@redhat.com [ OK ] Started dracut pre-udev hook. Starting udev Kernel Device Manager... [ OK ] Started udev Kernel Device Manager. Starting dracut pre-trigger hook... [ OK ] Started dracut pre-trigger hook. Starting udev Coldplug all Devices... Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting dracut initqueue hook... [ 5.055736] virtio_net virtio0 ens2: renamed from eth0 [ 5.067972] scsi host0: ata_piix [ 5.082562] scsi host1: ata_piix [ 5.085120] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc120 irq 14 [ 5.088666] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc128 irq 15 [ 7.315391] random: fast init done [ 9.194851] dracut-initqueue[575]: RTNETLINK answers: File exists [ 9.855844] random: crng init done [ 9.858390] random: 7 urandom warning(s) missed due to ratelimiting Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. Mounting /sysroot... [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. [ 10.616197] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped target Timers. [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped target Initrd Root Device. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Paths. [ OK ] Stopped target Sockets. [ OK ] Stopped target Slices. [ OK ] Stopped target System Initialization. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. Stopping udev Kernel Device Manager... [ OK ] Stopped target Local File Systems. [ OK ] Stopped target Swap. [ OK ] Stopped Apply Kernel Variables. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Closed udev Control Socket. [ OK ] Closed udev Kernel Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 11.972967] printk: systemd: 26 output lines suppressed due to ratelimiting [ 12.277685] SELinux: Disabled at runtime. [ 12.339395] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 12.347827] systemd[1]: Detected virtualization kvm. [ 12.349550] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 12.979884] systemd[1]: initrd-switch-root.service: Succeeded. [ 12.983596] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 12.988859] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 12.993337] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 12.996918] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 13.005501] systemd[1]: Starting Journal Service... Starting Journal Service... [ 13.009654] systemd[1]: Stopped target Switch Root. [ OK ] Stopped target Switch Root. [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Started Dispatch Password Requests to Console Directory Watch. Starting Remount Root and Kernel File Systems... [ OK ] Created slice system-sshd\x2dkeygen.slice. Mounting POSIX Message Queue File System... [ OK ] Reached target Paths. [ OK ] Listening on RPCbind Server Activation Socket. Starting Apply Kernel Variables... [ OK ] Reached target Local Encrypted Volumes. [ OK ] Listening on udev Kernel Socket. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Stopped target Initrd Root File System. [ OK ] Reached target RPC Port Mapper. [ OK ] Reached target rpc_pipefs.target. [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Listening on Process Core Dump Socket. [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Stopped target Initrd File Systems. [ OK ] Created slice User and Session Slice. [ OK ] Reached target Slices. Mounting Huge Pages File System... [ OK ] Listening on udev Control Socket. Starting udev Coldplug all Devices... Mounting Kernel Debug File System... [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Created slice system-getty.slice. Activating swap /dev/disk/by-label/SWAP... [ OK ] Started Journal Service. [ 13.256362] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Started Apply Kernel Variables. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Mounted Huge Pages File System. [ OK ] Mounted Kernel Debug File System. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Reached target Swap. Starting Configure read-only root support... Starting Create Static Device Nodes in /dev... Starting Flush Journal to Persistent Storage... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Reached target Local File Systems (Pre). Mounting /home/green/git/lustre-release... Mounting /mnt... Starting udev Kernel Device Manager... [ OK ] Started udev Coldplug all Devices. [ OK ] Mounted /mnt. [ 13.589431] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 14.083392] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 14.112927] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 14.306674] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 14.324872] EDAC sbridge: Ver: 1.1.2 [ 15.732752] Key type dns_resolver registered [ 16.082594] NFS: Registering the id_resolver key type [ 16.085933] Key type id_resolver registered [ 16.087624] Key type id_legacy registered [ 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 Cleanup of Temporary Directories. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Started dnf makecache --timer. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Started D-Bus System Message Bus. Starting Login Service... [ OK ] Started irqbalance daemon. [ OK ] Reached target sshd-keygen.target. Starting Restore /run/initramfs on shutdown... [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Reached target Timers. Starting Network Manager... [ OK ] Started Login Service. [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Network Manager. [ OK ] Reached target Network. Starting GSSAPI Proxy Daemon... Starting Dynamic System Tuning Daemon... Starting OpenSSH server daemon... Starting Network Manager Wait Online... [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... Starting Hostname Service... [ OK ] Started OpenSSH server daemon. [ OK ] Started Permit User Sessions. [ OK ] Started Command Scheduler. [ OK ] Started Serial Getty on ttyS1. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Getty on tty1. [ 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. Starting Authorization Manager... [ OK ] Started Dynamic System Tuning Daemon. [ OK ] Reached target Multi-User System. [ OK ] Reached target Graphical Interface. Starting Update UTMP about System Runlevel Changes... [ OK ] Started Authorization Manager. [ OK ] Started Update UTMP about System Runlevel Changes. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg612-client login: [ 49.107392] libcfs: loading out-of-tree module taints kernel. [ 49.267416] Key type ._llcrypt registered [ 49.270401] Key type .llcrypt registered [ 49.693979] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [ 49.715711] alg: No test for adler32 (adler32-zlib) [ 51.308423] Lustre: Lustre: Build Version: 2.17.57_85_gfc6b239 [ 52.188682] LNet: Added LNI 192.168.206.12@tcp [8/256/0/180] [ 54.063732] Key type lgssc registered [ 56.233394] Lustre: Echo OBD driver; http://www.lustre.org/ [ 244.895121] Lustre: Mounted lustre-client - version 2.17.57_85_gfc6b239 [ 249.934379] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 264.114845] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing check_logdir /tmp/testlogs/ [ 269.218535] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing yml_node [ 270.310716] Lustre: lustre-OST0000-osc-ffff8a6791405800: disconnect after 23s idle [ 272.650719] Lustre: DEBUG MARKER: Client: 2.17.57.85 [ 275.648488] Lustre: DEBUG MARKER: MDS: 2.17.57.85 [ 278.722318] Lustre: DEBUG MARKER: OSS: 2.17.57.85 [ 280.109225] Lustre: DEBUG MARKER: -----============= acceptance-small: replay-single ============----- Thu Aug 27 13:46:20 EDT 2026 [ 284.863048] hrtimer: interrupt took 5731747 ns [ 298.004188] Lustre: DEBUG MARKER: excepting tests: 59 36 [ 299.905736] Lustre: DEBUG MARKER: === replay-single: start setup 13:46:39 (1787852799) === [ 304.988980] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing check_config_client /mnt/lustre [ 325.491756] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 340.745591] Lustre: DEBUG MARKER: === replay-single: finish setup 13:47:20 (1787852840) === [ 342.450585] Lustre: DEBUG MARKER: == replay-single test 0a: empty replay =================== 13:47:22 (1787852842) [ 350.000855] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 352.229746] Lustre: lustre-MDT0000-mdc-ffff8a6791405800: Connection to lustre-MDT0000 (at 192.168.206.112@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 367.583791] Lustre: lustre-OST0000-osc-ffff8a6791405800: disconnect after 23s idle [ 367.599897] Lustre: Skipped 1 previous similar message [ 368.607662] Lustre: 2394:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787852853/real 1787852853] req@ffff8a67889d9680 x1874699278632832/t0(0) o400->MGC192.168.206.112@tcp@192.168.206.112@tcp:26/25 lens 224/224 e 0 to 1 dl 1787852869 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 368.635607] LustreError: MGC192.168.206.112@tcp: Connection to MGS (at 192.168.206.112@tcp) was lost; in progress operations using this service will fail [ 378.860089] Lustre: Evicted from MGS (at 192.168.206.112@tcp) after server handle changed from 0xfafcabacea5262cb to 0xfafcabacea526517 [ 378.876091] Lustre: MGC192.168.206.112@tcp: Connection restored to 192.168.206.112@tcp (at 192.168.206.112@tcp) [ 380.146769] Lustre: 6167:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.206.112@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 387.771144] Lustre: lustre-MDT0000-mdc-ffff8a6791405800: Connection restored to 192.168.206.112@tcp (at 192.168.206.112@tcp) [ 396.616858] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 398.226295] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 406.208382] Lustre: DEBUG MARKER: == replay-single test 0b: ensure object created after recover exists. (3284) ========================================================== 13:48:26 (1787852906) [ 409.578322] Lustre: lustre-OST0000-osc-ffff8a6791405800: Connection to lustre-OST0000 (at 192.168.206.112@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 424.928315] Lustre: lustre-OST0001-osc-ffff8a6791405800: disconnect after 25s idle [ 424.934225] Lustre: Skipped 1 previous similar message [ 427.421722] Lustre: lustre-OST0000-osc-ffff8a6791405800: Connection restored to 192.168.206.112@tcp (at 192.168.206.112@tcp) [ 439.927632] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 441.371429] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 451.023376] Lustre: DEBUG MARKER: == replay-single test 0c: check replay-barrier =========== 13:49:10 (1787852950) [ 457.650983] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 457.802789] Lustre: Unmounted lustre-client [ 495.184947] LustreError: lustre-MDT0000-mdc-ffff8a6791957800: operation mds_connect to node 192.168.206.112@tcp failed: rc = -16 [ 500.239552] LustreError: lustre-MDT0000-mdc-ffff8a6791957800: operation mds_connect to node 192.168.206.112@tcp failed: rc = -16 [ 505.331280] LustreError: lustre-MDT0000-mdc-ffff8a6791957800: operation mds_connect to node 192.168.206.112@tcp failed: rc = -16 [ 510.450730] LustreError: lustre-MDT0000-mdc-ffff8a6791957800: operation mds_connect to node 192.168.206.112@tcp failed: rc = -16 [ 515.586892] LustreError: lustre-MDT0000-mdc-ffff8a6791957800: operation mds_connect to node 192.168.206.112@tcp failed: rc = -16 [ 525.843061] LustreError: lustre-MDT0000-mdc-ffff8a6791957800: operation mds_connect to node 192.168.206.112@tcp failed: rc = -16 [ 525.850759] LustreError: Skipped 1 previous similar message [ 546.356070] LustreError: lustre-MDT0000-mdc-ffff8a6791957800: operation mds_connect to node 192.168.206.112@tcp failed: rc = -16 [ 546.390836] LustreError: Skipped 3 previous similar messages [ 566.806504] Lustre: Mounted lustre-client - version 2.17.57_85_gfc6b239 [ 575.664413] Lustre: DEBUG MARKER: == replay-single test 0d: expired recovery with no clients ========================================================== 13:51:15 (1787853075) [ 582.608511] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 582.748774] Lustre: Unmounted lustre-client [ 617.288844] LustreError: lustre-MDT0000-mdc-ffff8a6798030000: operation mds_connect to node 192.168.206.112@tcp failed: rc = -16 [ 617.294296] LustreError: Skipped 3 previous similar messages [ 684.025175] LustreError: lustre-MDT0000-mdc-ffff8a6798030000: operation mds_connect to node 192.168.206.112@tcp failed: rc = -16 [ 684.031363] LustreError: Skipped 12 previous similar messages [ 689.198959] Lustre: Mounted lustre-client - version 2.17.57_85_gfc6b239 [ 696.886614] Lustre: DEBUG MARKER: == replay-single test 1: simple create =================== 13:53:16 (1787853196) [ 704.461094] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 709.617551] Lustre: lustre-MDT0000-mdc-ffff8a6798030000: Connection to lustre-MDT0000 (at 192.168.206.112@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 724.895500] Lustre: 2392:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787853210/real 1787853210] req@ffff8a6791e5e940 x1874699278701824/t0(0) o400->MGC192.168.206.112@tcp@192.168.206.112@tcp:26/25 lens 224/224 e 0 to 1 dl 1787853226 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 724.947147] LustreError: MGC192.168.206.112@tcp: Connection to MGS (at 192.168.206.112@tcp) was lost; in progress operations using this service will fail [ 735.209370] Lustre: Evicted from MGS (at 192.168.206.112@tcp) after server handle changed from 0xfafcabacea5276c1 to 0xfafcabacea527a64 [ 735.222700] Lustre: MGC192.168.206.112@tcp: Connection restored to 192.168.206.112@tcp (at 192.168.206.112@tcp) [ 740.553101] Lustre: lustre-MDT0000-mdc-ffff8a6798030000: Connection restored to 192.168.206.112@tcp (at 192.168.206.112@tcp) [ 749.706555] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 751.554854] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 759.970859] Lustre: DEBUG MARKER: == replay-single test 2a: touch ========================== 13:54:19 (1787853259) [ 766.654378] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 773.113227] Lustre: lustre-MDT0000-mdc-ffff8a6798030000: Connection to lustre-MDT0000 (at 192.168.206.112@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 789.343468] Lustre: 2391:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787853274/real 1787853274] req@ffff8a6791e5d680 x1874699278714624/t0(0) o400->MGC192.168.206.112@tcp@192.168.206.112@tcp:26/25 lens 224/224 e 0 to 1 dl 1787853290 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 789.378122] LustreError: MGC192.168.206.112@tcp: Connection to MGS (at 192.168.206.112@tcp) was lost; in progress operations using this service will fail [ 799.595118] Lustre: Evicted from MGS (at 192.168.206.112@tcp) after server handle changed from 0xfafcabacea527a64 to 0xfafcabacea528061 [ 799.606620] Lustre: MGC192.168.206.112@tcp: Connection restored to 192.168.206.112@tcp (at 192.168.206.112@tcp) [ 802.522382] LustreError: 2390:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff8a6791f09e00 x1874699278713088/t21474836484(21474836484) o101->lustre-MDT0000-mdc-ffff8a6798030000@192.168.206.112@tcp:12/10 lens 592/608 e 0 to 0 dl 1787853319 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'touch.0' uid:0 gid:0 projid:0 [ 814.770520] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 816.502730] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 827.567289] Lustre: DEBUG MARKER: == replay-single test 2b: touch ========================== 13:55:26 (1787853326) [ 836.525653] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 840.678409] Lustre: lustre-MDT0000-mdc-ffff8a6798030000: Connection to lustre-MDT0000 (at 192.168.206.112@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 856.864322] Lustre: 2394:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787853341/real 1787853341] req@ffff8a6791e51a40 x1874699278729088/t0(0) o400->MGC192.168.206.112@tcp@192.168.206.112@tcp:26/25 lens 224/224 e 0 to 1 dl 1787853357 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 856.916277] LustreError: MGC192.168.206.112@tcp: Connection to MGS (at 192.168.206.112@tcp) was lost; in progress operations using this service will fail [ 867.317180] Lustre: Evicted from MGS (at 192.168.206.112@tcp) after server handle changed from 0xfafcabacea528061 to 0xfafcabacea5283da [ 867.339781] Lustre: MGC192.168.206.112@tcp: Connection restored to 192.168.206.112@tcp (at 192.168.206.112@tcp) [ 867.347705] Lustre: Skipped 1 previous similar message [ 868.472965] Lustre: 15184:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.206.112@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 874.657598] LustreError: 2390:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff8a6791f0b840 x1874699278728192/t25769803781(25769803781) o101->lustre-MDT0000-mdc-ffff8a6798030000@192.168.206.112@tcp:12/10 lens 592/608 e 0 to 0 dl 1787853391 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'touch.0' uid:0 gid:0 projid:0 [ 881.684178] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 883.667784] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 891.668231] Lustre: DEBUG MARKER: == replay-single test 2c: setstripe replay =============== 13:56:31 (1787853391) [ 898.795681] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 901.090629] Lustre: lustre-MDT0000-mdc-ffff8a6798030000: Connection to lustre-MDT0000 (at 192.168.206.112@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 917.471562] Lustre: 2394:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787853402/real 1787853402] req@ffff8a6791f0b840 x1874699278741888/t0(0) o400->MGC192.168.206.112@tcp@192.168.206.112@tcp:26/25 lens 224/224 e 0 to 1 dl 1787853418 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 917.497893] LustreError: MGC192.168.206.112@tcp: Connection to MGS (at 192.168.206.112@tcp) was lost; in progress operations using this service will fail [ 927.724945] Lustre: Evicted from MGS (at 192.168.206.112@tcp) after server handle changed from 0xfafcabacea5283da to 0xfafcabacea528913 [ 927.747777] Lustre: MGC192.168.206.112@tcp: Connection restored to 192.168.206.112@tcp (at 192.168.206.112@tcp) [ 927.762146] Lustre: Skipped 1 previous similar message [ 929.645566] Lustre: 15184:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.206.112@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 936.628128] LustreError: 2390:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff8a67888ec3c0 x1874699278740736/t30064771076(30064771076) o101->lustre-MDT0000-mdc-ffff8a6798030000@192.168.206.112@tcp:12/10 lens 536/608 e 0 to 0 dl 1787853453 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'lfs.0' uid:0 gid:0 projid:0 [ 944.461397] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 945.941288] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 953.929607] Lustre: DEBUG MARKER: == replay-single test 2d: setdirstripe replay ============ 13:57:33 (1787853453) [ 961.132926] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 963.556807] Lustre: lustre-MDT0000-mdc-ffff8a6798030000: Connection to lustre-MDT0000 (at 192.168.206.112@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 978.911889] Lustre: 2391:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787853464/real 1787853464] req@ffff8a6791e5f0c0 x1874699278754432/t0(0) o400->MGC192.168.206.112@tcp@192.168.206.112@tcp:26/25 lens 224/224 e 0 to 1 dl 1787853480 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 978.943201] LustreError: MGC192.168.206.112@tcp: Connection to MGS (at 192.168.206.112@tcp) was lost; in progress operations using this service will fail [ 989.156428] Lustre: Evicted from MGS (at 192.168.206.112@tcp) after server handle changed from 0xfafcabacea528913 to 0xfafcabacea528e37 [ 990.458479] Lustre: 15184:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.206.112@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 998.590136] Lustre: lustre-MDT0000-mdc-ffff8a6798030000: Connection restored to 192.168.206.112@tcp (at 192.168.206.112@tcp) [ 998.596794] Lustre: Skipped 2 previous similar messages [ 1007.659398] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1009.395746] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1018.150954] Lustre: DEBUG MARKER: == replay-single test 2e: O_CREAT|O_EXCL create replay === 13:58:37 (1787853517) [ 1027.434948] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1030.118352] Lustre: lustre-MDT0000-mdc-ffff8a6798030000: Connection to lustre-MDT0000 (at 192.168.206.112@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1035.743894] Lustre: 23276:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787853520/real 1787853520] req@ffff8a6791e5fc00 x1874699278765440/t0(0) o35->lustre-MDT0000-mdc-ffff8a6798030000@192.168.206.112@tcp:23/10 lens 392/624 e 0 to 1 dl 1787853536 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'openfile.0' uid:0 gid:0 projid:0 [ 1046.495970] LustreError: MGC192.168.206.112@tcp: Connection to MGS (at 192.168.206.112@tcp) was lost; in progress operations using this service will fail [ 1056.748507] Lustre: Evicted from MGS (at 192.168.206.112@tcp) after server handle changed from 0xfafcabacea528e37 to 0xfafcabacea529323 [ 1058.473894] Lustre: 15184:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.206.112@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 1073.423387] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1074.903996] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1082.724363] Lustre: DEBUG MARKER: == replay-single test 3a: replay failed open(O_DIRECTORY) ========================================================== 13:59:42 (1787853582) [ 1089.682105] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1107.935226] Lustre: 2393:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787853593/real 1787853593] req@ffff8a6791f08780 x1874699278781568/t0(0) o400->MGC192.168.206.112@tcp@192.168.206.112@tcp:26/25 lens 224/224 e 0 to 1 dl 1787853609 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1107.988054] Lustre: 2393:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 1107.995599] LustreError: MGC192.168.206.112@tcp: Connection to MGS (at 192.168.206.112@tcp) was lost; in progress operations using this service will fail [ 1118.186248] Lustre: Evicted from MGS (at 192.168.206.112@tcp) after server handle changed from 0xfafcabacea529323 to 0xfafcabacea529808 [ 1119.276731] Lustre: 15184:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.206.112@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 1127.615347] Lustre: lustre-MDT0000-mdc-ffff8a6798030000: Connection restored to 192.168.206.112@tcp (at 192.168.206.112@tcp) [ 1127.620682] Lustre: Skipped 3 previous similar messages [ 1134.472467] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1135.929515] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1144.841256] Lustre: DEBUG MARKER: == replay-single test 3b: replay failed open -ENOMEM ===== 14:00:44 (1787853644) [ 1153.034871] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1159.155176] Lustre: lustre-MDT0000-mdc-ffff8a6798030000: Connection to lustre-MDT0000 (at 192.168.206.112@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1159.174654] Lustre: Skipped 1 previous similar message [ 1175.519383] Lustre: 2393:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787853660/real 1787853660] req@ffff8a6791e50780 x1874699278795648/t0(0) o400->MGC192.168.206.112@tcp@192.168.206.112@tcp:26/25 lens 224/224 e 0 to 1 dl 1787853676 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1175.555790] LustreError: MGC192.168.206.112@tcp: Connection to MGS (at 192.168.206.112@tcp) was lost; in progress operations using this service will fail [ 1185.770810] Lustre: Evicted from MGS (at 192.168.206.112@tcp) after server handle changed from 0xfafcabacea529808 to 0xfafcabacea529e36 [ 1199.152983] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1200.525706] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1207.678649] Lustre: DEBUG MARKER: == replay-single test 3c: replay failed open -ENOMEM ===== 14:01:47 (1787853707) [ 1215.226994] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1259.959342] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1261.275727] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1268.537293] Lustre: DEBUG MARKER: == replay-single test 4a: |x| 10 open(O_CREAT)s ========== 14:02:48 (1787853768) [ 1274.920388] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1309.409099] LustreError: 2390:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff8a6791f09e00 x1874699278819456/t55834574851(55834574851) o101->lustre-MDT0000-mdc-ffff8a6798030000@192.168.206.112@tcp:12/10 lens 592/608 e 0 to 0 dl 1787853826 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'bash.0' uid:0 gid:0 projid:0 [ 1316.076914] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1317.276260] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1325.256918] Lustre: DEBUG MARKER: == replay-single test 4b: |x| rm 10 files ================ 14:03:45 (1787853825) [ 1332.853272] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1335.273887] Lustre: lustre-MDT0000-mdc-ffff8a6798030000: Connection to lustre-MDT0000 (at 192.168.206.112@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1335.295787] Lustre: Skipped 2 previous similar messages [ 1351.647973] Lustre: 2392:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787853836/real 1787853836] req@ffff8a6791e5e1c0 x1874699278862080/t0(0) o400->MGC192.168.206.112@tcp@192.168.206.112@tcp:26/25 lens 224/224 e 0 to 1 dl 1787853852 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1351.694513] Lustre: 2392:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 1351.703654] LustreError: MGC192.168.206.112@tcp: Connection to MGS (at 192.168.206.112@tcp) was lost; in progress operations using this service will fail [ 1351.719432] LustreError: Skipped 2 previous similar messages [ 1360.870075] Lustre: Evicted from MGS (at 192.168.206.112@tcp) after server handle changed from 0xfafcabacea52a9e3 to 0xfafcabacea52b416 [ 1360.876392] Lustre: Skipped 2 previous similar messages [ 1362.285547] Lustre: 15184:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.206.112@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 1380.541167] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1382.340493] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1391.283411] Lustre: DEBUG MARKER: == replay-single test 5: |x| 220 open(O_CREAT) =========== 14:04:51 (1787853891) [ 1399.614456] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1439.731422] Lustre: MGC192.168.206.112@tcp: Connection restored to 192.168.206.112@tcp (at 192.168.206.112@tcp) [ 1439.736650] Lustre: Skipped 8 previous similar messages [ 1445.581228] LustreError: 2390:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff8a6791e50b40 x1874699278876928/t64424509443(64424509443) o101->lustre-MDT0000-mdc-ffff8a6798030000@192.168.206.112@tcp:12/10 lens 592/608 e 0 to 0 dl 1787853962 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'bash.0' uid:0 gid:0 projid:0 [ 1445.612198] LustreError: 2390:0:(client.c:3448:ptlrpc_replay_interpret()) Skipped 9 previous similar messages [ 1454.784632] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1456.543832] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1479.538290] Lustre: DEBUG MARKER: == replay-single test 6a: mkdir + contained create ======= 14:06:19 (1787853979) [ 1487.134671] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1533.639673] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1535.442431] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1546.594911] Lustre: DEBUG MARKER: == replay-single test 6b: |X| rmdir ====================== 14:07:26 (1787854046) [ 1554.983944] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1603.460545] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1605.351342] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1615.750955] Lustre: DEBUG MARKER: == replay-single test 7: mkdir |X| contained create ====== 14:08:35 (1787854115) [ 1623.744340] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1627.128087] Lustre: lustre-MDT0000-mdc-ffff8a6798030000: Connection to lustre-MDT0000 (at 192.168.206.112@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1627.151871] Lustre: Skipped 3 previous similar messages [ 1643.487719] Lustre: 2394:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787854128/real 1787854128] req@ffff8a6783e4e1c0 x1874699279389056/t0(0) o400->MGC192.168.206.112@tcp@192.168.206.112@tcp:26/25 lens 224/224 e 0 to 1 dl 1787854144 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1643.511043] Lustre: 2394:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 1643.525289] LustreError: MGC192.168.206.112@tcp: Connection to MGS (at 192.168.206.112@tcp) was lost; in progress operations using this service will fail [ 1643.537656] LustreError: Skipped 3 previous similar messages [ 1653.745137] Lustre: Evicted from MGS (at 192.168.206.112@tcp) after server handle changed from 0xfafcabacea53556a to 0xfafcabacea535a87 [ 1653.760986] Lustre: Skipped 3 previous similar messages [ 1668.922496] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1671.093027] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1680.368971] Lustre: DEBUG MARKER: == replay-single test 8: creat open |X| close ============ 14:09:39 (1787854179) [ 1687.584964] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1718.061644] Lustre: 15184:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.206.112@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 1726.205056] LustreError: 2390:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff8a6783f90000 x1874699279404544/t81604378634(81604378634) o101->lustre-MDT0000-mdc-ffff8a6798030000@192.168.206.112@tcp:12/10 lens 664/608 e 0 to 0 dl 1787854243 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'multiop.0' uid:0 gid:0 projid:0 [ 1726.242030] LustreError: 2390:0:(client.c:3448:ptlrpc_replay_interpret()) Skipped 219 previous similar messages [ 1735.224749] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1736.884921] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1745.447564] Lustre: DEBUG MARKER: == replay-single test 9: |X| create (same inum/gen) ====== 14:10:44 (1787854244) [ 1753.215812] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1798.537769] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1800.344966] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1810.100791] Lustre: DEBUG MARKER: == replay-single test 10: create |X| rename unlink ======= 14:11:49 (1787854309) [ 1817.635733] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1865.712310] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1867.219565] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1875.807055] Lustre: DEBUG MARKER: == replay-single test 11: create open write rename |X| create-old-name read ========================================================== 14:12:55 (1787854375) [ 1884.186528] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1915.730597] Lustre: 15184:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.206.112@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 1923.250745] LustreError: 2390:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff8a6783fbf480 x1874699279448192/t94489280522(94489280522) o101->lustre-MDT0000-mdc-ffff8a6798030000@192.168.206.112@tcp:12/10 lens 592/608 e 0 to 0 dl 1787854440 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'bash.0' uid:0 gid:0 projid:0 [ 1930.334983] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1932.243592] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1940.244427] Lustre: DEBUG MARKER: == replay-single test 12: open, unlink |X| close ========= 14:14:00 (1787854440) [ 1948.528857] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1980.403742] Lustre: MGC192.168.206.112@tcp: Connection restored to 192.168.206.112@tcp (at 192.168.206.112@tcp) [ 1980.420311] Lustre: Skipped 15 previous similar messages [ 1980.438063] LustreError: 2390:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff8a6783fbc780 x1874699279448960/t94489280524(94489280524) o101->lustre-MDT0000-mdc-ffff8a6798030000@192.168.206.112@tcp:12/10 lens 576/608 e 0 to 0 dl 1787854497 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'grep.0' uid:0 gid:0 projid:0 [ 1980.484055] LustreError: 2390:0:(client.c:3448:ptlrpc_replay_interpret()) Skipped 1 previous similar message [ 1992.684972] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1994.201953] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2002.706145] Lustre: DEBUG MARKER: == replay-single test 13: open chmod 0 |x| write close === 14:15:01 (1787854501) [ 2010.763950] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2055.125187] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2056.569643] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2064.210526] Lustre: DEBUG MARKER: == replay-single test 14: open(O_CREAT), unlink |X| close ========================================================== 14:16:03 (1787854563) [ 2071.530723] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2100.909181] Lustre: 15184:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.206.112@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 2104.333515] LustreError: 2390:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff8a6783fbc780 x1874699279448960/t94489280524(94489280524) o101->lustre-MDT0000-mdc-ffff8a6798030000@192.168.206.112@tcp:12/10 lens 576/608 e 0 to 0 dl 1787854621 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'grep.0' uid:0 gid:0 projid:0 [ 2104.378049] LustreError: 2390:0:(client.c:3448:ptlrpc_replay_interpret()) Skipped 3 previous similar messages [ 2118.488555] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2119.938439] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2126.969977] Lustre: DEBUG MARKER: == replay-single test 15: open(O_CREAT), unlink |X| touch new, close ========================================================== 14:17:07 (1787854627) [ 2135.512532] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2140.157895] Lustre: lustre-MDT0000-mdc-ffff8a6798030000: Connection to lustre-MDT0000 (at 192.168.206.112@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 2140.176445] Lustre: Skipped 7 previous similar messages [ 2156.511576] Lustre: 2394:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787854641/real 1787854641] req@ffff8a6783e4ed00 x1874699279509632/t0(0) o400->MGC192.168.206.112@tcp@192.168.206.112@tcp:26/25 lens 224/224 e 0 to 1 dl 1787854657 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2156.530153] Lustre: 2394:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 7 previous similar messages [ 2156.534147] LustreError: MGC192.168.206.112@tcp: Connection to MGS (at 192.168.206.112@tcp) was lost; in progress operations using this service will fail [ 2156.539641] LustreError: Skipped 7 previous similar messages [ 2166.783649] Lustre: Evicted from MGS (at 192.168.206.112@tcp) after server handle changed from 0xfafcabacea538027 to 0xfafcabacea5386b0 [ 2166.806686] Lustre: Skipped 7 previous similar messages [ 2181.443665] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2183.278863] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2192.628871] Lustre: DEBUG MARKER: == replay-single test 16: |X| open(O_CREAT), unlink, touch new, unlink new ========================================================== 14:18:12 (1787854692) [ 2201.967632] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2235.285268] LustreError: 2390:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff8a6783fbc780 x1874699279448960/t94489280524(94489280524) o101->lustre-MDT0000-mdc-ffff8a6798030000@192.168.206.112@tcp:12/10 lens 576/608 e 0 to 0 dl 1787854752 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'grep.0' uid:0 gid:0 projid:0 [ 2235.306290] LustreError: 2390:0:(client.c:3448:ptlrpc_replay_interpret()) Skipped 4 previous similar messages [ 2247.398644] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2248.955630] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2257.188404] Lustre: DEBUG MARKER: == replay-single test 17: |X| open(O_CREAT), |replay| close ========================================================== 14:19:17 (1787854757) [ 2265.714484] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2311.509590] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2313.161841] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2321.255804] Lustre: DEBUG MARKER: == replay-single test 18: open(O_CREAT), unlink, touch new, close, touch, unlink ========================================================== 14:20:21 (1787854821) [ 2328.595384] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2371.110606] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2372.700202] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2380.149433] Lustre: DEBUG MARKER: == replay-single test 19: mcreate, open, write, rename === 14:21:20 (1787854880) [ 2387.026644] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2431.715765] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2433.527427] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2441.419623] Lustre: DEBUG MARKER: == replay-single test 20a: |X| open(O_CREAT), unlink, replay, close (test mds_cleanup_orphans) ========================================================== 14:22:21 (1787854941) [ 2448.736412] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2492.242680] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2493.529312] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2501.154608] Lustre: DEBUG MARKER: == replay-single test 20b: write, unlink, eviction, replay (test mds_cleanup_orphans) ========================================================== 14:23:21 (1787855001) [ 2507.688681] LustreError: lustre-MDT0000-mdc-ffff8a6798030000: operation mds_statfs to node 192.168.206.112@tcp failed: rc = -107 [ 2507.716980] LustreError: lustre-MDT0000-mdc-ffff8a6798030000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 2542.970158] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2544.351707] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2559.390690] Lustre: DEBUG MARKER: before 3156, after 3156 [ 2566.666237] Lustre: DEBUG MARKER: == replay-single test 20c: check that client eviction does not affect file content ========================================================== 14:24:26 (1787855066) [ 2570.497574] LustreError: lustre-MDT0000-mdc-ffff8a6798030000: operation mds_statfs to node 192.168.206.112@tcp failed: rc = -107 [ 2570.509769] LustreError: Skipped 1 previous similar message [ 2570.525718] LustreError: lustre-MDT0000-mdc-ffff8a6798030000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 2578.443381] Lustre: DEBUG MARKER: == replay-single test 21: |X| open(O_CREAT), unlink touch new, replay, close (test mds_cleanup_orphans) ========================================================== 14:24:37 (1787855077) [ 2587.069066] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2618.384838] Lustre: MGC192.168.206.112@tcp: Connection restored to 192.168.206.112@tcp (at 192.168.206.112@tcp) [ 2618.396577] Lustre: Skipped 21 previous similar messages [ 2623.173911] LustreError: 2390:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff8a6783fbc000 x1874699279691648/t141733920773(141733920773) o101->lustre-MDT0000-mdc-ffff8a6798030000@192.168.206.112@tcp:12/10 lens 592/608 e 0 to 0 dl 1787855140 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'multiop.0' uid:0 gid:0 projid:0 [ 2623.197982] LustreError: 2390:0:(client.c:3448:ptlrpc_replay_interpret()) Skipped 9 previous similar messages [ 2632.337517] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2633.878587] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2642.739479] Lustre: DEBUG MARKER: == replay-single test 22: open(O_CREAT), |X| unlink, replay, close (test mds_cleanup_orphans) ========================================================== 14:25:42 (1787855142) [ 2650.365638] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2694.794519] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2696.492869] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2704.623874] Lustre: DEBUG MARKER: == replay-single test 23: open(O_CREAT), |X| unlink touch new, replay, close (test mds_cleanup_orphans) ========================================================== 14:26:44 (1787855204) [ 2712.110545] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2756.708796] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2758.815817] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2766.723217] Lustre: DEBUG MARKER: == replay-single test 24: open(O_CREAT), replay, unlink, close (test mds_cleanup_orphans) ========================================================== 14:27:46 (1787855266) [ 2773.596216] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2779.110658] Lustre: lustre-MDT0000-mdc-ffff8a6798030000: Connection to lustre-MDT0000 (at 192.168.206.112@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 2779.134497] Lustre: Skipped 11 previous similar messages [ 2795.490316] Lustre: 2393:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787855280/real 1787855280] req@ffff8a6783f91e00 x1874699279737728/t0(0) o400->MGC192.168.206.112@tcp@192.168.206.112@tcp:26/25 lens 224/224 e 0 to 1 dl 1787855296 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2795.519305] Lustre: 2393:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 8 previous similar messages [ 2795.534261] LustreError: MGC192.168.206.112@tcp: Connection to MGS (at 192.168.206.112@tcp) was lost; in progress operations using this service will fail [ 2795.547427] LustreError: Skipped 9 previous similar messages [ 2805.747850] Lustre: Evicted from MGS (at 192.168.206.112@tcp) after server handle changed from 0xfafcabacea53b98c to 0xfafcabacea53bdd7 [ 2805.765045] Lustre: Skipped 9 previous similar messages [ 2820.869546] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2822.446801] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2830.433334] Lustre: DEBUG MARKER: == replay-single test 25: open(O_CREAT), unlink, replay, close (test mds_cleanup_orphans) ========================================================== 14:28:50 (1787855330) [ 2836.754194] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2882.368803] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2883.996805] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2892.337657] Lustre: DEBUG MARKER: == replay-single test 26: |X| open(O_CREAT), unlink two, close one, replay, close one (test mds_cleanup_orphans) ========================================================== 14:29:52 (1787855392) [ 2898.862447] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2946.010646] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2948.009671] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2956.783611] Lustre: DEBUG MARKER: == replay-single test 27: |X| open(O_CREAT), unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 14:30:56 (1787855456) [ 2963.301699] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3008.071249] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3009.695951] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3017.365487] Lustre: DEBUG MARKER: == replay-single test 28: open(O_CREAT), |X| unlink two, close one, replay, close one (test mds_cleanup_orphans) ========================================================== 14:31:57 (1787855517) [ 3025.363748] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3069.953548] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3071.649905] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3080.679905] Lustre: DEBUG MARKER: == replay-single test 29: open(O_CREAT), |X| unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 14:33:00 (1787855580) [ 3088.440480] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3118.768954] Lustre: 15184:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.206.112@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 3118.778264] Lustre: 15184:0:(mgc_request.c:1900:mgc_process_log()) Skipped 1 previous similar message [ 3135.715957] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3137.868765] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3147.609541] Lustre: DEBUG MARKER: == replay-single test 30: open(O_CREAT) two, unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 14:34:06 (1787855646) [ 3155.193409] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3186.029653] Lustre: 15184:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.206.112@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 3189.785068] LustreError: 2390:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff8a6783e4c3c0 x1874699279827840/t180388626437(180388626437) o101->lustre-MDT0000-mdc-ffff8a6798030000@192.168.206.112@tcp:12/10 lens 592/608 e 0 to 0 dl 1787855706 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'multiop.0' uid:0 gid:0 projid:0 [ 3189.815516] LustreError: 2390:0:(client.c:3448:ptlrpc_replay_interpret()) Skipped 15 previous similar messages [ 3203.448980] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3205.364134] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3215.387906] Lustre: DEBUG MARKER: == replay-single test 31: open(O_CREAT) two, unlink one, |X| unlink one, close two (test mds_cleanup_orphans) ========================================================== 14:35:14 (1787855714) [ 3224.650586] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3256.306085] Lustre: MGC192.168.206.112@tcp: Connection restored to 192.168.206.112@tcp (at 192.168.206.112@tcp) [ 3256.313538] Lustre: Skipped 19 previous similar messages [ 3270.630509] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3272.451729] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3281.351639] Lustre: DEBUG MARKER: == replay-single test 32: close() notices client eviction; close() after client eviction ========================================================== 14:36:21 (1787855781) [ 3283.948624] LustreError: lustre-MDT0000-mdc-ffff8a6798030000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 3290.232718] Lustre: DEBUG MARKER: == replay-single test 33a: fid seq shouldn't be reused after abort recovery ========================================================== 14:36:29 (1787855789) [ 3296.656721] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3314.683561] LustreError: lustre-MDT0000-mdc-ffff8a6798030000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 3340.889993] Lustre: DEBUG MARKER: == replay-single test 33b: test fid seq allocation ======= 14:37:20 (1787855840) [ 3350.684831] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3365.866234] LustreError: lustre-MDT0000-mdc-ffff8a6798030000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 3392.135272] Lustre: DEBUG MARKER: == replay-single test 34: abort recovery before client does replay (test mds_cleanup_orphans) ========================================================== 14:38:12 (1787855892) [ 3400.975892] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3406.833927] Lustre: lustre-MDT0000-mdc-ffff8a6798030000: Connection to lustre-MDT0000 (at 192.168.206.112@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 3406.853242] Lustre: Skipped 10 previous similar messages [ 3422.175239] Lustre: 2394:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787855907/real 1787855907] req@ffff8a6783e4fc00 x1874699279941888/t0(0) o400->MGC192.168.206.112@tcp@192.168.206.112@tcp:26/25 lens 224/224 e 0 to 1 dl 1787855923 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3422.184254] LustreError: MGC192.168.206.112@tcp: Connection to MGS (at 192.168.206.112@tcp) was lost; in progress operations using this service will fail [ 3422.199858] LustreError: lustre-MDT0000-mdc-ffff8a6798030000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 3422.214888] Lustre: 2394:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 7 previous similar messages [ 3422.234155] LustreError: Skipped 9 previous similar messages [ 3422.241299] Lustre: Evicted from MGS (at 192.168.206.112@tcp) after server handle changed from 0xfafcabacea53fd78 to 0xfafcabacea540a9f [ 3422.255445] Lustre: Skipped 9 previous similar messages [ 3445.327130] Lustre: DEBUG MARKER: == replay-single test 35: test recovery from llog for unlink op ========================================================== 14:39:04 (1787855944) [ 3463.149360] LustreError: lustre-MDT0000-mdc-ffff8a6798030000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 3483.113435] Lustre: DEBUG MARKER: SKIP: replay-single test_36 skipping ALWAYS excluded test 36 [ 3484.968697] Lustre: DEBUG MARKER: == replay-single test 37: abort recovery before client does replay (test mds_cleanup_orphans for directories) ========================================================== 14:39:44 (1787855984) [ 3493.730088] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3510.867243] LustreError: lustre-MDT0000-mdc-ffff8a6798030000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 3536.138621] Lustre: DEBUG MARKER: == replay-single test 38: test recovery from unlink llog (test llog_gen_rec) ========================================================== 14:40:36 (1787856036) [ 3574.734201] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3623.683842] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3625.531405] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3649.659401] Lustre: DEBUG MARKER: == replay-single test 39: test recovery from unlink llog (test llog_gen_rec) ========================================================== 14:42:28 (1787856148) [ 3679.226414] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3738.020798] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3740.191981] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3762.561651] Lustre: DEBUG MARKER: == replay-single test 41: read from a valid osc while other oscs are invalid ========================================================== 14:44:22 (1787856262) [ 3771.735486] Lustre: DEBUG MARKER: == replay-single test 42: recovery after ost failure ===== 14:44:31 (1787856271) [ 3800.632355] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-OST0000 [ 3907.465357] Lustre: DEBUG MARKER: == replay-single test 43: mds osc import failure during recovery; don't LBUG ========================================================== 14:46:46 (1787856406) [ 3917.309645] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3948.527962] Lustre: MGC192.168.206.112@tcp: Connection restored to 192.168.206.112@tcp (at 192.168.206.112@tcp) [ 3948.534849] Lustre: Skipped 16 previous similar messages [ 3949.612899] Lustre: 15184:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.206.112@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 3966.060905] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3967.681565] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3986.431064] Lustre: DEBUG MARKER: == replay-single test 44a: race in target handle connect ========================================================== 14:48:06 (1787856486) [ 4013.861712] Lustre: lustre-MDT0000-mdc-ffff8a6798030000: Connection to lustre-MDT0000 (at 192.168.206.112@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 4013.914849] Lustre: Skipped 9 previous similar messages [ 4073.768716] Lustre: DEBUG MARKER: == replay-single test 44b: race in target handle connect ========================================================== 14:49:33 (1787856573) [ 4095.993405] LustreError: 92310:0:(lmv_obd.c:1471:lmv_statfs()) lustre-MDT0000-mdc-ffff8a6798030000: can't stat MDS #0: rc = -114 [ 4118.507763] LustreError: 92333:0:(lmv_obd.c:1471:lmv_statfs()) lustre-MDT0000-mdc-ffff8a6798030000: can't stat MDS #0: rc = -114 [ 4141.554817] LustreError: 92355:0:(lmv_obd.c:1471:lmv_statfs()) lustre-MDT0000-mdc-ffff8a6798030000: can't stat MDS #0: rc = -114 [ 4164.593762] LustreError: 92377:0:(lmv_obd.c:1471:lmv_statfs()) lustre-MDT0000-mdc-ffff8a6798030000: can't stat MDS #0: rc = -114 [ 4188.137960] LustreError: 92400:0:(lmv_obd.c:1471:lmv_statfs()) lustre-MDT0000-mdc-ffff8a6798030000: can't stat MDS #0: rc = -114 [ 4211.198568] LustreError: 92422:0:(lmv_obd.c:1471:lmv_statfs()) lustre-MDT0000-mdc-ffff8a6798030000: can't stat MDS #0: rc = -114 [ 4233.271677] LustreError: 92445:0:(lmv_obd.c:1471:lmv_statfs()) lustre-MDT0000-mdc-ffff8a6798030000: can't stat MDS #0: rc = -114 [ 4278.533961] LustreError: 92489:0:(lmv_obd.c:1471:lmv_statfs()) lustre-MDT0000-mdc-ffff8a6798030000: can't stat MDS #0: rc = -114 [ 4278.563753] LustreError: 92489:0:(lmv_obd.c:1471:lmv_statfs()) Skipped 1 previous similar message [ 4307.564691] Lustre: DEBUG MARKER: == replay-single test 44c: race in target handle connect ========================================================== 14:53:27 (1787856807) [ 4314.178415] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4331.001234] LustreError: MGC192.168.206.112@tcp: Connection to MGS (at 192.168.206.112@tcp) was lost; in progress operations using this service will fail [ 4331.003538] LustreError: lustre-MDT0000-mdc-ffff8a6798030000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 4331.014887] LustreError: Skipped 5 previous similar messages [ 4331.036331] Lustre: Evicted from MGS (at 192.168.206.112@tcp) after server handle changed from 0xfafcabacea58336a to 0xfafcabacea5845ed [ 4331.042174] Lustre: Skipped 5 previous similar messages [ 4368.251896] Lustre: 15184:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.206.112@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 4389.174448] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4390.730957] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4400.881271] Lustre: DEBUG MARKER: == replay-single test 45: Handle failed close ============ 14:54:59 (1787856899) [ 4401.193390] Lustre: setting import lustre-MDT0000_UUID INACTIVE by administrator request [ 4401.213413] LustreError: 95059:0:(file.c:251:ll_close_inode_openhandle()) lustre-clilmv-ffff8a6798030000: inode [0x20001a9e1:0x1:0x0] mdc close failed: rc = -108 [ 4401.251966] LustreError: lustre-MDT0000-mdc-ffff8a6798030000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 4408.026477] Lustre: DEBUG MARKER: == replay-single test 46: Don't leak file handle after open resend (3325) ========================================================== 14:55:07 (1787856907) [ 4425.184144] Lustre: 95651:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787856910/real 1787856910] req@ffff8a6785d25680 x1874699282697856/t0(0) o700->lustre-MDT0000-mdc-ffff8a6798030000@192.168.206.112@tcp:30/10 lens 264/248 e 0 to 1 dl 1787856926 ref 2 fl Rpc:XQr/200/ffffffff rc 0/-1 job:'touch.0' uid:0 gid:0 projid:4294967295 [ 4425.219881] Lustre: 95651:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 4 previous similar messages [ 4460.986302] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4462.515849] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4471.954304] Lustre: DEBUG MARKER: == replay-single test 47: MDS->OSC failure during precreate cleanup (2824) ========================================================== 14:56:11 (1787856971) [ 4507.030168] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 4509.000482] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4583.962232] Lustre: DEBUG MARKER: == replay-single test 48: MDS->OSC failure during precreate cleanup (2824) ========================================================== 14:58:03 (1787857083) [ 4592.126879] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4624.872195] Lustre: MGC192.168.206.112@tcp: Connection restored to 192.168.206.112@tcp (at 192.168.206.112@tcp) [ 4624.885020] Lustre: Skipped 21 previous similar messages [ 4631.243463] LustreError: 2390:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff8a6784916d00 x1874699282761984/t236223201383(236223201383) o101->lustre-MDT0000-mdc-ffff8a6798030000@192.168.206.112@tcp:12/10 lens 592/608 e 0 to 0 dl 1787857192 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'createmany.0' uid:0 gid:0 projid:0 [ 4631.268993] LustreError: 2390:0:(client.c:3448:ptlrpc_replay_interpret()) Skipped 3 previous similar messages [ 4702.703367] Lustre: DEBUG MARKER: == replay-single test 50: Double OSC recovery, don't LASSERT (3812) ========================================================== 15:00:02 (1787857202) [ 4717.204565] Lustre: DEBUG MARKER: == replay-single test 52: time out lock replay (3764) ==== 15:00:17 (1787857217) [ 4724.206916] Lustre: lustre-MDT0000-mdc-ffff8a6798030000: Connection to lustre-MDT0000 (at 192.168.206.112@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 4724.222581] Lustre: Skipped 15 previous similar messages [ 4741.053715] Lustre: 15184:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.206.112@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 4816.282645] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4818.481606] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4828.130732] Lustre: DEBUG MARKER: == replay-single test 53a: |X| close request while two MDC requests in flight ========================================================== 15:02:07 (1787857327) [ 4838.217348] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4883.350296] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4885.026531] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4895.030449] Lustre: DEBUG MARKER: == replay-single test 53b: |X| open request while two MDC requests in flight ========================================================== 15:03:14 (1787857394) [ 4905.479186] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4935.140938] Lustre: Evicted from MGS (at 192.168.206.112@tcp) after server handle changed from 0xfafcabacea587a27 to 0xfafcabacea587f60 [ 4935.151024] Lustre: Skipped 5 previous similar messages [ 4950.323979] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4952.159977] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4961.448609] Lustre: DEBUG MARKER: == replay-single test 53c: |X| open request and close request while two MDC requests in flight ========================================================== 15:04:21 (1787857461) [ 4971.320112] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4994.527540] LustreError: MGC192.168.206.112@tcp: Connection to MGS (at 192.168.206.112@tcp) was lost; in progress operations using this service will fail [ 4994.543824] LustreError: Skipped 6 previous similar messages [ 5021.660746] Lustre: DEBUG MARKER: == replay-single test 53d: close reply while two MDC requests in flight ========================================================== 15:05:21 (1787857521) [ 5040.095740] Lustre: 105577:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787857525/real 1787857525] req@ffff8a6785cd6580 x1874699282887040/t0(0) o35->lustre-MDT0000-mdc-ffff8a6798030000@192.168.206.112@tcp:23/10 lens 392/624 e 0 to 1 dl 1787857541 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'multiop.0' uid:0 gid:0 projid:0 [ 5040.149185] Lustre: 105577:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 8 previous similar messages [ 5069.762857] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5071.390191] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5080.518326] Lustre: DEBUG MARKER: == replay-single test 53e: |X| open reply while two MDC requests in flight ========================================================== 15:06:20 (1787857580) [ 5092.532123] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5138.591552] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5140.221582] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5148.880339] Lustre: DEBUG MARKER: == replay-single test 53f: |X| open reply and close reply while two MDC requests in flight ========================================================== 15:07:28 (1787857648) [ 5159.784426] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5207.060629] Lustre: DEBUG MARKER: == replay-single test 53g: |X| drop open reply and close request while close and open are both in flight ========================================================== 15:08:26 (1787857706) [ 5218.455222] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5246.456538] Lustre: MGC192.168.206.112@tcp: Connection restored to 192.168.206.112@tcp (at 192.168.206.112@tcp) [ 5246.464779] Lustre: Skipped 15 previous similar messages [ 5248.233629] Lustre: 15184:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.206.112@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 5268.047252] Lustre: DEBUG MARKER: == replay-single test 53h: open request and close reply while two MDC requests in flight ========================================================== 15:09:27 (1787857767) [ 5279.596453] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5325.447638] Lustre: DEBUG MARKER: == replay-single test 55: let MDS_CHECK_RESENT return the original return code instead of 0 ========================================================== 15:10:25 (1787857825) [ 5386.207324] Lustre: lustre-MDT0000-mdc-ffff8a6798030000: Connection to lustre-MDT0000 (at 192.168.206.112@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 5386.230089] Lustre: Skipped 8 previous similar messages [ 5393.722528] Lustre: DEBUG MARKER: == replay-single test 56: don't replay a symlink open request (3440) ========================================================== 15:11:33 (1787857893) [ 5402.042899] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5448.903448] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5450.717536] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5471.447348] Lustre: DEBUG MARKER: == replay-single test 57: test recovery from llog for setattr op ========================================================== 15:12:50 (1787857970) [ 5480.904505] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5526.143375] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5527.671225] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5548.415619] Lustre: DEBUG MARKER: == replay-single test 58a: test recovery from llog for setattr op (test llog_gen_rec) ========================================================== 15:14:08 (1787858048) [ 5591.883209] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5610.465973] LustreError: MGC192.168.206.112@tcp: Connection to MGS (at 192.168.206.112@tcp) was lost; in progress operations using this service will fail [ 5610.486703] LustreError: Skipped 7 previous similar messages [ 5620.658060] Lustre: Evicted from MGS (at 192.168.206.112@tcp) after server handle changed from 0xfafcabacea58b116 to 0xfafcabacea5a0c22 [ 5620.675507] Lustre: Skipped 8 previous similar messages [ 5621.871558] Lustre: 15184:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.206.112@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 5638.718251] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5640.597894] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5693.014575] Lustre: DEBUG MARKER: == replay-single test 58b: test replay of setxattr op ==== 15:16:32 (1787858192) [ 5694.420529] Lustre: Mounted lustre-client - version 2.17.57_85_gfc6b239 [ 5702.741845] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5725.155483] Lustre: 2391:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787858210/real 1787858210] req@ffff8a6791fffc00 x1874699285736320/t0(0) o400->MGC192.168.206.112@tcp@192.168.206.112@tcp:26/25 lens 224/224 e 0 to 1 dl 1787858226 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5725.201535] Lustre: 2391:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 12 previous similar messages [ 5748.720626] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5750.393875] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5754.694113] Lustre: Unmounted lustre-client [ 5760.865808] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount FULL mgc.*.mgs_server_uuid 1475 0 [ 5762.366681] Lustre: DEBUG MARKER: mgc.*.mgs_server_uuid in FULL state after 0 sec [ 5769.099983] Lustre: DEBUG MARKER: == replay-single test 58c: resend/reconstruct setxattr op ========================================================== 15:17:48 (1787858268) [ 5775.736714] Lustre: Mounted lustre-client - version 2.17.57_85_gfc6b239 [ 5900.276830] Lustre: lustre-MDT0000-mdc-ffff8a6798030000: Connection restored to 192.168.206.112@tcp (at 192.168.206.112@tcp) [ 5900.287433] Lustre: Skipped 14 previous similar messages [ 5904.183169] Lustre: Unmounted lustre-client [ 5910.266550] Lustre: DEBUG MARKER: SKIP: replay-single test_59 skipping ALWAYS excluded test 59 [ 5911.770862] Lustre: DEBUG MARKER: == replay-single test 60: test llog post recovery init vs llog unlink ========================================================== 15:20:11 (1787858411) [ 5925.608250] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5959.399700] Lustre: 15184:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.206.112@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 5973.830728] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5975.389478] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5985.871201] Lustre: DEBUG MARKER: == replay-single test 61a: test race llog recovery vs llog cleanup ========================================================== 15:21:25 (1787858485) [ 6009.538070] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-OST0000 [ 6102.140142] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 6104.023776] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 6143.891088] Lustre: DEBUG MARKER: == replay-single test 61b: test race mds llog sync vs llog cleanup ========================================================== 15:24:03 (1787858643) [ 6151.144288] Lustre: lustre-MDT0000-mdc-ffff8a6798030000: Connection to lustre-MDT0000 (at 192.168.206.112@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 6151.163734] Lustre: Skipped 8 previous similar messages [ 6227.421444] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6229.184441] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6239.031720] Lustre: DEBUG MARKER: == replay-single test 61c: test race mds llog sync vs llog cleanup ========================================================== 15:25:38 (1787858738) [ 6289.539763] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 6291.832275] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 6303.414794] Lustre: DEBUG MARKER: == replay-single test 61d: error in llog_setup should cleanup the llog context correctly ========================================================== 15:26:43 (1787858803) [ 6326.255410] LustreError: MGC192.168.206.112@tcp: Connection to MGS (at 192.168.206.112@tcp) was lost; in progress operations using this service will fail [ 6326.275384] LustreError: Skipped 4 previous similar messages [ 6326.290887] Lustre: Evicted from MGS (at 192.168.206.112@tcp) after server handle changed from 0xfafcabacea5e0043 to 0xfafcabacea5e06c5 [ 6326.304576] Lustre: Skipped 4 previous similar messages [ 6338.831748] Lustre: DEBUG MARKER: == replay-single test 62: don't mis-drop resent replay === 15:27:18 (1787858838) [ 6347.530153] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 6367.203826] Lustre: 2391:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787858852/real 1787858852] req@ffff8a67851d83c0 x1874699286648960/t0(0) o400->MGC192.168.206.112@tcp@192.168.206.112@tcp:26/25 lens 224/224 e 0 to 1 dl 1787858868 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6367.252581] Lustre: 2391:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 4 previous similar messages [ 6379.258770] Lustre: 15184:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.206.112@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 6441.951506] LustreError: 2390:0:(client.c:3398:ptlrpc_replay_interpret()) @@@ request replay timed out req@ffff8a6787806580 x1874699286633984/t313532612610(313532612610) o36->lustre-MDT0000-mdc-ffff8a6798030000@192.168.206.112@tcp:12/10 lens 528/448 e 0 to 1 dl 1787858943 ref 2 fl Interpret:EXQU/204/ffffffff rc -110/-1 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 6442.107621] LustreError: 2390:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff8a67888ec780 x1874699286636288/t313532612612(313532612612) o101->lustre-MDT0000-mdc-ffff8a6798030000@192.168.206.112@tcp:12/10 lens 592/608 e 0 to 0 dl 1787859003 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'createmany.0' uid:0 gid:0 projid:0 [ 6442.139229] LustreError: 2390:0:(client.c:3448:ptlrpc_replay_interpret()) Skipped 19 previous similar messages [ 6448.730125] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6450.415620] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6460.277451] Lustre: DEBUG MARKER: == replay-single test 65a: AT: verify early replies ====== 15:29:20 (1787858960) [ 6518.728419] Lustre: DEBUG MARKER: == replay-single test 65b: AT: verify early replies on packed reply / bulk ========================================================== 15:30:18 (1787859018) [ 6569.164760] Lustre: DEBUG MARKER: == replay-single test 66a: AT: verify MDT service time adjusts with no early replies ========================================================== 15:31:09 (1787859069) [ 6635.449512] Lustre: DEBUG MARKER: == replay-single test 66b: AT: verify net latency adjusts ========================================================== 15:32:15 (1787859135) [ 6662.149733] LustreError: 132039:0:(client.c:1694:after_reply()) cfs_fail_timeout id 50c sleeping for 10000ms [ 6672.247130] LustreError: 132039:0:(client.c:1694:after_reply()) cfs_fail_timeout id 50c awake [ 6672.270086] LustreError: 132039:0:(client.c:1694:after_reply()) cfs_fail_timeout id 50c sleeping for 10000ms [ 6682.287257] LustreError: 132039:0:(client.c:1694:after_reply()) cfs_fail_timeout id 50c awake [ 6682.304931] LustreError: 132039:0:(client.c:1694:after_reply()) cfs_fail_timeout id 50c sleeping for 10000ms [ 6689.762074] LustreError: 2391:0:(client.c:1694:after_reply()) cfs_fail_timeout id 50c sleeping for 10000ms [ 6692.407432] LustreError: 132039:0:(client.c:1694:after_reply()) cfs_fail_timeout id 50c awake [ 6699.775244] LustreError: 2391:0:(client.c:1694:after_reply()) cfs_fail_timeout id 50c awake [ 6699.788363] LustreError: 2391:0:(client.c:1694:after_reply()) cfs_fail_timeout id 50c sleeping for 10000ms [ 6699.804169] LustreError: 2391:0:(client.c:1694:after_reply()) Skipped 1 previous similar message [ 6709.815158] LustreError: 2391:0:(client.c:1694:after_reply()) cfs_fail_timeout id 50c awake [ 6709.824331] LustreError: 2391:0:(client.c:1694:after_reply()) Skipped 1 previous similar message [ 6712.631263] LustreError: 132039:0:(client.c:1694:after_reply()) cfs_fail_timeout id 50c sleeping for 10000ms [ 6712.641803] LustreError: 132039:0:(client.c:1694:after_reply()) Skipped 1 previous similar message [ 6722.664643] LustreError: 132039:0:(client.c:1694:after_reply()) cfs_fail_timeout id 50c awake [ 6722.674723] LustreError: 132039:0:(client.c:1694:after_reply()) Skipped 1 previous similar message [ 6731.847553] Lustre: DEBUG MARKER: == replay-single test 67a: AT: verify slow request processing doesn't induce reconnects ========================================================== 15:33:51 (1787859231) [ 6814.765469] Lustre: DEBUG MARKER: == replay-single test 67b: AT: verify instant slowdown doesn't induce reconnects ========================================================== 15:35:14 (1787859314) [ 6850.798705] Lustre: DEBUG MARKER: phase 2 [ 6860.180575] Lustre: DEBUG MARKER: == replay-single test 68: AT: verify slowing locks ======= 15:35:59 (1787859359) [ 6892.096774] LustreError: 33489:0:(ldlm_request.c:1533:ldlm_cli_cancel_req()) cfs_fail_timeout id 312 sleeping for 19000ms [ 6911.175773] LustreError: 33489:0:(ldlm_request.c:1533:ldlm_cli_cancel_req()) cfs_fail_timeout id 312 awake [ 6946.602149] Lustre: DEBUG MARKER: == replay-single test 70a: check multi client t-f ======== 15:37:25 (1787859445) [ 6948.128577] Lustre: DEBUG MARKER: SKIP: replay-single test_70a Need two or more clients, have 1 [ 6950.083863] Lustre: DEBUG MARKER: == replay-single test 70b: dbench 2mdts recovery; 1 clients ========================================================== 15:37:29 (1787859449) [ 6955.019945] Lustre: DEBUG MARKER: Started rundbench load pid=135370 ... [ 6965.678314] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 6968.639252] Lustre: DEBUG MARKER: test_70b fail mds1 1 times [ 6970.863551] LustreError: lustre-MDT0000-mdc-ffff8a6798030000: operation ldlm_enqueue to node 192.168.206.112@tcp failed: rc = -19 [ 6970.884834] Lustre: lustre-MDT0000-mdc-ffff8a6798030000: Connection to lustre-MDT0000 (at 192.168.206.112@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 6970.911464] Lustre: Skipped 4 previous similar messages [ 6987.744068] Lustre: 2392:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787859472/real 1787859472] req@ffff8a678784d2c0 x1874699287079040/t0(0) o400->MGC192.168.206.112@tcp@192.168.206.112@tcp:26/25 lens 224/224 e 0 to 1 dl 1787859488 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6987.781582] Lustre: 2392:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 6987.791535] LustreError: MGC192.168.206.112@tcp: Connection to MGS (at 192.168.206.112@tcp) was lost; in progress operations using this service will fail [ 6987.804257] LustreError: Skipped 1 previous similar message [ 6996.982875] Lustre: Evicted from MGS (at 192.168.206.112@tcp) after server handle changed from 0xfafcabacea5e0d0f to 0xfafcabacea5e7f5b [ 6996.995122] Lustre: Skipped 1 previous similar message [ 6996.999830] Lustre: MGC192.168.206.112@tcp: Connection restored to 192.168.206.112@tcp (at 192.168.206.112@tcp) [ 6997.006152] Lustre: Skipped 10 previous similar messages [ 6998.576271] Lustre: 15184:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.206.112@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 7000.765604] LustreError: 2390:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff8a678781a940 x1874699286852608/t317827580263(317827580263) o101->lustre-MDT0000-mdc-ffff8a6798030000@192.168.206.112@tcp:12/10 lens 576/608 e 0 to 0 dl 1787859517 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'dbench.0' uid:0 gid:0 projid:0 [ 7000.798925] LustreError: 2390:0:(client.c:3448:ptlrpc_replay_interpret()) Skipped 24 previous similar messages [ 7012.974521] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 7015.756401] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7030.717815] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 7033.414911] Lustre: DEBUG MARKER: test_70b fail mds2 2 times [ 7080.345580] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 7082.458614] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7110.022386] Lustre: DEBUG MARKER: == replay-single test 70c: tar 2mdts recovery ============ 15:40:09 (1787859609) [ 7239.075857] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 7250.897978] Lustre: DEBUG MARKER: test_70c fail mds2 1 times [ 7254.283846] LustreError: lustre-MDT0001-mdc-ffff8a6798030000: operation mds_reint to node 192.168.206.112@tcp failed: rc = -107 [ 7289.046548] LustreError: 2390:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff8a6787819680 x1874699291591936/t8589938521(8589938521) o101->lustre-MDT0001-mdc-ffff8a6798030000@192.168.206.112@tcp:12/10 lens 600/608 e 0 to 0 dl 1787859806 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'tar.0' uid:0 gid:0 projid:0 [ 7289.079835] LustreError: 2390:0:(client.c:3448:ptlrpc_replay_interpret()) Skipped 27 previous similar messages [ 7300.952790] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 7302.680198] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7369.594289] Lustre: DEBUG MARKER: == replay-single test 70d: mkdir/rmdir striped dir 2mdts recovery ========================================================== 15:44:29 (1787859869) [ 7498.944502] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 7510.466750] Lustre: DEBUG MARKER: test_70d fail mds2 1 times [ 7513.590920] LustreError: lustre-MDT0001-mdc-ffff8a6798030000: operation mds_reint to node 192.168.206.112@tcp failed: rc = -107 [ 7537.439280] LustreError: 2390:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff8a6794e8e1c0 x1874699293530880/t12884903960(12884903960) o101->lustre-MDT0001-mdc-ffff8a6798030000@192.168.206.112@tcp:12/10 lens 648/608 e 0 to 0 dl 1787860054 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'lfs.0' uid:0 gid:0 projid:0 [ 7537.472188] LustreError: 2390:0:(client.c:3448:ptlrpc_replay_interpret()) Skipped 63 previous similar messages [ 7547.915104] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 7549.595678] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7557.598348] Lustre: DEBUG MARKER: == replay-single test 70e: rename cross-MDT with random fails ========================================================== 15:47:37 (1787860057) [ 7688.587403] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 7699.965776] Lustre: DEBUG MARKER: test_70e fail mds2 1 times [ 7706.602460] Lustre: lustre-MDT0001-mdc-ffff8a6798030000: Connection to lustre-MDT0001 (at 192.168.206.112@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 7706.611485] Lustre: Skipped 3 previous similar messages [ 7727.107155] LustreError: 2390:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff8a6794e8e1c0 x1874699293530880/t12884903960(12884903960) o101->lustre-MDT0001-mdc-ffff8a6798030000@192.168.206.112@tcp:12/10 lens 648/608 e 0 to 0 dl 1787860244 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'lfs.0' uid:0 gid:0 projid:0 [ 7727.126950] LustreError: 2390:0:(client.c:3448:ptlrpc_replay_interpret()) Skipped 21 previous similar messages [ 7730.901366] Lustre: lustre-MDT0001-mdc-ffff8a6798030000: Connection restored to 192.168.206.112@tcp (at 192.168.206.112@tcp) [ 7730.909788] Lustre: Skipped 4 previous similar messages [ 7740.340949] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 7742.226495] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7750.374774] Lustre: DEBUG MARKER: == replay-single test 70f: OSS O_DIRECT recovery with 1 clients ========================================================== 15:50:50 (1787860250) [ 7762.292248] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-OST0000 [ 7764.838957] Lustre: DEBUG MARKER: test_70f failing OST 1 times [ 7773.663154] Lustre: 2393:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787860258/real 1787860258] req@ffff8a67984bad00 x1874699298551808/t0(0) o4->lustre-OST0000-osc-ffff8a6798030000@192.168.206.112@tcp:6/4 lens 488/448 e 0 to 1 dl 1787860274 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'dd.0' uid:0 gid:0 projid:0 [ 7806.526539] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 7808.256098] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 7818.861830] Lustre: DEBUG MARKER: == replay-single test 71a: mkdir/rmdir striped dir with 2 mdts recovery ========================================================== 15:51:58 (1787860318) [ 7947.196939] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 7954.798147] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 7966.277410] Lustre: DEBUG MARKER: fail mds1 mds2 1 times [ 7969.061643] LustreError: lustre-MDT0000-mdc-ffff8a6798030000: operation mds_reint to node 192.168.206.112@tcp failed: rc = -19 [ 7987.936162] LustreError: MGC192.168.206.112@tcp: Connection to MGS (at 192.168.206.112@tcp) was lost; in progress operations using this service will fail [ 7998.380871] Lustre: Evicted from MGS (at 192.168.206.112@tcp) after server handle changed from 0xfafcabacea5e7f5b to 0xfafcabacea708661 [ 7999.540275] Lustre: 15184:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.206.112@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 8032.242108] LustreError: 2390:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff8a67984bb840 x1874699298657408/t322122566489(322122566489) o101->lustre-MDT0000-mdc-ffff8a6798030000@192.168.206.112@tcp:12/10 lens 520/664 e 0 to 0 dl 1787860549 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'lfs.0' uid:0 gid:0 projid:0 [ 8046.460962] Lustre: DEBUG MARKER: oleg612-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 [ 8048.006524] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8049.677767] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8057.919756] Lustre: DEBUG MARKER: == replay-single test 73a: open(O_CREAT), unlink, replay, reconnect before open replay, close ========================================================== 15:55:57 (1787860557) [ 8064.844382] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 8115.679196] LustreError: 2390:0:(client.c:3398:ptlrpc_replay_interpret()) @@@ request replay timed out req@ffff8a67984bb840 x1874699298657408/t322122566489(322122566489) o101->lustre-MDT0000-mdc-ffff8a6798030000@192.168.206.112@tcp:12/10 lens 520/664 e 0 to 1 dl 1787860616 ref 2 fl Interpret:EXPQU/604/ffffffff rc -110/-1 job:'lfs.0' uid:0 gid:0 projid:0 [ 8122.125975] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 8123.715803] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8132.274154] Lustre: DEBUG MARKER: == replay-single test 73b: open(O_CREAT), unlink, replay, reconnect at open_replay reply, close ========================================================== 15:57:11 (1787860631) [ 8139.716300] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 8187.871537] LustreError: 2390:0:(client.c:3398:ptlrpc_replay_interpret()) @@@ request replay timed out req@ffff8a67984bb840 x1874699298657408/t322122566489(322122566489) o101->lustre-MDT0000-mdc-ffff8a6798030000@192.168.206.112@tcp:12/10 lens 520/664 e 0 to 1 dl 1787860689 ref 2 fl Interpret:EXPQU/604/ffffffff rc -110/-1 job:'lfs.0' uid:0 gid:0 projid:0 [ 8194.040609] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 8195.607260] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8203.517877] Lustre: DEBUG MARKER: == replay-single test 74: Ensure applications don't fail waiting for OST recovery ========================================================== 15:58:23 (1787860703) [ 8205.985633] Lustre: Unmounted lustre-client [ 8238.095256] Lustre: Mounted lustre-client - version 2.17.57_85_gfc6b239 [ 8244.957522] LustreError: lustre-OST0000-osc-ffff8a67908f3800: operation ost_connect to node 192.168.206.112@tcp failed: rc = -16 [ 8262.154241] Lustre: DEBUG MARKER: == replay-single test 80a: DNE: create remote dir, drop update rep from MDT0, fail MDT0 ========================================================== 15:59:22 (1787860762) [ 8270.425935] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 8315.640627] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 8318.138370] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8329.000409] Lustre: DEBUG MARKER: == replay-single test 80b: DNE: create remote dir, drop update rep from MDT0, fail MDT1 ========================================================== 16:00:28 (1787860828) [ 8339.972326] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 8349.196725] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 8353.784747] Lustre: lustre-MDT0001-mdc-ffff8a67908f3800: Connection to lustre-MDT0001 (at 192.168.206.112@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 8353.809099] Lustre: Skipped 6 previous similar messages [ 8382.124764] Lustre: lustre-MDT0001-mdc-ffff8a67908f3800: Connection restored to 192.168.206.112@tcp (at 192.168.206.112@tcp) [ 8382.140746] Lustre: Skipped 9 previous similar messages [ 8391.346409] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 8393.116610] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8403.108477] Lustre: DEBUG MARKER: == replay-single test 80c: DNE: create remote dir, drop update rep from MDT1, fail MDT[0,1] ========================================================== 16:01:42 (1787860902) [ 8412.033646] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 8420.451430] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 8440.799194] Lustre: 2392:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787860925/real 1787860925] req@ffff8a67849912c0 x1874699300488960/t0(0) o400->MGC192.168.206.112@tcp@192.168.206.112@tcp:26/25 lens 224/224 e 0 to 1 dl 1787860941 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 8440.828842] Lustre: 2392:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 10 previous similar messages [ 8465.660744] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 8467.323615] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8507.716398] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 8509.229557] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8518.039274] Lustre: DEBUG MARKER: == replay-single test 80d: DNE: create remote dir, drop update rep from MDT1, fail 2 MDTs ========================================================== 16:03:38 (1787861018) [ 8529.893590] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 8538.607559] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 8607.420589] Lustre: DEBUG MARKER: oleg612-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 [ 8608.973572] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8610.593717] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8619.353687] Lustre: DEBUG MARKER: == replay-single test 80e: DNE: create remote dir, drop MDT1 rep, fail MDT0 ========================================================== 16:05:19 (1787861119) [ 8631.218307] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 8652.255320] LustreError: MGC192.168.206.112@tcp: Connection to MGS (at 192.168.206.112@tcp) was lost; in progress operations using this service will fail [ 8652.271656] LustreError: Skipped 5 previous similar messages [ 8662.507573] Lustre: Evicted from MGS (at 192.168.206.112@tcp) after server handle changed from 0xfafcabacea711e23 to 0xfafcabacea712c4d [ 8662.531297] Lustre: Skipped 5 previous similar messages [ 8676.824713] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 8678.345663] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8687.749620] Lustre: DEBUG MARKER: == replay-single test 80f: DNE: create remote dir, drop MDT1 rep, fail MDT1 ========================================================== 16:06:27 (1787861187) [ 8697.173820] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 8739.138244] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 8741.200838] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8750.321979] Lustre: DEBUG MARKER: == replay-single test 80g: DNE: create remote dir, drop MDT1 rep, fail MDT0, then MDT1 ========================================================== 16:07:29 (1787861249) [ 8762.232188] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 8769.258392] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 8800.363828] Lustre: 161563:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.206.112@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 8800.373024] Lustre: 161563:0:(mgc_request.c:1900:mgc_process_log()) Skipped 2 previous similar messages [ 8817.249560] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 8818.612862] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8861.819900] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 8864.203828] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8873.738783] Lustre: DEBUG MARKER: == replay-single test 80h: DNE: create remote dir, drop MDT1 rep, fail 2 MDTs ========================================================== 16:09:33 (1787861373) [ 8885.177991] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 8891.826187] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 8943.069891] Lustre: DEBUG MARKER: oleg612-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 [ 8944.969243] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8947.202389] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8957.580219] Lustre: DEBUG MARKER: == replay-single test 81a: DNE: unlink remote dir, drop MDT0 update rep, fail MDT1 ========================================================== 16:10:57 (1787861457) [ 8967.348625] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 8969.377144] LustreError: lustre-MDT0001-mdc-ffff8a67908f3800: operation mds_reint to node 192.168.206.112@tcp failed: rc = -19 [ 8969.397361] LustreError: Skipped 1 previous similar message [ 8969.400841] Lustre: lustre-MDT0001-mdc-ffff8a67908f3800: Connection to lustre-MDT0001 (at 192.168.206.112@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 8969.430572] Lustre: Skipped 13 previous similar messages [ 9004.207447] Lustre: lustre-MDT0001-mdc-ffff8a67908f3800: Connection restored to 192.168.206.112@tcp (at 192.168.206.112@tcp) [ 9004.214049] Lustre: Skipped 18 previous similar messages [ 9013.687517] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 9015.429335] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 9023.316521] Lustre: DEBUG MARKER: == replay-single test 81b: DNE: unlink remote dir, drop MDT0 update reply, fail MDT0 ========================================================== 16:12:03 (1787861523) [ 9031.526310] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 9052.649877] Lustre: 2392:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787861537/real 1787861537] req@ffff8a678347a940 x1874699300732672/t0(0) o400->MGC192.168.206.112@tcp@192.168.206.112@tcp:26/25 lens 224/224 e 0 to 1 dl 1787861553 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 9052.722609] Lustre: 2392:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 14 previous similar messages [ 9075.319660] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 9076.663639] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 9085.404620] Lustre: DEBUG MARKER: == replay-single test 81c: DNE: unlink remote dir, drop MDT0 update reply, fail MDT0,MDT1 ========================================================== 16:13:05 (1787861585) [ 9094.876414] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 9102.089963] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 9151.172301] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 9153.821303] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 9195.161619] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 9196.631949] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 9204.904532] Lustre: DEBUG MARKER: == replay-single test 81d: DNE: unlink remote dir, drop MDT0 update reply, fail 2 MDTs ========================================================== 16:15:04 (1787861704) [ 9212.743622] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 9219.564274] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 9225.188989] LustreError: lustre-MDT0001-mdc-ffff8a67908f3800: operation mds_reint to node 192.168.206.112@tcp failed: rc = -19 [ 9266.087380] Lustre: Evicted from MGS (at 192.168.206.112@tcp) after server handle changed from 0xfafcabacea716e2c to 0xfafcabacea7176ad [ 9266.099158] Lustre: Skipped 4 previous similar messages [ 9286.445864] Lustre: DEBUG MARKER: oleg612-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 [ 9287.878894] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 9289.331922] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 9297.293590] Lustre: DEBUG MARKER: == replay-single test 81e: DNE: unlink remote dir, drop MDT1 req reply, fail MDT0 ========================================================== 16:16:37 (1787861797) [ 9307.529830] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 9327.071303] LustreError: MGC192.168.206.112@tcp: Connection to MGS (at 192.168.206.112@tcp) was lost; in progress operations using this service will fail [ 9327.080130] LustreError: Skipped 5 previous similar messages [ 9350.419315] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 9352.141661] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 9360.533677] Lustre: DEBUG MARKER: == replay-single test 81f: DNE: unlink remote dir, drop MDT1 req reply, fail MDT1 ========================================================== 16:17:40 (1787861860) [ 9370.975493] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 9409.816385] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 9411.365903] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 9419.541565] Lustre: DEBUG MARKER: == replay-single test 81g: DNE: unlink remote dir, drop req reply, fail M0, then M1 ========================================================== 16:18:39 (1787861919) [ 9427.972478] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 9434.853439] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 9483.009509] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 9484.854483] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 9535.121126] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 9537.250690] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 9547.028562] Lustre: DEBUG MARKER: == replay-single test 81h: DNE: unlink remote dir, drop request reply, fail 2 MDTs ========================================================== 16:20:46 (1787862046) [ 9556.414540] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 9565.342338] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 9590.757716] Lustre: lustre-MDT0001-mdc-ffff8a67908f3800: Connection to lustre-MDT0001 (at 192.168.206.112@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 9590.779315] Lustre: Skipped 13 previous similar messages [ 9610.282552] Lustre: MGC192.168.206.112@tcp: Connection restored to 192.168.206.112@tcp (at 192.168.206.112@tcp) [ 9610.292952] Lustre: Skipped 17 previous similar messages [ 9611.832559] Lustre: 161563:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.206.112@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 9611.861782] Lustre: 161563:0:(mgc_request.c:1900:mgc_process_log()) Skipped 1 previous similar message [ 9643.447956] Lustre: DEBUG MARKER: oleg612-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 [ 9645.291894] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 9647.010422] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 9656.722322] Lustre: DEBUG MARKER: == replay-single test 84a: stale open during export disconnect ========================================================== 16:22:36 (1787862156) [ 9659.903852] LustreError: lustre-MDT0000-mdc-ffff8a67908f3800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 9666.790887] Lustre: DEBUG MARKER: == replay-single test 85a: check the cancellation of unused locks during recovery(IBITS) ========================================================== 16:22:46 (1787862166) [ 9704.023896] LustreError: 2390:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff8a6791989a40 x1874699300862336/t390842023944(390842023944) o101->lustre-MDT0000-mdc-ffff8a67908f3800@192.168.206.112@tcp:12/10 lens 576/608 e 0 to 0 dl 1787862221 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'grep.0' uid:0 gid:0 projid:0 [ 9704.041078] LustreError: 2390:0:(client.c:3448:ptlrpc_replay_interpret()) Skipped 5 previous similar messages [ 9716.589777] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 9718.242850] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 9726.329605] Lustre: DEBUG MARKER: == replay-single test 85b: check the cancellation of unused locks during recovery(EXTENT) ========================================================== 16:23:46 (1787862226) [ 9780.355553] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 9781.881160] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 9791.884972] Lustre: DEBUG MARKER: == replay-single test 86: umount server after clear nid_stats should not hit LBUG ========================================================== 16:24:51 (1787862291) [ 9795.226153] Lustre: Unmounted lustre-client [ 9816.059135] Lustre: Mounted lustre-client - version 2.17.57_85_gfc6b239 [ 9824.275876] Lustre: DEBUG MARKER: == replay-single test 87a: write replay ================== 16:25:23 (1787862323) [ 9835.474464] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-OST0000 [ 9877.893214] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 9879.318503] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 9888.322746] Lustre: DEBUG MARKER: == replay-single test 87b: write replay with changed data (checksum resend) ========================================================== 16:26:27 (1787862387) [ 9896.621415] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-OST0000 [ 9944.226499] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 9946.010834] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 9954.085341] Lustre: DEBUG MARKER: == replay-single test 88: MDS should not assign same objid to different files ========================================================== 16:27:34 (1787862454) [ 9962.042507] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-OST0000 [ 9969.049597] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 9996.257900] Lustre: 2393:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787862481/real 1787862481] req@ffff8a6791fcd2c0 x1874699301337984/t0(0) o400->MGC192.168.206.112@tcp@192.168.206.112@tcp:26/25 lens 224/224 e 0 to 1 dl 1787862497 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 9996.285729] Lustre: 2393:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 15 previous similar messages [ 9996.296047] LustreError: MGC192.168.206.112@tcp: Connection to MGS (at 192.168.206.112@tcp) was lost; in progress operations using this service will fail [ 9996.310263] LustreError: Skipped 3 previous similar messages [10006.509822] Lustre: Evicted from MGS (at 192.168.206.112@tcp) after server handle changed from 0xfafcabacea71f93e to 0xfafcabacea720649 [10006.518209] Lustre: Skipped 4 previous similar messages [10006.530663] LustreError: 2390:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff8a679367cb40 x1874699301293056/t399431958545(399431958545) o101->lustre-MDT0000-mdc-ffff8a6785157000@192.168.206.112@tcp:12/10 lens 576/608 e 0 to 0 dl 1787862523 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'md5sum.0' uid:0 gid:0 projid:0 [10006.566780] LustreError: 2390:0:(client.c:3448:ptlrpc_replay_interpret()) Skipped 99 previous similar messages [10058.729600] Lustre: DEBUG MARKER: == replay-single test 89: no disk space leak on late ost connection ========================================================== 16:29:18 (1787862558) [10095.585312] LustreError: 2390:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff8a679367cb40 x1874699301293056/t399431958545(399431958545) o101->lustre-MDT0000-mdc-ffff8a6785157000@192.168.206.112@tcp:12/10 lens 576/608 e 0 to 0 dl 1787862612 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'md5sum.0' uid:0 gid:0 projid:0 [10095.627259] LustreError: 2390:0:(client.c:3448:ptlrpc_replay_interpret()) Skipped 40 previous similar messages [10102.827332] Lustre: Unmounted lustre-client [10118.553896] Lustre: Mounted lustre-client - version 2.17.57_85_gfc6b239 [10118.567647] LustreError: lustre-OST0000-osc-ffff8a6786702800: operation ost_connect to node 192.168.206.112@tcp failed: rc = -16 [10123.796815] LustreError: lustre-OST0000-osc-ffff8a6786702800: operation ost_connect to node 192.168.206.112@tcp failed: rc = -16 [10128.893770] LustreError: lustre-OST0000-osc-ffff8a6786702800: operation ost_connect to node 192.168.206.112@tcp failed: rc = -16 [10139.149268] LustreError: lustre-OST0000-osc-ffff8a6786702800: operation ost_connect to node 192.168.206.112@tcp failed: rc = -16 [10139.165465] LustreError: Skipped 1 previous similar message [10159.641901] LustreError: lustre-OST0000-osc-ffff8a6786702800: operation ost_connect to node 192.168.206.112@tcp failed: rc = -16 [10159.664286] LustreError: Skipped 3 previous similar messages [10187.280693] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 59 sec [10198.119399] Lustre: DEBUG MARKER: free_before: 7646268 free_after: 7646268 [10204.807412] Lustre: DEBUG MARKER: == replay-single test 90: lfs find identifies the missing striped file segments ========================================================== 16:31:44 (1787862704) [10210.789227] Lustre: lustre-OST0000-osc-ffff8a6786702800: Connection to lustre-OST0000 (at 192.168.206.112@tcp) was lost; in progress operations using this service will wait for recovery to complete [10210.806161] Lustre: Skipped 9 previous similar messages [10231.440813] Lustre: lustre-OST0000-osc-ffff8a6786702800: Connection restored to 192.168.206.112@tcp (at 192.168.206.112@tcp) [10231.453366] Lustre: Skipped 12 previous similar messages [10248.332484] Lustre: DEBUG MARKER: == replay-single test 93a: replay + reconnect ============ 16:32:28 (1787862748) [10253.805774] LustreError: lustre-OST0000-osc-ffff8a6786702800: operation ost_write to node 192.168.206.112@tcp failed: rc = -107 [10253.822325] LustreError: Skipped 4 previous similar messages [10323.257873] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [10324.909787] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [10332.989191] Lustre: DEBUG MARKER: == replay-single test 93b: replay + reconnect on mds ===== 16:33:52 (1787862832) [10366.640400] Lustre: 202107:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.206.112@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [10366.661446] Lustre: 202107:0:(mgc_request.c:1900:mgc_process_log()) Skipped 1 previous similar message [10459.922718] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [10461.465359] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [10470.553667] Lustre: DEBUG MARKER: == replay-single test complete, duration 10189 sec ======= 16:36:10 (1787862970) [10472.052116] Lustre: DEBUG MARKER: === replay-single: start cleanup 16:36:11 (1787862971) === [10484.364119] Lustre: DEBUG MARKER: === replay-single: finish cleanup 16:36:23 (1787862983) === [10545.119620] Lustre: DEBUG MARKER: oleg612-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [10546.774479] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [10551.370788] Lustre: Unmounted lustre-client [10608.670914] Key type lgssc unregistered [10608.994801] LNet: 209531:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [10609.007196] LNetError: 209531:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [10609.044659] LNet: Removed LNI 192.168.206.12@tcp [10610.168157] Key type .llcrypt unregistered [10610.170120] Key type ._llcrypt unregistered