[ 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 454734843 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2400.000 MHz processor [ 0.000000] last_pfn = 0x146e00 max_arch_pfn = 0x400000000 [ 0.000000] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT [ 0.000000] last_pfn = 0xbffda max_arch_pfn = 0x400000000 [ 0.000000] found SMP MP-table at [mem 0x000f54d0-0x000f54df] [ 0.000000] RAMDISK: [mem 0xbcc64000-0xbffcffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F52F0 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE2464 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE2300 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 0022C0 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE2374 000090 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE2404 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE243C 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe2300-0xbffe2373] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe22ff] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe2374-0xbffe2403] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe2404-0xbffe243b] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe243c-0xbffe2463] [ 0.000000] No NUMA configuration found [ 0.000000] Faking a node at [mem 0x0000000000000000-0x0000000146dfffff] [ 0.000000] NODE_DATA(0) allocated [mem 0x1465a3000-0x1465cdfff] [ 0.000000] Reserving 256MB of memory at 2752MB for crashkernel (System RAM: 4205MB) [ 0.000000] Zone ranges: [ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.000000] DMA32 [mem 0x0000000001000000-0x00000000ffffffff] [ 0.000000] Normal [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Device empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff] [ 0.000000] node 0: [mem 0x0000000000100000-0x00000000bffd9fff] [ 0.000000] node 0: [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Zeroed struct page in unavailable ranges: 4744 pages [ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x0000000146dfffff] [ 0.000000] ACPI: PM-Timer IO Port: 0x608 [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) [ 0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) [ 0.000000] Using ACPI (MADT) for SMP configuration information [ 0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000] TSC deadline timer available [ 0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs [ 0.000000] kvm-guest: KVM setup pv remote TLB flush [ 0.000000] kvm-guest: setup PV sched yield [ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff] [ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff] [ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff] [ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff] [ 0.000000] PM: Registered nosave memory: [mem 0xbffda000-0xbfffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xc0000000-0xfeffbfff] [ 0.000000] PM: Registered nosave memory: [mem 0xfeffc000-0xfeffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xff000000-0xfffbffff] [ 0.000000] PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff] [ 0.000000] [mem 0xc0000000-0xfeffbfff] available for PCI devices [ 0.000000] Booting paravirtualized kernel on KVM [ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns [ 0.000000] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1 [ 0.000000] percpu: Embedded 63 pages/cpu s221184 r8192 d28672 u524288 [ 0.000000] kvm-guest: PV spinlocks enabled [ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1059618 [ 0.000000] Policy zone: Normal [ 0.000000] Kernel command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] Specific versions of hardware are certified with Red Hat Enterprise Linux 8. Please see the list of hardware certified with Red Hat Enterprise Linux 8 at https://catalog.redhat.com. [ 0.000000] audit: disabled (until reboot) [ 0.000000] software IO TLB: area num 4. [ 0.000000] Memory: 2829700K/4306400K available (18435K kernel code, 11221K rwdata, 7248K rodata, 2908K init, 18040K bss, 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.001011] APIC: Switch to symmetric I/O mode setup [ 0.003248] x2apic enabled [ 0.004008] Switched APIC routing to physical x2apic. [ 0.005014] kvm-guest: setup PV IPIs [ 0.008000] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.008000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x22983777dd9, max_idle_ns: 440795300422 ns [ 0.008022] Calibrating delay loop (skipped) preset value.. 4800.00 BogoMIPS (lpj=2400000) [ 0.009012] pid_max: default: 32768 minimum: 301 [ 0.010125] LSM: Security Framework initializing [ 0.011055] Yama: becoming mindful. [ 0.012035] SELinux: Initializing. [ 0.014006] *** VALIDATE selinux *** [ 0.022562] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.027329] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.028149] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.029114] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.030123] *** VALIDATE tmpfs *** [ 0.031481] *** VALIDATE proc *** [ 0.033157] *** VALIDATE cgroup *** [ 0.034011] *** VALIDATE cgroup2 *** [ 0.036202] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.038108] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.039010] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.040033] Spectre V2 : User space: Vulnerable [ 0.041010] Speculative Store Bypass: Vulnerable [ 0.043404] debug: unmapping init [mem 0xffffffffa7c59000-0xffffffffa7c60fff] [ 0.045746] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.046582] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.047022] ... version: 2 [ 0.048010] ... bit width: 48 [ 0.049016] ... generic registers: 4 [ 0.050010] ... value mask: 0000ffffffffffff [ 0.051011] ... max period: 00007fffffffffff [ 0.052011] ... fixed-purpose events: 3 [ 0.053010] ... event mask: 000000070000000f [ 0.054301] rcu: Hierarchical SRCU implementation. [ 0.056305] smp: Bringing up secondary CPUs ... [ 0.057516] x86: Booting SMP configuration: [ 0.058020] .... node #0, CPUs: #1 #2 #3 [ 0.061389] smp: Brought up 1 node, 4 CPUs [ 0.063011] smpboot: Max logical packages: 1 [ 0.064017] smpboot: Total of 4 processors activated (19200.00 BogoMIPS) [ 0.201236] node 0 deferred pages initialised in 134ms [ 0.205452] devtmpfs: initialized [ 0.207252] x86/mm: Memory block size: 128MB [ 0.210545] gcov: version magic: 0x41383552 [ 0.213308] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.215065] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.218294] pinctrl core: initialized pinctrl subsystem [ 0.220165] [ 0.220811] ************************************************************* [ 0.222011] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.224010] ** ** [ 0.227012] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.229011] ** ** [ 0.232013] ** This means that this kernel is built to expose internal ** [ 0.235010] ** IOMMU data structures, which may compromise security on ** [ 0.237011] ** your system. ** [ 0.239013] ** ** [ 0.242014] ** If you see this message and you are not debugging the ** [ 0.244011] ** kernel, report this immediately to your vendor! ** [ 0.247012] ** ** [ 0.249010] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.251013] ************************************************************* [ 0.254720] NET: Registered protocol family 16 [ 0.256410] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.259059] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.262058] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.266127] cpuidle: using governor menu [ 0.269052] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.272706] PCI: Using configuration type 1 for base access [ 0.275162] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.285173] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.288057] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.292082] cryptd: max_cpu_qlen set to 1000 [ 0.295275] ACPI: Added _OSI(Module Device) [ 0.297016] ACPI: Added _OSI(Processor Device) [ 0.299023] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.301022] ACPI: Added _OSI(Processor Aggregator Device) [ 0.306787] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.315339] ACPI: Interpreter enabled [ 0.317096] ACPI: PM: (supports S0 S3 S4 S5) [ 0.319016] ACPI: Using IOAPIC for interrupt routing [ 0.321165] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.324456] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.335278] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.337040] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.340019] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.344080] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.349397] acpiphp: Slot [2] registered [ 0.352147] acpiphp: Slot [5] registered [ 0.353143] acpiphp: Slot [6] registered [ 0.355211] acpiphp: Slot [3] registered [ 0.357143] acpiphp: Slot [4] registered [ 0.359166] acpiphp: Slot [7] registered [ 0.361159] acpiphp: Slot [8] registered [ 0.363137] acpiphp: Slot [9] registered [ 0.365130] acpiphp: Slot [10] registered [ 0.366131] acpiphp: Slot [11] registered [ 0.368155] acpiphp: Slot [12] registered [ 0.370139] acpiphp: Slot [13] registered [ 0.371172] acpiphp: Slot [14] registered [ 0.373158] acpiphp: Slot [15] registered [ 0.374123] acpiphp: Slot [16] registered [ 0.376121] acpiphp: Slot [17] registered [ 0.378138] acpiphp: Slot [18] registered [ 0.379147] acpiphp: Slot [19] registered [ 0.382215] acpiphp: Slot [20] registered [ 0.384138] acpiphp: Slot [21] registered [ 0.386104] acpiphp: Slot [22] registered [ 0.387117] acpiphp: Slot [23] registered [ 0.389115] acpiphp: Slot [24] registered [ 0.391206] acpiphp: Slot [25] registered [ 0.392093] acpiphp: Slot [26] registered [ 0.394102] acpiphp: Slot [27] registered [ 0.395108] acpiphp: Slot [28] registered [ 0.397130] acpiphp: Slot [29] registered [ 0.399098] acpiphp: Slot [30] registered [ 0.400125] acpiphp: Slot [31] registered [ 0.402060] PCI host bridge to bus 0000:00 [ 0.403021] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.406023] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.408027] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.411025] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.414024] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.417032] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.419228] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.422107] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.425405] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.434560] pci 0000:00:01.1: reg 0x20: [io 0xc120-0xc12f] [ 0.439015] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.442032] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.445026] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.448025] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.451514] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.453862] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.457045] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.460962] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.467014] pci 0000:00:02.0: reg 0x10: [io 0xc100-0xc11f] [ 0.477730] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.482025] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.488924] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.498016] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.506015] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.517015] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.528000] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.535012] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.544015] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.563015] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.573459] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.576409] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.578427] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.581529] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.584268] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.590090] iommu: Default domain type: Passthrough [ 0.592460] SCSI subsystem initialized [ 0.594143] ACPI: bus type USB registered [ 0.596115] usbcore: registered new interface driver usbfs [ 0.598077] usbcore: registered new interface driver hub [ 0.600077] usbcore: registered new device driver usb [ 0.602165] pps_core: LinuxPPS API ver. 1 registered [ 0.606013] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.609056] PTP clock support registered [ 0.611115] EDAC MC: Ver: 3.0.0 [ 0.614123] PCI: Using ACPI for IRQ routing [ 0.616802] NetLabel: Initializing [ 0.618010] NetLabel: domain hash size = 128 [ 0.619008] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.621070] NetLabel: unlabeled traffic allowed by default [ 0.623127] vgaarb: loaded [ 0.624238] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.626014] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.633265] clocksource: Switched to clocksource kvm-clock [ 0.733943] VFS: Disk quotas dquot_6.6.0 [ 0.736121] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.738697] *** VALIDATE ramfs *** [ 0.740049] *** VALIDATE hugetlbfs *** [ 0.741628] pnp: PnP ACPI init [ 0.744123] pnp: PnP ACPI: found 6 devices [ 0.759433] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.762786] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.765071] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.767291] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.769678] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.772226] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.775552] NET: Registered protocol family 2 [ 0.778930] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.785129] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.789346] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.794988] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.799124] TCP: Hash tables configured (established 65536 bind 65536) [ 0.802084] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.805876] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.808994] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.812557] NET: Registered protocol family 1 [ 0.816028] RPC: Registered named UNIX socket transport module. [ 0.818071] RPC: Registered udp transport module. [ 0.819743] RPC: Registered tcp transport module. [ 0.821508] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.823929] NET: Registered protocol family 44 [ 0.825506] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.828025] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.830304] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.832786] PCI: CLS 0 bytes, default 64 [ 0.834256] Unpacking initramfs... [ 2.227932] debug: unmapping init [mem 0xffff946c7cc64000-0xffff946c7ffcffff] [ 2.232039] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.234136] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.237073] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x22983777dd9, max_idle_ns: 440795300422 ns [ 2.767274] Initialise system trusted keyrings [ 2.769093] Key type blacklist registered [ 2.771208] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.780179] zbud: loaded [ 2.783106] *** VALIDATE nfs *** [ 2.784115] *** VALIDATE nfs4 *** [ 2.785418] pstore: using deflate compression [ 2.790140] Platform Keyring initialized [ 2.899351] NET: Registered protocol family 38 [ 2.900715] Key type asymmetric registered [ 2.902153] Asymmetric key parser 'x509' registered [ 2.904311] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 2.908161] io scheduler mq-deadline registered [ 2.910183] io scheduler kyber registered [ 2.912185] io scheduler bfq registered [ 2.914408] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 2.917412] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 2.920154] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 2.923771] ACPI: Power Button [PWRF] [ 2.929738] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 2.938424] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 2.962701] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 2.992370] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.023445] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.028808] Non-volatile memory driver v1.3 [ 3.030695] Linux agpgart interface v0.103 [ 3.065097] virtio_blk virtio1: [vda] 149968 512-byte logical blocks (76.8 MB/73.2 MiB) [ 3.068407] vda: detected capacity change from 0 to 76783616 [ 3.087363] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.091629] vdb: detected capacity change from 0 to 1073741824 [ 3.099674] libphy: Fixed MDIO Bus: probed [ 3.114820] usbcore: registered new interface driver usbserial_generic [ 3.117986] usbserial: USB Serial support registered for generic [ 3.120178] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.124566] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.126671] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.129460] mousedev: PS/2 mouse device common for all mice [ 3.133085] rtc_cmos 00:05: RTC can wake from S4 [ 3.136098] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.138279] rtc_cmos 00:05: registered as rtc0 [ 3.143048] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.143163] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.147155] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.149960] intel_pstate: CPU model not supported [ 3.156864] hid: raw HID events driver (C) Jiri Kosina [ 3.160282] usbcore: registered new interface driver usbhid [ 3.162992] usbhid: USB HID core driver [ 3.165306] drop_monitor: Initializing network drop monitor service [ 3.168501] Initializing XFRM netlink socket [ 3.171617] NET: Registered protocol family 10 [ 3.175232] Segment Routing with IPv6 [ 3.176761] NET: Registered protocol family 17 [ 3.179038] mpls_gso: MPLS GSO support [ 3.185411] RAS: Correctable Errors collector initialized. [ 3.187184] AVX version of gcm_enc/dec engaged. [ 3.188856] AES CTR mode by8 optimization enabled [ 3.269821] sched_clock: Marking stable (3269801511, 0)->(4146553381, -876751870) [ 3.273975] registered taskstats version 1 [ 3.275791] Loading compiled-in X.509 certificates [ 3.277958] zswap: loaded using pool lzo/zbud [ 3.302818] Key type big_key registered [ 3.314648] Key type encrypted registered [ 3.316771] ima: No TPM chip found, activating TPM-bypass! [ 3.319472] ima: Allocated hash algorithm: sha1 [ 3.321310] ima: No architecture policies found [ 3.323206] evm: Initialising EVM extended attributes: [ 3.324535] evm: security.selinux [ 3.325403] evm: security.ima [ 3.326317] evm: security.capability [ 3.327799] evm: HMAC attrs: 0x1 [ 3.330303] rtc_cmos 00:05: setting system clock to 2026-09-30 16:26:14 UTC (1790785574) [ 3.337519] debug: unmapping init [mem 0xffffffffa8c03000-0xffffffffa8dfffff] [ 3.340543] debug: unmapping init [mem 0xffffffffa7982000-0xffffffffa7c58fff] [ 3.348273] Write protecting the kernel read-only data: 28672k [ 3.351627] debug: unmapping init [mem 0xffffffffa6003000-0xffffffffa61fffff] [ 3.354398] debug: unmapping init [mem 0xffffffffa6914000-0xffffffffa69fffff] [ 3.382872] 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.391098] systemd[1]: Detected virtualization kvm. [ 3.393279] systemd[1]: Detected architecture x86-64. [ 3.395392] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.423798] systemd[1]: No hostname configured. [ 3.425741] systemd[1]: Set hostname to . [ 3.428518] random: systemd: uninitialized urandom read (16 bytes read) [ 3.431823] systemd[1]: Initializing machine ID from random generator. [ 3.465454] random: ln: uninitialized urandom read (6 bytes read) [ 3.563477] random: systemd: uninitialized urandom read (16 bytes read) [ 3.565891] systemd[1]: Reached target Local File Systems. [ OK ] Reached target Local File Systems. [ 3.570441] systemd[1]: Reached target Timers. [ OK ] Reached target Timers. [ 3.574378] systemd[1]: Reached target Initrd Root Device. [ OK ] Reached target Initrd Root Device. [ OK ] Listening on udev Control Socket. [ OK ] Listening on udev Kernel Socket. [ OK ] Listening on Journal Socket. Starting Apply Kernel Variables... Starting Setup Virtual Console... Starting Create Volatile Files and Directories... [ OK ] Reached target Swap. [ OK ] Listening on Journal Socket (/dev/log). Starting Journal Service... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Paths. [ OK ] Reached target Sockets. [ OK ] Started Memstrack Anylazing Service. [ OK ] Reached target Slices. [ OK ] Reached target Local Encrypted Volumes. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Started Apply Kernel Variables. [ OK ] Started Setup Virtual Console. [ OK ] Started Create Volatile Files and Directories. [ 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.226154] device-mapper: uevent: version 1.0.3 [ 4.228914] 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...[ 4.563288] random: fast init done [ 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.035906] virtio_net virtio0 ens2: renamed from eth0 [ 5.095881] scsi host0: ata_piix [ 5.140811] scsi host1: ata_piix [ 5.142572] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc120 irq 14 [ 5.145154] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc128 irq 15 [ 9.309539] dracut-initqueue[590]: RTNETLINK answers: File exists [ 9.833889] random: crng init done [ 9.835470] 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.177258] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped target Timers. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Slices. [ OK ] Stopped target Sockets. [ OK ] Stopped target System Initialization. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped target Swap. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. Stopping udev Kernel Device Manager... [ OK ] Stopped target Paths. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ 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 Kernel Socket. [ OK ] Closed udev Control Socket. Starting Cleanup udevd DB... [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 12.945681] printk: systemd: 26 output lines suppressed due to ratelimiting [ 13.652970] SELinux: Disabled at runtime. [ 13.787551] 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) [ 13.804109] systemd[1]: Detected virtualization kvm. [ 13.806691] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 15.467420] systemd[1]: initrd-switch-root.service: Succeeded. [ 15.472378] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 15.490176] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 15.493111] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 15.495662] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 15.509588] systemd[1]: Starting Journal Service... Starting Journal Service... [ 15.531089] systemd[1]: Starting Create list of required static device nodes for the current kernel... Starting Create list of required st…ce nodes for the current kernel... [ OK ] Listening on udev Kernel Socket. [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Listening on RPCbind Server Activation Socket. Mounting POSIX Message Queue File System... [ OK ] Created slice system-getty.slice. Mounting Huge Pages File System... [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Reached target rpc_pipefs.target. Starting Remount Root and Kernel File Systems... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Local Encrypted Volumes. Starting Apply Kernel Variables... [ OK ] Reached target Paths. [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Listening on udev Control Socket. Starting udev Coldplug all Devices... [ OK ] Listening on Process Core Dump Socket. Activating swap /dev/disk/by-label/SWAP... Mounting Kernel Debug File System... [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd File Systems. [ OK ] Stopped target Initrd Root File System. [ OK ] Created slice User and Session Slice. [ OK ] Reached target Slices. [ OK ] Reached target RPC Port Mapper. [ 15.923580] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS [ OK ] Started Journal Service. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Mounted Huge Pages File System. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Started Apply Kernel Variables. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Mounted Kernel Debug File System. [ 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 udev Coldplug all Devices. [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. Starting udev Kernel Device Manager... [ OK ] Reached target Local File Systems (Pre). Mounting /home/green/git/lustre-release... Mounting /mnt... [ OK ] Mounted /mnt. [ 16.550259] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 17.221394] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 17.310845] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 17.681603] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 17.716302] EDAC sbridge: Ver: 1.1.2 [ 20.413787] Key type dns_resolver registered [ 21.032630] NFS: Registering the id_resolver key type [ 21.035457] Key type id_resolver registered [ 21.040130] Key type id_legacy registered [ OK ] Started Configure read-only root support. [ OK ] Reached target Local File Systems. Starting Mark the need to relabel after reboot... Starting Rebuild Dynamic Linker Cache... Starting Create Volatile Files and Directories... Starting Load/Save Random Seed... [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Load/Save Random Seed. [ OK ] Started Create Volatile Files and Directories. Starting RPC Bind... Starting Update UTMP about System Boot/Shutdown... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Started dnf makecache --timer. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. [ OK ] Reached target sshd-keygen.target. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Started irqbalance daemon. Starting Login Service... [ OK ] Started D-Bus System Message Bus. Starting Network Manager... [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Reached target Timers. Starting Restore /run/initramfs on shutdown... [ OK ] Started Login Service. [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Network Manager. [ OK ] Reached target Network. Starting Dynamic System Tuning Daemon... Starting GSSAPI Proxy Daemon... Starting OpenSSH server daemon... Starting Network Manager Wait Online... [ OK ] Started GSSAPI Proxy Daemon. Starting Hostname Service... [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... [ OK ] Started OpenSSH server daemon. [ OK ] Started Permit User Sessions. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Command Scheduler. [ OK ] Started Serial Getty on ttyS1. [ 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. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg317-client login: [ 35.363202] hrtimer: interrupt took 5788744 ns [ 89.088175] libcfs: loading out-of-tree module taints kernel. [ 89.315200] Key type ._llcrypt registered [ 89.317963] Key type .llcrypt registered [ 89.867396] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [ 89.885166] alg: No test for adler32 (adler32-zlib) [ 91.418698] Lustre: Lustre: Build Version: 2.17.58_40_ge80375b [ 92.374835] LNet: Added LNI 192.168.203.17@tcp [8/256/0/180] [ 94.216242] Key type lgssc registered [ 96.003476] Lustre: Echo OBD driver; http://www.lustre.org/ [ 255.095151] Lustre: Mounted lustre-client - version 2.17.58_40_ge80375b [ 259.921913] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 271.084888] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing check_logdir /tmp/testlogs/ [ 276.070934] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing yml_node [ 280.364782] Lustre: DEBUG MARKER: Client: 2.17.58.40 [ 280.547084] Lustre: lustre-OST0000-osc-ffff946cc57ce800: disconnect after 23s idle [ 283.018929] Lustre: DEBUG MARKER: MDS: 2.17.58.40 [ 285.909688] Lustre: DEBUG MARKER: OSS: 2.17.58.40 [ 287.404376] Lustre: DEBUG MARKER: -----============= acceptance-small: replay-single ============----- Wed Sep 30 12:30:57 EDT 2026 [ 303.154069] Lustre: DEBUG MARKER: excepting tests: 59 36 [ 305.277992] Lustre: DEBUG MARKER: === replay-single: start setup 12:31:14 (1790785874) === [ 310.966155] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing check_config_client /mnt/lustre [ 331.758640] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 343.393126] Lustre: DEBUG MARKER: === replay-single: finish setup 12:31:53 (1790785913) === [ 345.273431] Lustre: DEBUG MARKER: == replay-single test 0a: empty replay =================== 12:31:54 (1790785914) [ 349.910095] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 352.260610] Lustre: lustre-MDT0000-mdc-ffff946cc57ce800: Connection to lustre-MDT0000 (at 192.168.203.117@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 367.586475] Lustre: lustre-OST0000-osc-ffff946cc57ce800: disconnect after 21s idle [ 367.598639] Lustre: Skipped 1 previous similar message [ 368.614422] Lustre: 2405:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790785923/real 1790785923] req@ffff946cd1ecb800 x1877774867383552/t0(0) o400->MGC192.168.203.117@tcp@192.168.203.117@tcp:26/25 lens 224/224 e 0 to 1 dl 1790785939 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 368.655866] LustreError: MGC192.168.203.117@tcp: Connection to MGS (at 192.168.203.117@tcp) was lost; in progress operations using this service will fail [ 376.300915] Lustre: lustre-MDT0000-mdc-ffff946cc57ce800: Connection restored to 192.168.203.117@tcp (at 192.168.203.117@tcp) [ 377.897540] Lustre: Evicted from MGS (at 192.168.203.117@tcp) after server handle changed from 0x231826f8a7b32275 to 0x231826f8a7b326c0 [ 377.917562] Lustre: MGC192.168.203.117@tcp: Connection restored to 192.168.203.117@tcp (at 192.168.203.117@tcp) [ 385.874906] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 387.326760] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 395.429891] Lustre: DEBUG MARKER: == replay-single test 0b: ensure object created after recover exists. (3284) ========================================================== 12:32:45 (1790785965) [ 398.314052] Lustre: lustre-OST0000-osc-ffff946cc57ce800: Connection to lustre-OST0000 (at 192.168.203.117@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 413.666554] Lustre: lustre-OST0001-osc-ffff946cc57ce800: disconnect after 24s idle [ 413.674059] Lustre: Skipped 1 previous similar message [ 417.264121] Lustre: lustre-OST0000-osc-ffff946cc57ce800: Connection restored to 192.168.203.117@tcp (at 192.168.203.117@tcp) [ 431.685674] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 433.130742] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 442.202196] Lustre: DEBUG MARKER: == replay-single test 0c: check replay-barrier =========== 12:33:31 (1790786011) [ 446.410856] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 446.585550] Lustre: Unmounted lustre-client [ 475.251751] LustreError: lustre-MDT0000-mdc-ffff946cd2259800: operation mds_connect to node 192.168.203.117@tcp failed: rc = -16 [ 480.776760] LustreError: lustre-MDT0000-mdc-ffff946cd2259800: operation mds_connect to node 192.168.203.117@tcp failed: rc = -16 [ 485.880273] LustreError: lustre-MDT0000-mdc-ffff946cd2259800: operation mds_connect to node 192.168.203.117@tcp failed: rc = -16 [ 491.034298] LustreError: lustre-MDT0000-mdc-ffff946cd2259800: operation mds_connect to node 192.168.203.117@tcp failed: rc = -16 [ 496.127828] LustreError: lustre-MDT0000-mdc-ffff946cd2259800: operation mds_connect to node 192.168.203.117@tcp failed: rc = -16 [ 506.359196] LustreError: lustre-MDT0000-mdc-ffff946cd2259800: operation mds_connect to node 192.168.203.117@tcp failed: rc = -16 [ 506.374334] LustreError: Skipped 1 previous similar message [ 526.865829] LustreError: lustre-MDT0000-mdc-ffff946cd2259800: operation mds_connect to node 192.168.203.117@tcp failed: rc = -16 [ 526.882915] LustreError: Skipped 3 previous similar messages [ 542.282506] Lustre: Mounted lustre-client - version 2.17.58_40_ge80375b [ 552.643718] Lustre: DEBUG MARKER: == replay-single test 0d: expired recovery with no clients ========================================================== 12:35:22 (1790786122) [ 556.627449] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 556.812102] Lustre: Unmounted lustre-client [ 586.524382] LustreError: lustre-MDT0000-mdc-ffff946cc86bc000: operation mds_connect to node 192.168.203.117@tcp failed: rc = -16 [ 586.531776] LustreError: Skipped 2 previous similar messages [ 653.314226] LustreError: lustre-MDT0000-mdc-ffff946cc86bc000: operation mds_connect to node 192.168.203.117@tcp failed: rc = -16 [ 653.323301] LustreError: Skipped 12 previous similar messages [ 658.454266] Lustre: Mounted lustre-client - version 2.17.58_40_ge80375b [ 666.917838] Lustre: DEBUG MARKER: == replay-single test 1: simple create =================== 12:37:16 (1790786236) [ 670.773767] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 673.763916] Lustre: lustre-MDT0000-mdc-ffff946cc86bc000: Connection to lustre-MDT0000 (at 192.168.203.117@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 689.056336] Lustre: 2405:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790786244/real 1790786244] req@ffff946cc690a680 x1877774867449600/t0(0) o400->MGC192.168.203.117@tcp@192.168.203.117@tcp:26/25 lens 224/224 e 0 to 1 dl 1790786260 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 689.096995] LustreError: MGC192.168.203.117@tcp: Connection to MGS (at 192.168.203.117@tcp) was lost; in progress operations using this service will fail [ 696.773615] Lustre: lustre-MDT0000-mdc-ffff946cc86bc000: Connection restored to 192.168.203.117@tcp (at 192.168.203.117@tcp) [ 700.138097] Lustre: Evicted from MGS (at 192.168.203.117@tcp) after server handle changed from 0x231826f8a7b33648 to 0x231826f8a7b33cca [ 703.946477] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 705.325826] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 713.148749] Lustre: DEBUG MARKER: == replay-single test 2a: touch ========================== 12:38:03 (1790786283) [ 716.682880] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 720.883780] Lustre: lustre-MDT0000-mdc-ffff946cc86bc000: Connection to lustre-MDT0000 (at 192.168.203.117@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 737.248947] Lustre: 2405:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790786292/real 1790786292] req@ffff946cd2330700 x1877774867461888/t0(0) o400->MGC192.168.203.117@tcp@192.168.203.117@tcp:26/25 lens 224/224 e 0 to 1 dl 1790786308 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 737.278484] LustreError: MGC192.168.203.117@tcp: Connection to MGS (at 192.168.203.117@tcp) was lost; in progress operations using this service will fail [ 737.305949] Lustre: Evicted from MGS (at 192.168.203.117@tcp) after server handle changed from 0x231826f8a7b33cca to 0x231826f8a7b33f01 [ 737.319654] Lustre: MGC192.168.203.117@tcp: Connection restored to 192.168.203.117@tcp (at 192.168.203.117@tcp) [ 737.325900] Lustre: Skipped 1 previous similar message [ 742.287547] LustreError: 2402:0:(client.c:3449:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff946cd2331f80 x1877774867460992/t21474836484(21474836484) o101->lustre-MDT0000-mdc-ffff946cc86bc000@192.168.203.117@tcp:12/10 lens 592/608 e 0 to 0 dl 1790786324 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'touch.0' uid:0 gid:0 projid:0 [ 750.364797] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 751.839522] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 759.753748] Lustre: DEBUG MARKER: == replay-single test 2b: touch ========================== 12:38:49 (1790786329) [ 763.556990] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 767.990313] Lustre: lustre-MDT0000-mdc-ffff946cc86bc000: Connection to lustre-MDT0000 (at 192.168.203.117@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 784.352148] Lustre: 2404:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790786339/real 1790786339] req@ffff946cd2293480 x1877774867474304/t0(0) o400->MGC192.168.203.117@tcp@192.168.203.117@tcp:26/25 lens 224/224 e 0 to 1 dl 1790786355 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 784.371863] LustreError: MGC192.168.203.117@tcp: Connection to MGS (at 192.168.203.117@tcp) was lost; in progress operations using this service will fail [ 784.389063] Lustre: Evicted from MGS (at 192.168.203.117@tcp) after server handle changed from 0x231826f8a7b33f01 to 0x231826f8a7b3433e [ 784.398183] Lustre: MGC192.168.203.117@tcp: Connection restored to 192.168.203.117@tcp (at 192.168.203.117@tcp) [ 784.402946] Lustre: Skipped 1 previous similar message [ 789.881389] LustreError: 2402:0:(client.c:3449:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff946cd2331880 x1877774867473408/t25769803781(25769803781) o101->lustre-MDT0000-mdc-ffff946cc86bc000@192.168.203.117@tcp:12/10 lens 592/608 e 0 to 0 dl 1790786372 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'touch.0' uid:0 gid:0 projid:0 [ 798.264438] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 799.489128] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 806.594931] Lustre: DEBUG MARKER: == replay-single test 2c: setstripe replay =============== 12:39:36 (1790786376) [ 810.274146] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 816.109171] Lustre: lustre-MDT0000-mdc-ffff946cc86bc000: Connection to lustre-MDT0000 (at 192.168.203.117@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 831.478831] LustreError: MGC192.168.203.117@tcp: Connection to MGS (at 192.168.203.117@tcp) was lost; in progress operations using this service will fail [ 831.508181] Lustre: Evicted from MGS (at 192.168.203.117@tcp) after server handle changed from 0x231826f8a7b3433e to 0x231826f8a7b34981 [ 831.528873] Lustre: MGC192.168.203.117@tcp: Connection restored to 192.168.203.117@tcp (at 192.168.203.117@tcp) [ 831.543210] Lustre: Skipped 1 previous similar message [ 835.444330] LustreError: 2402:0:(client.c:3449:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff946cd2290e00 x1877774867485056/t30064771076(30064771076) o101->lustre-MDT0000-mdc-ffff946cc86bc000@192.168.203.117@tcp:12/10 lens 536/608 e 0 to 0 dl 1790786418 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'lfs.0' uid:0 gid:0 projid:0 [ 842.905441] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 844.477032] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 852.067684] Lustre: DEBUG MARKER: == replay-single test 2d: setdirstripe replay ============ 12:40:22 (1790786422) [ 855.488046] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 862.181474] Lustre: lustre-MDT0000-mdc-ffff946cc86bc000: Connection to lustre-MDT0000 (at 192.168.203.117@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 877.557195] LustreError: MGC192.168.203.117@tcp: Connection to MGS (at 192.168.203.117@tcp) was lost; in progress operations using this service will fail [ 877.579689] Lustre: Evicted from MGS (at 192.168.203.117@tcp) after server handle changed from 0x231826f8a7b34981 to 0x231826f8a7b34f1c [ 877.592097] Lustre: MGC192.168.203.117@tcp: Connection restored to 192.168.203.117@tcp (at 192.168.203.117@tcp) [ 877.598224] Lustre: Skipped 1 previous similar message [ 887.140541] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 888.717057] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 896.306948] Lustre: DEBUG MARKER: == replay-single test 2e: O_CREAT|O_EXCL create replay === 12:41:06 (1790786466) [ 902.106359] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 908.262564] Lustre: lustre-MDT0000-mdc-ffff946cc86bc000: Connection to lustre-MDT0000 (at 192.168.203.117@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 912.864856] Lustre: 22859:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790786468/real 1790786468] req@ffff946cc6909f80 x1877774867504640/t0(0) o35->lustre-MDT0000-mdc-ffff946cc86bc000@192.168.203.117@tcp:23/10 lens 392/624 e 0 to 1 dl 1790786484 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'openfile.0' uid:0 gid:0 projid:0 [ 923.627418] LustreError: MGC192.168.203.117@tcp: Connection to MGS (at 192.168.203.117@tcp) was lost; in progress operations using this service will fail [ 923.692093] Lustre: Evicted from MGS (at 192.168.203.117@tcp) after server handle changed from 0x231826f8a7b34f1c to 0x231826f8a7b353e5 [ 934.158810] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 935.499819] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 942.254398] Lustre: DEBUG MARKER: == replay-single test 3a: replay failed open(O_DIRECTORY) ========================================================== 12:41:52 (1790786512) [ 946.060914] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 965.600489] Lustre: 2404:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790786520/real 1790786520] req@ffff946cd1ecc380 x1877774867517696/t0(0) o400->MGC192.168.203.117@tcp@192.168.203.117@tcp:26/25 lens 224/224 e 0 to 1 dl 1790786536 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 965.626207] LustreError: MGC192.168.203.117@tcp: Connection to MGS (at 192.168.203.117@tcp) was lost; in progress operations using this service will fail [ 971.688804] Lustre: lustre-MDT0000-mdc-ffff946cc86bc000: Connection restored to 192.168.203.117@tcp (at 192.168.203.117@tcp) [ 971.693811] Lustre: Skipped 3 previous similar messages [ 975.719884] Lustre: Evicted from MGS (at 192.168.203.117@tcp) after server handle changed from 0x231826f8a7b353e5 to 0x231826f8a7b35a98 [ 977.993239] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 979.375376] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 986.050763] Lustre: DEBUG MARKER: == replay-single test 3b: replay failed open -ENOMEM ===== 12:42:36 (1790786556) [ 988.893238] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 996.324975] Lustre: lustre-MDT0000-mdc-ffff946cc86bc000: Connection to lustre-MDT0000 (at 192.168.203.117@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 996.341358] Lustre: Skipped 1 previous similar message [ 1021.438952] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1023.145681] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1031.880901] Lustre: DEBUG MARKER: == replay-single test 3c: replay failed open -ENOMEM ===== 12:43:21 (1790786601) [ 1035.675193] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1057.770216] LustreError: MGC192.168.203.117@tcp: Connection to MGS (at 192.168.203.117@tcp) was lost; in progress operations using this service will fail [ 1057.783514] LustreError: Skipped 1 previous similar message [ 1057.797038] Lustre: Evicted from MGS (at 192.168.203.117@tcp) after server handle changed from 0x231826f8a7b35d8c to 0x231826f8a7b360cd [ 1057.803965] Lustre: Skipped 1 previous similar message [ 1068.592954] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1069.592576] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1077.043225] Lustre: DEBUG MARKER: == replay-single test 4a: |x| 10 open(O_CREAT)s ========== 12:44:06 (1790786646) [ 1081.389120] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1101.792425] Lustre: 2404:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790786656/real 1790786656] req@ffff946cd1ecc380 x1877774867557248/t0(0) o400->MGC192.168.203.117@tcp@192.168.203.117@tcp:26/25 lens 224/224 e 0 to 1 dl 1790786672 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1101.832287] Lustre: MGC192.168.203.117@tcp: Connection restored to 192.168.203.117@tcp (at 192.168.203.117@tcp) [ 1101.840297] Lustre: Skipped 5 previous similar messages [ 1106.834803] LustreError: 2402:0:(client.c:3449:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff946cd2333480 x1877774867549312/t55834574851(55834574851) o101->lustre-MDT0000-mdc-ffff946cc86bc000@192.168.203.117@tcp:12/10 lens 592/608 e 0 to 0 dl 1790786689 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'bash.0' uid:0 gid:0 projid:0 [ 1114.396810] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1115.973402] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1123.404394] Lustre: DEBUG MARKER: == replay-single test 4b: |x| rm 10 files ================ 12:44:53 (1790786693) [ 1127.309545] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1132.520540] Lustre: lustre-MDT0000-mdc-ffff946cc86bc000: Connection to lustre-MDT0000 (at 192.168.203.117@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1132.533177] Lustre: Skipped 2 previous similar messages [ 1147.872146] Lustre: 2405:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790786703/real 1790786703] req@ffff946cc6909500 x1877774867588096/t0(0) o400->MGC192.168.203.117@tcp@192.168.203.117@tcp:26/25 lens 224/224 e 0 to 1 dl 1790786719 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1160.679537] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1161.901701] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1169.598707] Lustre: DEBUG MARKER: == replay-single test 5: |x| 220 open(O_CREAT) =========== 12:45:39 (1790786739) [ 1173.065979] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1199.072445] LustreError: MGC192.168.203.117@tcp: Connection to MGS (at 192.168.203.117@tcp) was lost; in progress operations using this service will fail [ 1199.086126] LustreError: Skipped 2 previous similar messages [ 1199.103234] Lustre: Evicted from MGS (at 192.168.203.117@tcp) after server handle changed from 0x231826f8a7b37357 to 0x231826f8a7b3a989 [ 1199.108881] Lustre: Skipped 2 previous similar messages [ 1202.574603] LustreError: 2402:0:(client.c:3449:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff946cc6908a80 x1877774867598848/t64424509443(64424509443) o101->lustre-MDT0000-mdc-ffff946cc86bc000@192.168.203.117@tcp:12/10 lens 592/608 e 0 to 0 dl 1790786786 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'bash.0' uid:0 gid:0 projid:0 [ 1202.605639] LustreError: 2402:0:(client.c:3449:ptlrpc_replay_interpret()) Skipped 9 previous similar messages [ 1211.265856] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1213.357936] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1234.113870] Lustre: DEBUG MARKER: == replay-single test 6a: mkdir + contained create ======= 12:46:44 (1790786804) [ 1237.705980] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1256.416743] Lustre: 2403:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790786811/real 1790786811] req@ffff946cd85c1180 x1877774868068480/t0(0) o400->MGC192.168.203.117@tcp@192.168.203.117@tcp:26/25 lens 224/224 e 0 to 1 dl 1790786827 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1256.433122] Lustre: 2403:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 1271.444294] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1272.923916] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1282.432934] Lustre: DEBUG MARKER: == replay-single test 6b: |X| rmdir ====================== 12:47:32 (1790786852) [ 1286.239178] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1319.171591] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1320.733176] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1328.193400] Lustre: DEBUG MARKER: == replay-single test 7: mkdir |X| contained create ====== 12:48:18 (1790786898) [ 1331.782830] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1364.537798] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1365.913564] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1373.195056] Lustre: DEBUG MARKER: == replay-single test 8: creat open |X| close ============ 12:49:03 (1790786943) [ 1376.882490] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1395.680174] Lustre: 2403:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790786950/real 1790786950] req@ffff946cd47c0e00 x1877774868104064/t0(0) o400->MGC192.168.203.117@tcp@192.168.203.117@tcp:26/25 lens 224/224 e 0 to 1 dl 1790786966 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1403.290395] LustreError: 2402:0:(client.c:3449:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff946cd08b9f80 x1877774868103936/t81604378634(81604378634) o101->lustre-MDT0000-mdc-ffff946cc86bc000@192.168.203.117@tcp:12/10 lens 664/608 e 0 to 0 dl 1790786990 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'multiop.0' uid:0 gid:0 projid:0 [ 1403.330236] LustreError: 2402:0:(client.c:3449:ptlrpc_replay_interpret()) Skipped 219 previous similar messages [ 1403.422966] Lustre: lustre-MDT0000-mdc-ffff946cc86bc000: Connection restored to 192.168.203.117@tcp (at 192.168.203.117@tcp) [ 1403.439620] Lustre: Skipped 11 previous similar messages [ 1412.635527] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1414.024562] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1421.736939] Lustre: DEBUG MARKER: == replay-single test 9: |X| create (same inum/gen) ====== 12:49:51 (1790786991) [ 1426.167379] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1431.012904] Lustre: lustre-MDT0000-mdc-ffff946cc86bc000: Connection to lustre-MDT0000 (at 192.168.203.117@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1431.030894] Lustre: Skipped 5 previous similar messages [ 1459.680102] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1461.118720] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1469.076365] Lustre: DEBUG MARKER: == replay-single test 10: create |X| rename unlink ======= 12:50:38 (1790787038) [ 1472.741427] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1493.490135] LustreError: MGC192.168.203.117@tcp: Connection to MGS (at 192.168.203.117@tcp) was lost; in progress operations using this service will fail [ 1493.513837] LustreError: Skipped 5 previous similar messages [ 1493.544160] Lustre: Evicted from MGS (at 192.168.203.117@tcp) after server handle changed from 0x231826f8a7b42464 to 0x231826f8a7b429b2 [ 1493.553926] Lustre: Skipped 5 previous similar messages [ 1504.877937] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1506.183269] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1513.792909] Lustre: DEBUG MARKER: == replay-single test 11: create open write rename |X| create-old-name read ========================================================== 12:51:23 (1790787083) [ 1517.097790] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1540.991145] LustreError: 2402:0:(client.c:3449:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff946cd85c0e00 x1877774868140416/t94489280522(94489280522) o101->lustre-MDT0000-mdc-ffff946cc86bc000@192.168.203.117@tcp:12/10 lens 592/608 e 0 to 0 dl 1790787127 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'bash.0' uid:0 gid:0 projid:0 [ 1547.406199] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1548.699222] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1555.921667] Lustre: DEBUG MARKER: == replay-single test 12: open, unlink |X| close ========= 12:52:05 (1790787125) [ 1559.404256] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1581.095071] LustreError: 2402:0:(client.c:3449:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff946cd85c1f80 x1877774868141184/t94489280524(94489280524) o101->lustre-MDT0000-mdc-ffff946cc86bc000@192.168.203.117@tcp:12/10 lens 576/608 e 0 to 0 dl 1790787168 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'grep.0' uid:0 gid:0 projid:0 [ 1581.113347] LustreError: 2402:0:(client.c:3449:ptlrpc_replay_interpret()) Skipped 1 previous similar message [ 1593.371177] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1594.697230] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1601.880333] Lustre: DEBUG MARKER: == replay-single test 13: open chmod 0 |x| write close === 12:52:51 (1790787171) [ 1605.025565] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1641.186665] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1642.575978] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1650.018148] Lustre: DEBUG MARKER: == replay-single test 14: open(O_CREAT), unlink |X| close ========================================================== 12:53:39 (1790787219) [ 1653.617789] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1675.227782] LustreError: 2402:0:(client.c:3449:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff946cd85c1f80 x1877774868141184/t94489280524(94489280524) o101->lustre-MDT0000-mdc-ffff946cc86bc000@192.168.203.117@tcp:12/10 lens 576/608 e 0 to 0 dl 1790787262 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'grep.0' uid:0 gid:0 projid:0 [ 1675.268352] LustreError: 2402:0:(client.c:3449:ptlrpc_replay_interpret()) Skipped 3 previous similar messages [ 1686.648275] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1688.045545] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1695.662404] Lustre: DEBUG MARKER: == replay-single test 15: open(O_CREAT), unlink |X| touch new, close ========================================================== 12:54:25 (1790787265) [ 1700.187658] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1720.802650] Lustre: 2403:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790787275/real 1790787275] req@ffff946cd85c3b80 x1877774868193920/t0(0) o400->MGC192.168.203.117@tcp@192.168.203.117@tcp:26/25 lens 224/224 e 0 to 1 dl 1790787291 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1720.838345] Lustre: 2403:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 4 previous similar messages [ 1745.713968] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1747.145937] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1755.211428] Lustre: DEBUG MARKER: == replay-single test 16: |X| open(O_CREAT), unlink, touch new, unlink new ========================================================== 12:55:25 (1790787325) [ 1759.426117] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1805.209839] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1807.016568] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1815.532482] Lustre: DEBUG MARKER: == replay-single test 17: |X| open(O_CREAT), |replay| close ========================================================== 12:56:24 (1790787384) [ 1818.877860] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1839.614681] LustreError: 2402:0:(client.c:3449:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff946cd85c1f80 x1877774868141184/t94489280524(94489280524) o101->lustre-MDT0000-mdc-ffff946cc86bc000@192.168.203.117@tcp:12/10 lens 576/608 e 0 to 0 dl 1790787426 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'grep.0' uid:0 gid:0 projid:0 [ 1839.669191] LustreError: 2402:0:(client.c:3449:ptlrpc_replay_interpret()) Skipped 5 previous similar messages [ 1852.440144] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1854.319929] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1863.301428] Lustre: DEBUG MARKER: == replay-single test 18: open(O_CREAT), unlink, touch new, close, touch, unlink ========================================================== 12:57:13 (1790787433) [ 1866.925054] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1901.128305] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1902.702626] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1911.542360] Lustre: DEBUG MARKER: == replay-single test 19: mcreate, open, write, rename === 12:58:01 (1790787481) [ 1915.909784] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1937.439398] Lustre: MGC192.168.203.117@tcp: Connection restored to 192.168.203.117@tcp (at 192.168.203.117@tcp) [ 1937.446418] Lustre: Skipped 21 previous similar messages [ 1938.853712] Lustre: 15090:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.203.117@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 1959.378329] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1960.593919] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1968.060248] Lustre: DEBUG MARKER: == replay-single test 20a: |X| open(O_CREAT), unlink, replay, close (test mds_cleanup_orphans) ========================================================== 12:58:57 (1790787537) [ 1971.275176] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1977.327081] Lustre: lustre-MDT0000-mdc-ffff946cc86bc000: Connection to lustre-MDT0000 (at 192.168.203.117@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1977.350394] Lustre: Skipped 10 previous similar messages [ 2006.118689] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2007.525342] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2014.881861] Lustre: DEBUG MARKER: == replay-single test 20b: write, unlink, eviction, replay (test mds_cleanup_orphans) ========================================================== 12:59:44 (1790787584) [ 2022.343668] LustreError: lustre-MDT0000-mdc-ffff946cc86bc000: operation mds_statfs to node 192.168.203.117@tcp failed: rc = -107 [ 2022.369528] LustreError: lustre-MDT0000-mdc-ffff946cc86bc000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 2022.411176] LustreError: 56054:0:(file.c:251:ll_close_inode_openhandle()) lustre-clilmv-ffff946cc86bc000: inode [0x200001b71:0x118:0x0] mdc close failed: rc = -108 [ 2022.411443] LustreError: 55996:0:(vvp_io.c:1889:vvp_io_init()) lustre: refresh file layout [0x200001b71:0x132:0x0] error -108. [ 2043.873359] LustreError: MGC192.168.203.117@tcp: Connection to MGS (at 192.168.203.117@tcp) was lost; in progress operations using this service will fail [ 2043.888795] LustreError: Skipped 10 previous similar messages [ 2054.125587] Lustre: Evicted from MGS (at 192.168.203.117@tcp) after server handle changed from 0x231826f8a7b4602a to 0x231826f8a7b4648a [ 2054.135299] Lustre: Skipped 10 previous similar messages [ 2068.551726] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2069.994263] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2089.303630] Lustre: DEBUG MARKER: before 4096, after 4096 [ 2095.170171] Lustre: DEBUG MARKER: == replay-single test 20c: check that client eviction does not affect file content ========================================================== 13:01:05 (1790787665) [ 2097.144986] LustreError: lustre-MDT0000-mdc-ffff946cc86bc000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 2104.365480] Lustre: DEBUG MARKER: == replay-single test 21: |X| open(O_CREAT), unlink touch new, replay, close (test mds_cleanup_orphans) ========================================================== 13:01:14 (1790787674) [ 2108.070847] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2143.110116] LustreError: 2402:0:(client.c:3449:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff946cd1227100 x1877774868298624/t141733920773(141733920773) o101->lustre-MDT0000-mdc-ffff946cc86bc000@192.168.203.117@tcp:12/10 lens 592/608 e 0 to 0 dl 1790787726 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'multiop.0' uid:0 gid:0 projid:0 [ 2143.152508] LustreError: 2402:0:(client.c:3449:ptlrpc_replay_interpret()) Skipped 8 previous similar messages [ 2152.039733] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2153.646856] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2161.981536] Lustre: DEBUG MARKER: == replay-single test 22: open(O_CREAT), |X| unlink, replay, close (test mds_cleanup_orphans) ========================================================== 13:02:11 (1790787731) [ 2166.328329] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2200.997369] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2203.102097] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2213.701649] Lustre: DEBUG MARKER: == replay-single test 23: open(O_CREAT), |X| unlink touch new, replay, close (test mds_cleanup_orphans) ========================================================== 13:03:03 (1790787783) [ 2218.214910] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2251.215685] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2252.605637] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2260.014576] Lustre: DEBUG MARKER: == replay-single test 24: open(O_CREAT), replay, unlink, close (test mds_cleanup_orphans) ========================================================== 13:03:50 (1790787830) [ 2263.855810] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2282.400285] Lustre: 2403:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790787837/real 1790787837] req@ffff946cd47c3100 x1877774868339712/t0(0) o400->MGC192.168.203.117@tcp@192.168.203.117@tcp:26/25 lens 224/224 e 0 to 1 dl 1790787853 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2282.448334] Lustre: 2403:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 5 previous similar messages [ 2294.965732] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2296.427439] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2303.387899] Lustre: DEBUG MARKER: == replay-single test 25: open(O_CREAT), unlink, replay, close (test mds_cleanup_orphans) ========================================================== 13:04:33 (1790787873) [ 2307.174514] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2339.226884] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2340.725523] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2349.117647] Lustre: DEBUG MARKER: == replay-single test 26: |X| open(O_CREAT), unlink two, close one, replay, close one (test mds_cleanup_orphans) ========================================================== 13:05:19 (1790787919) [ 2353.013658] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2398.446803] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2399.965726] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2407.454964] Lustre: DEBUG MARKER: == replay-single test 27: |X| open(O_CREAT), unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 13:06:17 (1790787977) [ 2411.002712] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2453.858483] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2455.123359] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2461.660991] Lustre: DEBUG MARKER: == replay-single test 28: open(O_CREAT), |X| unlink two, close one, replay, close one (test mds_cleanup_orphans) ========================================================== 13:07:11 (1790788031) [ 2464.822203] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2507.129983] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2508.484963] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2515.634922] Lustre: DEBUG MARKER: == replay-single test 29: open(O_CREAT), |X| unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 13:08:05 (1790788085) [ 2519.158384] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2539.538356] Lustre: MGC192.168.203.117@tcp: Connection restored to 192.168.203.117@tcp (at 192.168.203.117@tcp) [ 2539.549701] Lustre: Skipped 23 previous similar messages [ 2549.810993] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2551.050841] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2559.102719] Lustre: DEBUG MARKER: == replay-single test 30: open(O_CREAT) two, unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 13:08:48 (1790788128) [ 2562.648050] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2596.047078] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2597.644128] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2606.328236] Lustre: DEBUG MARKER: == replay-single test 31: open(O_CREAT) two, unlink one, |X| unlink one, close two (test mds_cleanup_orphans) ========================================================== 13:09:35 (1790788175) [ 2610.606881] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2617.316152] Lustre: lustre-MDT0000-mdc-ffff946cc86bc000: Connection to lustre-MDT0000 (at 192.168.203.117@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 2617.329465] Lustre: Skipped 13 previous similar messages [ 2634.029942] Lustre: 15090:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.203.117@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 2654.058959] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2655.757082] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2664.307962] Lustre: DEBUG MARKER: == replay-single test 32: close() notices client eviction; close() after client eviction ========================================================== 13:10:34 (1790788234) [ 2667.040095] LustreError: lustre-MDT0000-mdc-ffff946cc86bc000: operation mds_statfs to node 192.168.203.117@tcp failed: rc = -107 [ 2667.059460] LustreError: lustre-MDT0000-mdc-ffff946cc86bc000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 2674.079115] Lustre: DEBUG MARKER: == replay-single test 33a: fid seq shouldn't be reused after abort recovery ========================================================== 13:10:44 (1790788244) [ 2676.693816] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2687.976347] LustreError: MGC192.168.203.117@tcp: Connection to MGS (at 192.168.203.117@tcp) was lost; in progress operations using this service will fail [ 2687.987339] LustreError: Skipped 11 previous similar messages [ 2688.003172] Lustre: Evicted from MGS (at 192.168.203.117@tcp) after server handle changed from 0x231826f8a7b4a1a0 to 0x231826f8a7b4ab0f [ 2688.009612] Lustre: Skipped 11 previous similar messages [ 2688.025238] LustreError: lustre-MDT0000-mdc-ffff946cc86bc000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 2714.130630] Lustre: DEBUG MARKER: == replay-single test 33b: test fid seq allocation ======= 13:11:23 (1790788283) [ 2718.414536] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2734.127289] LustreError: lustre-MDT0000-mdc-ffff946cc86bc000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 2756.694305] Lustre: DEBUG MARKER: == replay-single test 34: abort recovery before client does replay (test mds_cleanup_orphans) ========================================================== 13:12:06 (1790788326) [ 2761.042331] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2775.106658] LustreError: lustre-MDT0000-mdc-ffff946cc86bc000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 2797.606993] Lustre: DEBUG MARKER: == replay-single test 35: test recovery from llog for unlink op ========================================================== 13:12:47 (1790788367) [ 2816.030126] LustreError: lustre-MDT0000-mdc-ffff946cc86bc000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 2838.098534] Lustre: DEBUG MARKER: SKIP: replay-single test_36 skipping ALWAYS excluded test 36 [ 2839.664929] Lustre: DEBUG MARKER: == replay-single test 37: abort recovery before client does replay (test mds_cleanup_orphans for directories) ========================================================== 13:13:29 (1790788409) [ 2843.848892] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2862.155313] LustreError: lustre-MDT0000-mdc-ffff946cc86bc000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 2882.119507] Lustre: DEBUG MARKER: == replay-single test 38: test recovery from unlink llog (test llog_gen_rec) ========================================================== 13:14:11 (1790788451) [ 2914.625860] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2934.752562] Lustre: 2404:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790788489/real 1790788489] req@ffff946cc34fad80 x1877774869224832/t0(0) o400->MGC192.168.203.117@tcp@192.168.203.117@tcp:26/25 lens 224/224 e 0 to 1 dl 1790788505 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2934.787389] Lustre: 2404:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 5 previous similar messages [ 2949.340511] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2950.779412] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2972.133654] Lustre: DEBUG MARKER: == replay-single test 39: test recovery from unlink llog (test llog_gen_rec) ========================================================== 13:15:41 (1790788541) [ 2995.007048] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3038.554792] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3039.990124] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3061.091903] Lustre: DEBUG MARKER: == replay-single test 41: read from a valid osc while other oscs are invalid ========================================================== 13:17:11 (1790788631) [ 3070.710813] Lustre: DEBUG MARKER: == replay-single test 42: recovery after ost failure ===== 13:17:20 (1790788640) [ 3092.840382] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-OST0000 [ 3193.601733] Lustre: DEBUG MARKER: == replay-single test 43: mds osc import failure during recovery; don't LBUG ========================================================== 13:19:23 (1790788763) [ 3198.332853] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3220.459744] Lustre: MGC192.168.203.117@tcp: Connection restored to 192.168.203.117@tcp (at 192.168.203.117@tcp) [ 3220.470991] Lustre: Skipped 20 previous similar messages [ 3235.964942] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3237.408708] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3257.278803] Lustre: DEBUG MARKER: == replay-single test 44a: race in target handle connect ========================================================== 13:20:26 (1790788826) [ 3263.580509] Lustre: lustre-MDT0000-mdc-ffff946cc86bc000: Connection to lustre-MDT0000 (at 192.168.203.117@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 3263.593239] Lustre: Skipped 10 previous similar messages [ 3341.794581] Lustre: DEBUG MARKER: == replay-single test 44b: race in target handle connect ========================================================== 13:21:51 (1790788911) [ 3363.886725] LustreError: 89276:0:(lmv_obd.c:1471:lmv_statfs()) lustre-MDT0000-mdc-ffff946cc86bc000: can't stat MDS #0: rc = -114 [ 3386.232214] LustreError: 89299:0:(lmv_obd.c:1471:lmv_statfs()) lustre-MDT0000-mdc-ffff946cc86bc000: can't stat MDS #0: rc = -114 [ 3408.872428] LustreError: 89321:0:(lmv_obd.c:1471:lmv_statfs()) lustre-MDT0000-mdc-ffff946cc86bc000: can't stat MDS #0: rc = -114 [ 3431.413748] LustreError: 89344:0:(lmv_obd.c:1471:lmv_statfs()) lustre-MDT0000-mdc-ffff946cc86bc000: can't stat MDS #0: rc = -114 [ 3453.935881] LustreError: 89366:0:(lmv_obd.c:1471:lmv_statfs()) lustre-MDT0000-mdc-ffff946cc86bc000: can't stat MDS #0: rc = -114 [ 3476.478714] LustreError: 89389:0:(lmv_obd.c:1471:lmv_statfs()) lustre-MDT0000-mdc-ffff946cc86bc000: can't stat MDS #0: rc = -114 [ 3499.499562] LustreError: 89411:0:(lmv_obd.c:1471:lmv_statfs()) lustre-MDT0000-mdc-ffff946cc86bc000: can't stat MDS #0: rc = -114 [ 3543.856892] LustreError: 89457:0:(lmv_obd.c:1471:lmv_statfs()) lustre-MDT0000-mdc-ffff946cc86bc000: can't stat MDS #0: rc = -114 [ 3543.872817] LustreError: 89457:0:(lmv_obd.c:1471:lmv_statfs()) Skipped 1 previous similar message [ 3572.902155] Lustre: DEBUG MARKER: == replay-single test 44c: race in target handle connect ========================================================== 13:25:42 (1790789142) [ 3576.432789] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3591.655064] LustreError: MGC192.168.203.117@tcp: Connection to MGS (at 192.168.203.117@tcp) was lost; in progress operations using this service will fail [ 3591.668932] LustreError: Skipped 7 previous similar messages [ 3591.684246] Lustre: Evicted from MGS (at 192.168.203.117@tcp) after server handle changed from 0x231826f8a7b8ee13 to 0x231826f8a7b9001f [ 3591.694027] Lustre: Skipped 7 previous similar messages [ 3591.727135] LustreError: lustre-MDT0000-mdc-ffff946cc86bc000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 3628.512245] Lustre: 2403:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790789183/real 1790789183] req@ffff946cc3688e00 x1877774871260672/t0(0) o400->MGC192.168.203.117@tcp@192.168.203.117@tcp:26/25 lens 224/224 e 0 to 1 dl 1790789199 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3628.546524] Lustre: 2403:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 3642.988687] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3644.784036] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3653.279867] Lustre: DEBUG MARKER: == replay-single test 45: Handle failed close ============ 13:27:02 (1790789222) [ 3653.522349] Lustre: setting import lustre-MDT0000_UUID INACTIVE by administrator request [ 3653.547883] LustreError: 91977:0:(file.c:251:ll_close_inode_openhandle()) lustre-clilmv-ffff946cc86bc000: inode [0x20001a9e1:0x1:0x0] mdc close failed: rc = -108 [ 3653.584625] LustreError: lustre-MDT0000-mdc-ffff946cc86bc000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 3660.603264] Lustre: DEBUG MARKER: == replay-single test 46: Don't leak file handle after open resend (3325) ========================================================== 13:27:10 (1790789230) [ 3713.008302] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3714.738321] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3725.228545] Lustre: DEBUG MARKER: == replay-single test 47: MDS->OSC failure during precreate cleanup (2824) ========================================================== 13:28:15 (1790789295) [ 3762.533719] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 3763.962784] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 3835.616568] Lustre: DEBUG MARKER: == replay-single test 48: MDS->OSC failure during precreate cleanup (2824) ========================================================== 13:30:05 (1790789405) [ 3839.443824] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3868.524497] Lustre: MGC192.168.203.117@tcp: Connection restored to 192.168.203.117@tcp (at 192.168.203.117@tcp) [ 3868.530141] Lustre: Skipped 21 previous similar messages [ 3875.162341] LustreError: 2402:0:(client.c:3449:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff946cc344f800 x1877774871334912/t236223201383(236223201383) o101->lustre-MDT0000-mdc-ffff946cc86bc000@192.168.203.117@tcp:12/10 lens 592/608 e 0 to 0 dl 1790789502 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'createmany.0' uid:0 gid:0 projid:0 [ 3875.186529] LustreError: 2402:0:(client.c:3449:ptlrpc_replay_interpret()) Skipped 19 previous similar messages [ 3945.586501] Lustre: DEBUG MARKER: == replay-single test 50: Double OSC recovery, don't LASSERT (3812) ========================================================== 13:31:55 (1790789515) [ 3958.721525] Lustre: DEBUG MARKER: == replay-single test 52: time out lock replay (3764) ==== 13:32:08 (1790789528) [ 3962.874875] Lustre: lustre-MDT0000-mdc-ffff946cc86bc000: Connection to lustre-MDT0000 (at 192.168.203.117@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 3962.904610] Lustre: Skipped 18 previous similar messages [ 4048.989433] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4049.997360] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4058.431613] Lustre: DEBUG MARKER: == replay-single test 53a: |X| close request while two MDC requests in flight ========================================================== 13:33:48 (1790789628) [ 4064.593497] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4088.167896] Lustre: 15090:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.203.117@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 4105.700567] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4107.194989] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4115.085630] Lustre: DEBUG MARKER: == replay-single test 53b: |X| open request while two MDC requests in flight ========================================================== 13:34:45 (1790789685) [ 4120.924661] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4151.447576] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4152.457742] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4159.065673] Lustre: DEBUG MARKER: == replay-single test 53c: |X| open request and close request while two MDC requests in flight ========================================================== 13:35:29 (1790789729) [ 4165.154686] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4193.319927] Lustre: Evicted from MGS (at 192.168.203.117@tcp) after server handle changed from 0x231826f8a7b93a87 to 0x231826f8a7b9444a [ 4193.333385] Lustre: Skipped 6 previous similar messages [ 4197.300165] Lustre: DEBUG MARKER: == replay-single test 53d: close reply while two MDC requests in flight ========================================================== 13:36:07 (1790789767) [ 4218.850669] LustreError: MGC192.168.203.117@tcp: Connection to MGS (at 192.168.203.117@tcp) was lost; in progress operations using this service will fail [ 4218.861567] LustreError: Skipped 7 previous similar messages [ 4233.554352] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4235.272059] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4242.539511] Lustre: DEBUG MARKER: == replay-single test 53e: |X| open reply while two MDC requests in flight ========================================================== 13:36:52 (1790789812) [ 4248.451343] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4282.696357] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4284.702713] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4293.534364] Lustre: DEBUG MARKER: == replay-single test 53f: |X| open reply and close reply while two MDC requests in flight ========================================================== 13:37:43 (1790789863) [ 4299.900993] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4312.032144] Lustre: 105087:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790789867/real 1790789867] req@ffff946cd855c380 x1877774871484800/t0(0) o35->lustre-MDT0000-mdc-ffff946cc86bc000@192.168.203.117@tcp:23/10 lens 392/624 e 0 to 1 dl 1790789883 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'multiop.0' uid:0 gid:0 projid:0 [ 4312.052587] Lustre: 105087:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 11 previous similar messages [ 4335.231770] Lustre: DEBUG MARKER: == replay-single test 53g: |X| drop open reply and close request while close and open are both in flight ========================================================== 13:38:24 (1790789904) [ 4343.564901] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4378.611517] Lustre: DEBUG MARKER: == replay-single test 53h: open request and close reply while two MDC requests in flight ========================================================== 13:39:08 (1790789948) [ 4386.730972] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4424.063735] Lustre: DEBUG MARKER: == replay-single test 55: let MDS_CHECK_RESENT return the original return code instead of 0 ========================================================== 13:39:53 (1790789993) [ 4485.110644] Lustre: lustre-MDT0000-mdc-ffff946cc86bc000: Connection restored to 192.168.203.117@tcp (at 192.168.203.117@tcp) [ 4485.115376] Lustre: Skipped 19 previous similar messages [ 4491.021120] Lustre: DEBUG MARKER: == replay-single test 56: don't replay a symlink open request (3440) ========================================================== 13:41:00 (1790790060) [ 4494.944621] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4531.015689] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4533.062286] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4551.552710] Lustre: DEBUG MARKER: == replay-single test 57: test recovery from llog for setattr op ========================================================== 13:42:01 (1790790121) [ 4556.491853] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4590.830548] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4592.513739] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4608.894373] Lustre: DEBUG MARKER: == replay-single test 58a: test recovery from llog for setattr op (test llog_gen_rec) ========================================================== 13:42:58 (1790790178) [ 4650.193539] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4654.063386] Lustre: lustre-MDT0000-mdc-ffff946cc86bc000: Connection to lustre-MDT0000 (at 192.168.203.117@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 4654.101230] Lustre: Skipped 11 previous similar messages [ 4694.614491] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4696.314112] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4750.588672] Lustre: DEBUG MARKER: == replay-single test 58b: test replay of setxattr op ==== 13:45:20 (1790790320) [ 4751.017203] Lustre: Mounted lustre-client - version 2.17.58_40_ge80375b [ 4755.073935] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4778.819083] Lustre: 15090:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.203.117@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 4799.412647] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4801.320180] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4805.669308] Lustre: Unmounted lustre-client [ 4810.570781] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount FULL mgc.*.mgs_server_uuid 1475 0 [ 4811.815513] Lustre: DEBUG MARKER: mgc.*.mgs_server_uuid in FULL state after 0 sec [ 4820.137240] Lustre: DEBUG MARKER: == replay-single test 58c: resend/reconstruct setxattr op ========================================================== 13:46:29 (1790790389) [ 4825.779261] Lustre: Mounted lustre-client - version 2.17.58_40_ge80375b [ 4951.008130] Lustre: 115285:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790790462/real 1790790462] req@ffff946cc4604700 x1877774874329600/t0(0) o36->lustre-MDT0000-mdc-ffff946cc86bc000@192.168.203.117@tcp:12/10 lens 66040/440 e 0 to 1 dl 1790790522 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'setfattr.0' uid:0 gid:0 projid:0 [ 4951.049895] Lustre: 115285:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 7 previous similar messages [ 4954.177301] Lustre: Unmounted lustre-client [ 4959.786567] Lustre: DEBUG MARKER: SKIP: replay-single test_59 skipping ALWAYS excluded test 59 [ 4961.136486] Lustre: DEBUG MARKER: == replay-single test 60: test llog post recovery init vs llog unlink ========================================================== 13:48:51 (1790790531) [ 4970.097808] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4991.904174] LustreError: MGC192.168.203.117@tcp: Connection to MGS (at 192.168.203.117@tcp) was lost; in progress operations using this service will fail [ 4991.925624] LustreError: Skipped 8 previous similar messages [ 4991.945676] Lustre: Evicted from MGS (at 192.168.203.117@tcp) after server handle changed from 0x231826f8a7bd7813 to 0x231826f8a7bda89c [ 4991.956976] Lustre: Skipped 9 previous similar messages [ 5002.120583] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5003.610656] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5012.679202] Lustre: DEBUG MARKER: == replay-single test 61a: test race llog recovery vs llog cleanup ========================================================== 13:49:42 (1790790582) [ 5031.079488] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-OST0000 [ 5113.383629] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 5115.595919] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 5155.064820] Lustre: DEBUG MARKER: == replay-single test 61b: test race mds llog sync vs llog cleanup ========================================================== 13:52:04 (1790790724) [ 5186.546129] Lustre: MGC192.168.203.117@tcp: Connection restored to 192.168.203.117@tcp (at 192.168.203.117@tcp) [ 5186.553738] Lustre: Skipped 13 previous similar messages [ 5226.664405] Lustre: 15090:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.203.117@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 5249.428453] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5251.039377] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5260.731800] Lustre: DEBUG MARKER: == replay-single test 61c: test race mds llog sync vs llog cleanup ========================================================== 13:53:50 (1790790830) [ 5276.662309] Lustre: lustre-OST0000-osc-ffff946cc86bc000: Connection to lustre-OST0000 (at 192.168.203.117@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 5276.694387] Lustre: Skipped 8 previous similar messages [ 5314.716598] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 5317.092206] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 5328.906853] Lustre: DEBUG MARKER: == replay-single test 61d: error in llog_setup should cleanup the llog context correctly ========================================================== 13:54:58 (1790790898) [ 5359.314249] Lustre: DEBUG MARKER: == replay-single test 62: don't mis-drop resent replay === 13:55:28 (1790790928) [ 5363.928397] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5389.115770] Lustre: 15090:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.203.117@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 5455.843947] LustreError: 2402:0:(client.c:3399:ptlrpc_replay_interpret()) @@@ request replay timed out req@ffff946cc45dce00 x1877774875193216/t313532612612(313532612612) o101->lustre-MDT0000-mdc-ffff946cc86bc000@192.168.203.117@tcp:12/10 lens 592/664 e 0 to 1 dl 1790791026 ref 2 fl Interpret:EXQU/604/ffffffff rc -110/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 5455.956602] LustreError: 2402:0:(client.c:3449:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff946cc45dce00 x1877774875193216/t313532612612(313532612612) o101->lustre-MDT0000-mdc-ffff946cc86bc000@192.168.203.117@tcp:12/10 lens 592/608 e 0 to 0 dl 1790791087 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'createmany.0' uid:0 gid:0 projid:0 [ 5455.997979] LustreError: 2402:0:(client.c:3449:ptlrpc_replay_interpret()) Skipped 19 previous similar messages [ 5462.454712] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5464.278695] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5474.352394] Lustre: DEBUG MARKER: == replay-single test 65a: AT: verify early replies ====== 13:57:24 (1790791044) [ 5533.312782] Lustre: DEBUG MARKER: == replay-single test 65b: AT: verify early replies on packed reply / bulk ========================================================== 13:58:23 (1790791103) [ 5583.805948] Lustre: DEBUG MARKER: == replay-single test 66a: AT: verify MDT service time adjusts with no early replies ========================================================== 13:59:13 (1790791153) [ 5648.771196] Lustre: DEBUG MARKER: == replay-single test 66b: AT: verify net latency adjusts ========================================================== 14:00:18 (1790791218) [ 5676.477842] LustreError: 128056:0:(client.c:1695:after_reply()) cfs_fail_timeout id 50c sleeping for 10000ms [ 5686.501606] LustreError: 128056:0:(client.c:1695:after_reply()) cfs_fail_timeout id 50c awake [ 5686.530261] LustreError: 128056:0:(client.c:1695:after_reply()) cfs_fail_timeout id 50c sleeping for 10000ms [ 5696.560139] LustreError: 128056:0:(client.c:1695:after_reply()) cfs_fail_timeout id 50c awake [ 5696.583266] LustreError: 128056:0:(client.c:1695:after_reply()) cfs_fail_timeout id 50c sleeping for 10000ms [ 5706.592145] LustreError: 128056:0:(client.c:1695:after_reply()) cfs_fail_timeout id 50c awake [ 5706.615265] LustreError: 128056:0:(client.c:1695:after_reply()) cfs_fail_timeout id 50c sleeping for 10000ms [ 5716.616136] LustreError: 128056:0:(client.c:1695:after_reply()) cfs_fail_timeout id 50c awake [ 5716.634742] LustreError: 2406:0:(client.c:1695:after_reply()) cfs_fail_timeout id 50c sleeping for 10000ms [ 5726.640426] LustreError: 2406:0:(client.c:1695:after_reply()) cfs_fail_timeout id 50c awake [ 5726.659170] LustreError: 128056:0:(client.c:1695:after_reply()) cfs_fail_timeout id 50c sleeping for 10000ms [ 5736.696471] LustreError: 128056:0:(client.c:1695:after_reply()) cfs_fail_timeout id 50c awake [ 5744.049525] Lustre: DEBUG MARKER: == replay-single test 67a: AT: verify slow request processing doesn't induce reconnects ========================================================== 14:01:53 (1790791313) [ 5824.484444] Lustre: DEBUG MARKER: == replay-single test 67b: AT: verify instant slowdown doesn't induce reconnects ========================================================== 14:03:14 (1790791394) [ 5862.169873] Lustre: DEBUG MARKER: phase 2 [ 5875.110530] Lustre: DEBUG MARKER: == replay-single test 68: AT: verify slowing locks ======= 14:04:04 (1790791444) [ 5905.487619] LustreError: 30435:0:(ldlm_request.c:1533:ldlm_cli_cancel_req()) cfs_fail_timeout id 312 sleeping for 19000ms [ 5924.544119] LustreError: 30435:0:(ldlm_request.c:1533:ldlm_cli_cancel_req()) cfs_fail_timeout id 312 awake [ 5958.709470] Lustre: DEBUG MARKER: == replay-single test 70a: check multi client t-f ======== 14:05:27 (1790791527) [ 5960.659686] Lustre: DEBUG MARKER: SKIP: replay-single test_70a Need two or more clients, have 1 [ 5962.504592] Lustre: DEBUG MARKER: == replay-single test 70b: dbench 2mdts recovery; 1 clients ========================================================== 14:05:32 (1790791532) [ 5969.215825] Lustre: DEBUG MARKER: Started rundbench load pid=131396 ... [ 5976.915222] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5979.602571] Lustre: DEBUG MARKER: test_70b fail mds1 1 times [ 5981.880627] LustreError: lustre-MDT0000-mdc-ffff946cc86bc000: operation mds_reint to node 192.168.203.117@tcp failed: rc = -19 [ 5981.890424] Lustre: lustre-MDT0000-mdc-ffff946cc86bc000: Connection to lustre-MDT0000 (at 192.168.203.117@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 5981.919285] Lustre: Skipped 2 previous similar messages [ 6000.608157] Lustre: 2406:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790791555/real 1790791555] req@ffff946cc4604000 x1877774875580672/t0(0) o400->MGC192.168.203.117@tcp@192.168.203.117@tcp:26/25 lens 224/224 e 0 to 1 dl 1790791571 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6000.632323] Lustre: 2406:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 6000.645523] LustreError: MGC192.168.203.117@tcp: Connection to MGS (at 192.168.203.117@tcp) was lost; in progress operations using this service will fail [ 6000.661944] LustreError: Skipped 4 previous similar messages [ 6005.897083] LustreError: 2402:0:(client.c:3449:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff946cc586a680 x1877774875421824/t317827580263(317827580263) o101->lustre-MDT0000-mdc-ffff946cc86bc000@192.168.203.117@tcp:12/10 lens 576/608 e 0 to 0 dl 1790791592 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'dbench.0' uid:0 gid:0 projid:0 [ 6005.922488] LustreError: 2402:0:(client.c:3449:ptlrpc_replay_interpret()) Skipped 24 previous similar messages [ 6008.125564] Lustre: lustre-MDT0000-mdc-ffff946cc86bc000: Connection restored to 192.168.203.117@tcp (at 192.168.203.117@tcp) [ 6008.146254] Lustre: Skipped 7 previous similar messages [ 6010.041772] Lustre: Evicted from MGS (at 192.168.203.117@tcp) after server handle changed from 0x231826f8a7bec81a to 0x231826f8a7bf3550 [ 6010.050542] Lustre: Skipped 4 previous similar messages [ 6018.148217] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6021.196857] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6029.473611] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 6031.996489] Lustre: DEBUG MARKER: test_70b fail mds2 2 times [ 6068.074223] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 6070.291357] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6079.238511] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 6082.585861] Lustre: DEBUG MARKER: test_70b fail mds1 3 times [ 6085.013703] LustreError: lustre-MDT0000-mdc-ffff946cc86bc000: operation ldlm_enqueue to node 192.168.203.117@tcp failed: rc = -19 [ 6114.425051] Lustre: 15090:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.203.117@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 6117.678961] LustreError: 2402:0:(client.c:3449:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff946cc586a680 x1877774875421824/t317827580263(317827580263) o101->lustre-MDT0000-mdc-ffff946cc86bc000@192.168.203.117@tcp:12/10 lens 576/608 e 0 to 0 dl 1790791704 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'dbench.0' uid:0 gid:0 projid:0 [ 6117.712722] LustreError: 2402:0:(client.c:3449:ptlrpc_replay_interpret()) Skipped 26 previous similar messages [ 6129.998650] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6131.361227] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6139.616679] Lustre: DEBUG MARKER: == replay-single test 70c: tar 2mdts recovery ============ 14:08:29 (1790791709) [ 6264.807543] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 6276.560236] Lustre: DEBUG MARKER: test_70c fail mds1 1 times [ 6279.530090] LustreError: lustre-MDT0000-mdc-ffff946cc86bc000: operation mds_reint to node 192.168.203.117@tcp failed: rc = -19 [ 6317.647327] LustreError: 2402:0:(client.c:3449:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff946cd04d5180 x1877774878887424/t326417517692(326417517692) o101->lustre-MDT0000-mdc-ffff946cc86bc000@192.168.203.117@tcp:12/10 lens 592/608 e 0 to 0 dl 1790791904 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'tar.0' uid:0 gid:0 projid:0 [ 6317.670134] LustreError: 2402:0:(client.c:3449:ptlrpc_replay_interpret()) Skipped 49 previous similar messages [ 6327.631960] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6329.183829] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6449.306932] Lustre: DEBUG MARKER: == replay-single test 70d: mkdir/rmdir striped dir 2mdts recovery ========================================================== 14:13:38 (1790792018) [ 6574.642781] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 6586.303250] Lustre: DEBUG MARKER: test_70d fail mds2 1 times [ 6594.021087] Lustre: lustre-MDT0001-mdc-ffff946cc86bc000: Connection to lustre-MDT0001 (at 192.168.203.117@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 6594.042690] Lustre: Skipped 3 previous similar messages [ 6609.471551] LustreError: 2402:0:(client.c:3449:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff946cc59f7100 x1877774881782016/t8589941062(8589941062) o101->lustre-MDT0001-mdc-ffff946cc86bc000@192.168.203.117@tcp:12/10 lens 648/608 e 0 to 0 dl 1790792196 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'lfs.0' uid:0 gid:0 projid:0 [ 6609.494509] LustreError: 2402:0:(client.c:3449:ptlrpc_replay_interpret()) Skipped 43 previous similar messages [ 6615.177485] Lustre: lustre-MDT0001-mdc-ffff946cc86bc000: Connection restored to 192.168.203.117@tcp (at 192.168.203.117@tcp) [ 6615.192660] Lustre: Skipped 6 previous similar messages [ 6622.374661] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 6624.566549] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6751.283966] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 6762.724705] Lustre: DEBUG MARKER: test_70d fail mds1 2 times [ 6784.480251] Lustre: 2405:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790792339/real 1790792339] req@ffff946cd1613480 x1877774885647616/t0(0) o400->MGC192.168.203.117@tcp@192.168.203.117@tcp:26/25 lens 224/224 e 0 to 1 dl 1790792355 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6784.520498] Lustre: 2405:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 6784.528472] LustreError: MGC192.168.203.117@tcp: Connection to MGS (at 192.168.203.117@tcp) was lost; in progress operations using this service will fail [ 6784.547288] LustreError: Skipped 2 previous similar messages [ 6794.687553] Lustre: Evicted from MGS (at 192.168.203.117@tcp) after server handle changed from 0x231826f8a7c2e156 to 0x231826f8a7cac0ae [ 6794.698818] Lustre: Skipped 2 previous similar messages [ 6800.085303] LustreError: 2402:0:(client.c:3449:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff946cd02dad80 x1877774885450240/t330712490969(330712490969) o101->lustre-MDT0000-mdc-ffff946cc86bc000@192.168.203.117@tcp:12/10 lens 576/608 e 0 to 0 dl 1790792457 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'touch.0' uid:0 gid:0 projid:0 [ 6800.138858] LustreError: 2402:0:(client.c:3449:ptlrpc_replay_interpret()) Skipped 17 previous similar messages [ 6811.540236] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6813.313632] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6822.388858] Lustre: DEBUG MARKER: == replay-single test 70e: rename cross-MDT with random fails ========================================================== 14:19:52 (1790792392) [ 6948.842996] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 6961.154474] Lustre: DEBUG MARKER: test_70e fail mds2 1 times [ 6999.889942] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 7001.730558] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7011.427693] Lustre: DEBUG MARKER: == replay-single test 70f: OSS O_DIRECT recovery with 1 clients ========================================================== 14:23:01 (1790792581) [ 7019.957073] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-OST0000 [ 7022.498934] Lustre: DEBUG MARKER: test_70f failing OST 1 times [ 7058.824969] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 7060.583889] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 7071.565498] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-OST0000 [ 7074.028841] Lustre: DEBUG MARKER: test_70f failing OST 2 times [ 7111.589319] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 7113.190384] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 7124.081829] Lustre: DEBUG MARKER: == replay-single test 71a: mkdir/rmdir striped dir with 2 mdts recovery ========================================================== 14:24:53 (1790792693) [ 7249.873436] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 7254.160237] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 7265.849619] Lustre: DEBUG MARKER: fail mds1 mds2 1 times [ 7268.761950] LustreError: lustre-MDT0000-mdc-ffff946cc86bc000: operation mds_reint to node 192.168.203.117@tcp failed: rc = -19 [ 7268.775773] Lustre: lustre-MDT0000-mdc-ffff946cc86bc000: Connection to lustre-MDT0000 (at 192.168.203.117@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 7268.788328] Lustre: Skipped 4 previous similar messages [ 7297.510403] Lustre: MGC192.168.203.117@tcp: Connection restored to 192.168.203.117@tcp (at 192.168.203.117@tcp) [ 7297.526809] Lustre: Skipped 4 previous similar messages [ 7301.003354] LustreError: 2402:0:(client.c:3449:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff946cd12a7800 x1877774888260608/t335007454652(335007454652) o101->lustre-MDT0000-mdc-ffff946cc86bc000@192.168.203.117@tcp:12/10 lens 520/664 e 0 to 0 dl 1790792888 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'lfs.0' uid:0 gid:0 projid:0 [ 7301.031965] LustreError: 2402:0:(client.c:3449:ptlrpc_replay_interpret()) Skipped 17 previous similar messages [ 7319.587709] Lustre: DEBUG MARKER: oleg317-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 [ 7321.015474] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7322.678729] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7330.409449] Lustre: DEBUG MARKER: == replay-single test 73a: open(O_CREAT), unlink, replay, reconnect before open replay, close ========================================================== 14:28:20 (1790792900) [ 7333.825335] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 7372.768206] LustreError: 2402:0:(client.c:3399:ptlrpc_replay_interpret()) @@@ request replay timed out req@ffff946cd12a7800 x1877774888260608/t335007454652(335007454652) o101->lustre-MDT0000-mdc-ffff946cc86bc000@192.168.203.117@tcp:12/10 lens 520/664 e 0 to 1 dl 1790792943 ref 2 fl Interpret:EXPQU/604/ffffffff rc -110/-1 job:'lfs.0' uid:0 gid:0 projid:0 [ 7377.879724] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 7379.247873] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7386.668264] Lustre: DEBUG MARKER: == replay-single test 73b: open(O_CREAT), unlink, replay, reconnect at open_replay reply, close ========================================================== 14:29:16 (1790792956) [ 7390.602777] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 7412.714833] LustreError: MGC192.168.203.117@tcp: Connection to MGS (at 192.168.203.117@tcp) was lost; in progress operations using this service will fail [ 7412.735534] LustreError: Skipped 2 previous similar messages [ 7412.752644] Lustre: Evicted from MGS (at 192.168.203.117@tcp) after server handle changed from 0x231826f8a7d1942a to 0x231826f8a7d1976b [ 7412.770940] Lustre: Skipped 2 previous similar messages [ 7413.867260] Lustre: 15090:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.203.117@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 7437.794919] Lustre: 2402:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790792992/real 1790792992] req@ffff946cd12a7800 x1877774888260608/t335007454652(335007454652) o101->lustre-MDT0000-mdc-ffff946cc86bc000@192.168.203.117@tcp:12/10 lens 520/664 e 0 to 1 dl 1790793008 ref 2 fl Rpc:XPQr/604/ffffffff rc 0/-1 job:'lfs.0' uid:0 gid:0 projid:0 [ 7437.845446] Lustre: 2402:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 9 previous similar messages [ 7437.867253] LustreError: 2402:0:(client.c:3399:ptlrpc_replay_interpret()) @@@ request replay timed out req@ffff946cd12a7800 x1877774888260608/t335007454652(335007454652) o101->lustre-MDT0000-mdc-ffff946cc86bc000@192.168.203.117@tcp:12/10 lens 520/664 e 0 to 1 dl 1790793008 ref 2 fl Interpret:EXPQU/604/ffffffff rc -110/-1 job:'lfs.0' uid:0 gid:0 projid:0 [ 7445.023639] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 7446.735228] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7454.919727] Lustre: DEBUG MARKER: == replay-single test 74: Ensure applications don't fail waiting for OST recovery ========================================================== 14:30:24 (1790793024) [ 7456.979229] Lustre: Unmounted lustre-client [ 7486.906902] Lustre: Mounted lustre-client - version 2.17.58_40_ge80375b [ 7492.099207] LustreError: lustre-OST0000-osc-ffff946cc7e14000: operation ost_connect to node 192.168.203.117@tcp failed: rc = -16 [ 7506.586363] Lustre: DEBUG MARKER: == replay-single test 80a: DNE: create remote dir, drop update rep from MDT0, fail MDT0 ========================================================== 14:31:16 (1790793076) [ 7510.766091] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 7534.700879] Lustre: 160198:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.203.117@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 7552.202342] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 7553.515712] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7560.955819] Lustre: DEBUG MARKER: == replay-single test 80b: DNE: create remote dir, drop update rep from MDT0, fail MDT1 ========================================================== 14:32:10 (1790793130) [ 7566.296865] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 7570.076395] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 7571.833737] LustreError: lustre-MDT0001-mdc-ffff946cc7e14000: operation mds_reint to node 192.168.203.117@tcp failed: rc = -19 [ 7571.841995] LustreError: Skipped 1 previous similar message [ 7608.346588] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 7609.724487] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7619.215432] Lustre: DEBUG MARKER: == replay-single test 80c: DNE: create remote dir, drop update rep from MDT1, fail MDT[0,1] ========================================================== 14:33:08 (1790793188) [ 7624.400604] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 7628.279737] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 7674.475610] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 7676.558413] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7711.798319] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 7713.241537] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7721.793347] Lustre: DEBUG MARKER: == replay-single test 80d: DNE: create remote dir, drop update rep from MDT1, fail 2 MDTs ========================================================== 14:34:51 (1790793291) [ 7729.553155] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 7733.339727] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 7738.726541] LustreError: lustre-MDT0001-mdc-ffff946cc7e14000: operation mds_reint to node 192.168.203.117@tcp failed: rc = -19 [ 7778.724811] Lustre: DEBUG MARKER: oleg317-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 [ 7780.011621] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7781.479289] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7789.903696] Lustre: DEBUG MARKER: == replay-single test 80e: DNE: create remote dir, drop MDT1 rep, fail MDT0 ========================================================== 14:35:59 (1790793359) [ 7797.242857] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 7818.415404] Lustre: 160198:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.203.117@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 7839.113288] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 7840.574654] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7849.045786] Lustre: DEBUG MARKER: == replay-single test 80f: DNE: create remote dir, drop MDT1 rep, fail MDT1 ========================================================== 14:36:59 (1790793419) [ 7853.510914] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 7887.300209] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 7888.792730] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7898.237996] Lustre: DEBUG MARKER: == replay-single test 80g: DNE: create remote dir, drop MDT1 rep, fail MDT0, then MDT1 ========================================================== 14:37:48 (1790793468) [ 7906.194621] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 7910.738718] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 7915.488147] Lustre: lustre-MDT0001-mdc-ffff946cc7e14000: Connection to lustre-MDT0001 (at 192.168.203.117@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 7915.507540] Lustre: Skipped 12 previous similar messages [ 7915.536662] Lustre: lustre-MDT0001-mdc-ffff946cc7e14000: Connection restored to 192.168.203.117@tcp (at 192.168.203.117@tcp) [ 7915.560894] Lustre: Skipped 19 previous similar messages [ 7955.769418] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 7957.364418] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7992.604702] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 7994.188444] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8001.921795] Lustre: DEBUG MARKER: == replay-single test 80h: DNE: create remote dir, drop MDT1 rep, fail 2 MDTs ========================================================== 14:39:31 (1790793571) [ 8009.701453] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 8014.071650] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 8034.785061] LustreError: MGC192.168.203.117@tcp: Connection to MGS (at 192.168.203.117@tcp) was lost; in progress operations using this service will fail [ 8034.802205] LustreError: Skipped 5 previous similar messages [ 8038.881340] Lustre: 2404:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790793594/real 1790793594] req@ffff946cc4536a00 x1877774889741056/t0(0) o400->lustre-MDT0001-mdc-ffff946cc7e14000@192.168.203.117@tcp:12/10 lens 224/224 e 0 to 1 dl 1790793610 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 8038.923388] Lustre: 2404:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 10 previous similar messages [ 8044.078204] Lustre: Evicted from MGS (at 192.168.203.117@tcp) after server handle changed from 0x231826f8a7d1ee9e to 0x231826f8a7d1fdb6 [ 8044.102158] Lustre: Skipped 5 previous similar messages [ 8065.166802] Lustre: DEBUG MARKER: oleg317-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 [ 8066.942420] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8068.294452] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8077.999174] Lustre: DEBUG MARKER: == replay-single test 81a: DNE: unlink remote dir, drop MDT0 update rep, fail MDT1 ========================================================== 14:40:47 (1790793647) [ 8083.193731] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 8085.042951] LustreError: lustre-MDT0001-mdc-ffff946cc7e14000: operation mds_reint to node 192.168.203.117@tcp failed: rc = -19 [ 8124.825552] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 8126.383193] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8133.963469] Lustre: DEBUG MARKER: == replay-single test 81b: DNE: unlink remote dir, drop MDT0 update reply, fail MDT0 ========================================================== 14:41:43 (1790793703) [ 8138.406937] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 8180.188414] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 8182.107688] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8190.263868] Lustre: DEBUG MARKER: == replay-single test 81c: DNE: unlink remote dir, drop MDT0 update reply, fail MDT0,MDT1 ========================================================== 14:42:40 (1790793760) [ 8195.318149] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 8198.961366] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 8230.778205] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 8232.480926] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8268.196112] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 8269.911949] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8277.884208] Lustre: DEBUG MARKER: == replay-single test 81d: DNE: unlink remote dir, drop MDT0 update reply, fail 2 MDTs ========================================================== 14:44:07 (1790793847) [ 8283.263724] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 8286.932154] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 8292.699946] LustreError: lustre-MDT0001-mdc-ffff946cc7e14000: operation mds_reint to node 192.168.203.117@tcp failed: rc = -19 [ 8333.476735] Lustre: DEBUG MARKER: oleg317-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 [ 8334.974561] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8336.301850] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8345.396360] Lustre: DEBUG MARKER: == replay-single test 81e: DNE: unlink remote dir, drop MDT1 req reply, fail MDT0 ========================================================== 14:45:15 (1790793915) [ 8351.839650] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 8386.166703] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 8387.591211] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8395.613788] Lustre: DEBUG MARKER: == replay-single test 81f: DNE: unlink remote dir, drop MDT1 req reply, fail MDT1 ========================================================== 14:46:05 (1790793965) [ 8400.012207] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 8432.357308] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 8434.015349] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8444.964867] Lustre: DEBUG MARKER: == replay-single test 81g: DNE: unlink remote dir, drop req reply, fail M0, then M1 ========================================================== 14:46:55 (1790794015) [ 8450.601246] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 8454.733400] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 8489.295423] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 8491.002106] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8520.093442] Lustre: lustre-MDT0001-mdc-ffff946cc7e14000: Connection restored to 192.168.203.117@tcp (at 192.168.203.117@tcp) [ 8520.098811] Lustre: Skipped 23 previous similar messages [ 8529.748454] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 8531.374389] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8539.070310] Lustre: DEBUG MARKER: == replay-single test 81h: DNE: unlink remote dir, drop request reply, fail 2 MDTs ========================================================== 14:48:29 (1790794109) [ 8543.735914] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 8547.066825] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0001 [ 8556.000204] Lustre: lustre-MDT0001-mdc-ffff946cc7e14000: Connection to lustre-MDT0001 (at 192.168.203.117@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 8556.011193] Lustre: Skipped 17 previous similar messages [ 8597.879710] Lustre: DEBUG MARKER: oleg317-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 [ 8599.566937] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8601.442349] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8610.633451] Lustre: DEBUG MARKER: == replay-single test 84a: stale open during export disconnect ========================================================== 14:49:40 (1790794180) [ 8614.535573] LustreError: lustre-MDT0000-mdc-ffff946cc7e14000: operation ldlm_enqueue to node 192.168.203.117@tcp failed: rc = -107 [ 8614.557208] LustreError: lustre-MDT0000-mdc-ffff946cc7e14000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 8614.577472] LustreError: 189501:0:(file.c:6167:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -5 [ 8622.961568] Lustre: DEBUG MARKER: == replay-single test 85a: check the cancellation of unused locks during recovery(IBITS) ========================================================== 14:49:52 (1790794192) [ 8646.631031] Lustre: 2404:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790794201/real 1790794201] req@ffff946cc596ed80 x1877774890023680/t0(0) o400->MGC192.168.203.117@tcp@192.168.203.117@tcp:26/25 lens 224/224 e 0 to 1 dl 1790794217 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 8646.683136] Lustre: 2404:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 18 previous similar messages [ 8646.705954] LustreError: MGC192.168.203.117@tcp: Connection to MGS (at 192.168.203.117@tcp) was lost; in progress operations using this service will fail [ 8646.715947] LustreError: Skipped 6 previous similar messages [ 8651.834422] LustreError: 2402:0:(client.c:3449:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff946cd12a5c00 x1877774889908864/t403726925837(403726925837) o101->lustre-MDT0000-mdc-ffff946cc7e14000@192.168.203.117@tcp:12/10 lens 576/608 e 0 to 0 dl 1790794238 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'grep.0' uid:0 gid:0 projid:0 [ 8651.889818] LustreError: 2402:0:(client.c:3449:ptlrpc_replay_interpret()) Skipped 7 previous similar messages [ 8656.431881] Lustre: Evicted from MGS (at 192.168.203.117@tcp) after server handle changed from 0x231826f8a7d23ec3 to 0x231826f8a7d2733c [ 8656.447268] Lustre: Skipped 6 previous similar messages [ 8663.711646] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 8665.124170] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8672.931483] Lustre: DEBUG MARKER: == replay-single test 85b: check the cancellation of unused locks during recovery(EXTENT) ========================================================== 14:50:42 (1790794242) [ 8722.313103] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 8723.704456] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 8732.143780] Lustre: DEBUG MARKER: == replay-single test 86: umount server after clear nid_stats should not hit LBUG ========================================================== 14:51:42 (1790794302) [ 8734.704087] Lustre: Unmounted lustre-client [ 8750.485950] Lustre: Mounted lustre-client - version 2.17.58_40_ge80375b [ 8755.859273] Lustre: DEBUG MARKER: == replay-single test 87a: write replay ================== 14:52:05 (1790794325) [ 8760.075337] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-OST0000 [ 8795.607441] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 8797.220853] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 8806.091322] Lustre: DEBUG MARKER: == replay-single test 87b: write replay with changed data (checksum resend) ========================================================== 14:52:55 (1790794375) [ 8810.600576] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-OST0000 [ 8846.374408] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 8847.431967] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 8854.700979] Lustre: DEBUG MARKER: == replay-single test 88: MDS should not assign same objid to different files ========================================================== 14:53:44 (1790794424) [ 8859.690725] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-OST0000 [ 8864.897775] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 8906.285835] LustreError: 2402:0:(client.c:3449:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff946cd1f0c700 x1877774890326656/t412316860431(412316860431) o101->lustre-MDT0000-mdc-ffff946cd1fce800@192.168.203.117@tcp:12/10 lens 576/608 e 0 to 0 dl 1790794493 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'md5sum.0' uid:0 gid:0 projid:0 [ 8906.316827] LustreError: 2402:0:(client.c:3449:ptlrpc_replay_interpret()) Skipped 99 previous similar messages [ 8953.910941] Lustre: DEBUG MARKER: == replay-single test 89: no disk space leak on late ost connection ========================================================== 14:55:23 (1790794523) [ 9000.622370] Lustre: Unmounted lustre-client [ 9014.627696] Lustre: Mounted lustre-client - version 2.17.58_40_ge80375b [ 9014.665201] LustreError: lustre-OST0000-osc-ffff946cc86dd000: operation ost_connect to node 192.168.203.117@tcp failed: rc = -16 [ 9083.391296] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 61 sec [ 9098.486549] Lustre: DEBUG MARKER: free_before: 7520256 free_after: 7520256 [ 9103.985768] Lustre: DEBUG MARKER: == replay-single test 90: lfs find identifies the missing striped file segments ========================================================== 14:57:53 (1790794673) [ 9128.894614] Lustre: lustre-OST0000-osc-ffff946cc86dd000: Connection restored to 192.168.203.117@tcp (at 192.168.203.117@tcp) [ 9128.904475] Lustre: Skipped 12 previous similar messages [ 9143.317027] Lustre: DEBUG MARKER: == replay-single test 93a: replay + reconnect ============ 14:58:33 (1790794713) [ 9212.995691] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 9214.291939] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 9221.797286] Lustre: DEBUG MARKER: == replay-single test 93b: replay + reconnect on mds ===== 14:59:51 (1790794791) [ 9228.772662] Lustre: lustre-MDT0000-mdc-ffff946cc86dd000: Connection to lustre-MDT0000 (at 192.168.203.117@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 9228.785085] Lustre: Skipped 12 previous similar messages [ 9255.733505] Lustre: 199141:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.203.117@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 9274.336141] Lustre: 2402:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790794829/real 1790794829] req@ffff946cd1613100 x1877774890497664/t0(0) o400->lustre-MDT0000-mdc-ffff946cc86dd000@192.168.203.117@tcp:12/10 lens 224/224 e 0 to 1 dl 1790794845 ref 1 fl Rpc:XQr/2c0/ffffffff rc 0/-1 job:'ldlm_lock_repla.0' uid:0 gid:0 projid:4294967295 [ 9274.363918] Lustre: 2402:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 5 previous similar messages [ 9349.724921] Lustre: DEBUG MARKER: oleg317-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 9351.771430] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 9359.933773] Lustre: DEBUG MARKER: == replay-single test complete, duration 9071 sec ======== 15:02:09 (1790794929) [ 9361.924873] Lustre: DEBUG MARKER: === replay-single: start cleanup 15:02:11 (1790794931) === [ 9372.993577] Lustre: DEBUG MARKER: === replay-single: finish cleanup 15:02:22 (1790794942) === [ 9399.993152] Lustre: Unmounted lustre-client [ 9444.044720] Key type lgssc unregistered [ 9444.362827] LNet: 205633:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 9444.369902] LNetError: 205633:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 9444.396252] LNet: Removed LNI 192.168.203.17@tcp [ 9445.336452] Key type .llcrypt unregistered [ 9445.338359] Key type ._llcrypt unregistered