[ 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 467098287 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2399.998 MHz processor [ 0.000000] last_pfn = 0x146e00 max_arch_pfn = 0x400000000 [ 0.000000] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT [ 0.000000] last_pfn = 0xbffda max_arch_pfn = 0x400000000 [ 0.000000] found SMP MP-table at [mem 0x000f54d0-0x000f54df] [ 0.000000] RAMDISK: [mem 0xbcc64000-0xbffcffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F52F0 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE2464 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE2300 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 0022C0 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE2374 000090 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE2404 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE243C 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe2300-0xbffe2373] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe22ff] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe2374-0xbffe2403] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe2404-0xbffe243b] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe243c-0xbffe2463] [ 0.000000] No NUMA configuration found [ 0.000000] Faking a node at [mem 0x0000000000000000-0x0000000146dfffff] [ 0.000000] NODE_DATA(0) allocated [mem 0x1465a3000-0x1465cdfff] [ 0.000000] Reserving 256MB of memory at 2752MB for crashkernel (System RAM: 4205MB) [ 0.000000] Zone ranges: [ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.000000] DMA32 [mem 0x0000000001000000-0x00000000ffffffff] [ 0.000000] Normal [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Device empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff] [ 0.000000] node 0: [mem 0x0000000000100000-0x00000000bffd9fff] [ 0.000000] node 0: [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Zeroed struct page in unavailable ranges: 4744 pages [ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x0000000146dfffff] [ 0.000000] ACPI: PM-Timer IO Port: 0x608 [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) [ 0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) [ 0.000000] Using ACPI (MADT) for SMP configuration information [ 0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000] TSC deadline timer available [ 0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs [ 0.000000] kvm-guest: KVM setup pv remote TLB flush [ 0.000000] kvm-guest: setup PV sched yield [ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff] [ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff] [ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff] [ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff] [ 0.000000] PM: Registered nosave memory: [mem 0xbffda000-0xbfffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xc0000000-0xfeffbfff] [ 0.000000] PM: Registered nosave memory: [mem 0xfeffc000-0xfeffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xff000000-0xfffbffff] [ 0.000000] PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff] [ 0.000000] [mem 0xc0000000-0xfeffbfff] available for PCI devices [ 0.000000] Booting paravirtualized kernel on KVM [ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns [ 0.000000] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1 [ 0.000000] percpu: Embedded 63 pages/cpu s221184 r8192 d28672 u524288 [ 0.000000] kvm-guest: PV spinlocks enabled [ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1059618 [ 0.000000] Policy zone: Normal [ 0.000000] Kernel command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] Specific versions of hardware are certified with Red Hat Enterprise Linux 8. Please see the list of hardware certified with Red Hat Enterprise Linux 8 at https://catalog.redhat.com. [ 0.000000] audit: disabled (until reboot) [ 0.000000] software IO TLB: area num 4. [ 0.000000] Memory: 2829700K/4306400K available (18435K kernel code, 11221K rwdata, 7248K rodata, 2908K init, 18040K bss, 524584K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] ftrace: allocating 41240 entries in 162 pages [ 0.000000] ftrace: allocated 162 pages with 3 groups [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] rcu: RCU event tracing is enabled. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ 0.000000] rcu: RCU callback double-/use-after-free debug enabled. [ 0.000000] Rude variant of Tasks RCU enabled. [ 0.000000] Tracing variant of Tasks RCU enabled. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 0.000000] NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16 [ 0.000000] random: get_random_bytes called from start_kernel+0x622/0x9a8 with crng_init=0 [ 0.001000] Console: colour *CGA 80x25 [ 0.001000] printk: console [ttyS1] enabled [ 0.001000] ACPI: Core revision 20220331 [ 0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.001012] APIC: Switch to symmetric I/O mode setup [ 0.002378] x2apic enabled [ 0.003009] Switched APIC routing to physical x2apic. [ 0.004013] kvm-guest: setup PV IPIs [ 0.007000] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.007000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.007021] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.008012] pid_max: default: 32768 minimum: 301 [ 0.009143] LSM: Security Framework initializing [ 0.011025] Yama: becoming mindful. [ 0.011690] SELinux: Initializing. [ 0.012047] *** VALIDATE selinux *** [ 0.019607] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.023721] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.024151] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.025108] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.027059] *** VALIDATE tmpfs *** [ 0.028201] *** VALIDATE proc *** [ 0.029181] *** VALIDATE cgroup *** [ 0.029959] *** VALIDATE cgroup2 *** [ 0.031059] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.032124] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.033009] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.034027] Spectre V2 : User space: Vulnerable [ 0.035006] Speculative Store Bypass: Vulnerable [ 0.038451] debug: unmapping init [mem 0xffffffffb3a59000-0xffffffffb3a60fff] [ 0.040836] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.041709] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.042024] ... version: 2 [ 0.043014] ... bit width: 48 [ 0.044013] ... generic registers: 4 [ 0.045011] ... value mask: 0000ffffffffffff [ 0.046015] ... max period: 00007fffffffffff [ 0.047013] ... fixed-purpose events: 3 [ 0.048012] ... event mask: 000000070000000f [ 0.049313] rcu: Hierarchical SRCU implementation. [ 0.051447] smp: Bringing up secondary CPUs ... [ 0.052577] x86: Booting SMP configuration: [ 0.053036] .... node #0, CPUs: #1 #2 #3 [ 0.056293] smp: Brought up 1 node, 4 CPUs [ 0.058011] smpboot: Max logical packages: 1 [ 0.059019] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.144557] node 0 deferred pages initialised in 82ms [ 0.148096] devtmpfs: initialized [ 0.149270] x86/mm: Memory block size: 128MB [ 0.151698] gcov: version magic: 0x41383552 [ 0.155082] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.156074] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.157278] pinctrl core: initialized pinctrl subsystem [ 0.158192] [ 0.159009] ************************************************************* [ 0.160015] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.161012] ** ** [ 0.162015] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.163012] ** ** [ 0.164016] ** This means that this kernel is built to expose internal ** [ 0.165011] ** IOMMU data structures, which may compromise security on ** [ 0.166013] ** your system. ** [ 0.167012] ** ** [ 0.168013] ** If you see this message and you are not debugging the ** [ 0.169013] ** kernel, report this immediately to your vendor! ** [ 0.170011] ** ** [ 0.171014] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.172009] ************************************************************* [ 0.173535] NET: Registered protocol family 16 [ 0.174353] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.176043] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.178044] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.180349] cpuidle: using governor menu [ 0.182515] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.184490] PCI: Using configuration type 1 for base access [ 0.187129] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.196064] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.198031] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.202071] cryptd: max_cpu_qlen set to 1000 [ 0.205243] ACPI: Added _OSI(Module Device) [ 0.207017] ACPI: Added _OSI(Processor Device) [ 0.208011] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.210013] ACPI: Added _OSI(Processor Aggregator Device) [ 0.215442] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.221590] ACPI: Interpreter enabled [ 0.223061] ACPI: PM: (supports S0 S3 S4 S5) [ 0.224017] ACPI: Using IOAPIC for interrupt routing [ 0.226101] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.229378] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.238572] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.241045] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.244019] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.247082] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.252468] acpiphp: Slot [2] registered [ 0.254113] acpiphp: Slot [5] registered [ 0.255110] acpiphp: Slot [6] registered [ 0.257148] acpiphp: Slot [3] registered [ 0.258084] acpiphp: Slot [4] registered [ 0.259086] acpiphp: Slot [7] registered [ 0.261119] acpiphp: Slot [8] registered [ 0.262096] acpiphp: Slot [9] registered [ 0.264096] acpiphp: Slot [10] registered [ 0.265102] acpiphp: Slot [11] registered [ 0.267099] acpiphp: Slot [12] registered [ 0.268106] acpiphp: Slot [13] registered [ 0.270102] acpiphp: Slot [14] registered [ 0.271079] acpiphp: Slot [15] registered [ 0.272076] acpiphp: Slot [16] registered [ 0.274147] acpiphp: Slot [17] registered [ 0.275109] acpiphp: Slot [18] registered [ 0.276173] acpiphp: Slot [19] registered [ 0.278106] acpiphp: Slot [20] registered [ 0.279140] acpiphp: Slot [21] registered [ 0.281108] acpiphp: Slot [22] registered [ 0.282090] acpiphp: Slot [23] registered [ 0.284100] acpiphp: Slot [24] registered [ 0.285118] acpiphp: Slot [25] registered [ 0.287101] acpiphp: Slot [26] registered [ 0.288090] acpiphp: Slot [27] registered [ 0.290100] acpiphp: Slot [28] registered [ 0.291091] acpiphp: Slot [29] registered [ 0.293101] acpiphp: Slot [30] registered [ 0.294088] acpiphp: Slot [31] registered [ 0.295164] PCI host bridge to bus 0000:00 [ 0.297018] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.300028] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.302022] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.305031] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.307024] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.309021] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.311181] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.313902] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.316009] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.322623] pci 0000:00:01.1: reg 0x20: [io 0xc120-0xc12f] [ 0.327096] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.331023] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.334018] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.336024] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.339565] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.341844] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.345049] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.348091] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.352017] pci 0000:00:02.0: reg 0x10: [io 0xc100-0xc11f] [ 0.362018] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.367014] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.372471] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.382015] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.387014] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.399017] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.409931] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.420019] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.430018] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.450019] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.460080] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.463070] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.466351] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.468340] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.470264] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.474106] iommu: Default domain type: Passthrough [ 0.476395] SCSI subsystem initialized [ 0.477218] ACPI: bus type USB registered [ 0.479132] usbcore: registered new interface driver usbfs [ 0.481080] usbcore: registered new interface driver hub [ 0.483080] usbcore: registered new device driver usb [ 0.485169] pps_core: LinuxPPS API ver. 1 registered [ 0.487012] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.490058] PTP clock support registered [ 0.491136] EDAC MC: Ver: 3.0.0 [ 0.492136] PCI: Using ACPI for IRQ routing [ 0.494023] NetLabel: Initializing [ 0.495009] NetLabel: domain hash size = 128 [ 0.497010] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.499079] NetLabel: unlabeled traffic allowed by default [ 0.501326] vgaarb: loaded [ 0.503380] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.504014] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.514000] clocksource: Switched to clocksource kvm-clock [ 0.622513] VFS: Disk quotas dquot_6.6.0 [ 0.624084] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.626680] *** VALIDATE ramfs *** [ 0.627941] *** VALIDATE hugetlbfs *** [ 0.629532] pnp: PnP ACPI init [ 0.632294] pnp: PnP ACPI: found 6 devices [ 0.649424] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.652931] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.655268] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.657630] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.659727] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.662280] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.665333] NET: Registered protocol family 2 [ 0.667886] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.672447] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.676256] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.681545] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.685166] TCP: Hash tables configured (established 65536 bind 65536) [ 0.688180] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.691464] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.694368] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.697809] NET: Registered protocol family 1 [ 0.700651] RPC: Registered named UNIX socket transport module. [ 0.702749] RPC: Registered udp transport module. [ 0.704596] RPC: Registered tcp transport module. [ 0.706339] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.708865] NET: Registered protocol family 44 [ 0.710775] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.713222] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.715597] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.717938] PCI: CLS 0 bytes, default 64 [ 0.719583] Unpacking initramfs... [ 2.052909] debug: unmapping init [mem 0xffffa0867cc64000-0xffffa0867ffcffff] [ 2.055820] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.058271] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.060632] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 2.546474] Initialise system trusted keyrings [ 2.548363] Key type blacklist registered [ 2.550301] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.559070] zbud: loaded [ 2.562125] *** VALIDATE nfs *** [ 2.563411] *** VALIDATE nfs4 *** [ 2.565963] pstore: using deflate compression [ 2.569485] Platform Keyring initialized [ 2.676800] NET: Registered protocol family 38 [ 2.678898] Key type asymmetric registered [ 2.680826] Asymmetric key parser 'x509' registered [ 2.682734] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 2.686750] io scheduler mq-deadline registered [ 2.688344] io scheduler kyber registered [ 2.689990] io scheduler bfq registered [ 2.691787] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 2.694586] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 2.696757] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 2.699601] ACPI: Power Button [PWRF] [ 2.706638] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 2.715803] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 2.732147] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 2.761628] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 2.790287] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 2.794809] Non-volatile memory driver v1.3 [ 2.796636] Linux agpgart interface v0.103 [ 2.831707] virtio_blk virtio1: [vda] 146640 512-byte logical blocks (75.1 MB/71.6 MiB) [ 2.834235] vda: detected capacity change from 0 to 75079680 [ 2.850727] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 2.853456] vdb: detected capacity change from 0 to 1073741824 [ 2.861901] libphy: Fixed MDIO Bus: probed [ 2.872160] usbcore: registered new interface driver usbserial_generic [ 2.874580] usbserial: USB Serial support registered for generic [ 2.876793] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 2.881509] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 2.883028] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 2.885124] mousedev: PS/2 mouse device common for all mice [ 2.887668] rtc_cmos 00:05: RTC can wake from S4 [ 2.890754] rtc_cmos 00:05: registered as rtc0 [ 2.892516] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 2.895129] intel_pstate: CPU model not supported [ 2.896792] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 2.900679] hid: raw HID events driver (C) Jiri Kosina [ 2.902386] usbcore: registered new interface driver usbhid [ 2.904512] usbhid: USB HID core driver [ 2.906179] drop_monitor: Initializing network drop monitor service [ 2.908244] Initializing XFRM netlink socket [ 2.908806] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 2.910250] NET: Registered protocol family 10 [ 2.915597] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 2.916735] Segment Routing with IPv6 [ 2.919459] NET: Registered protocol family 17 [ 2.921215] mpls_gso: MPLS GSO support [ 2.925958] RAS: Correctable Errors collector initialized. [ 2.927543] AVX version of gcm_enc/dec engaged. [ 2.928718] AES CTR mode by8 optimization enabled [ 2.991492] sched_clock: Marking stable (2991456452, 0)->(3891904312, -900447860) [ 2.994306] registered taskstats version 1 [ 2.996209] Loading compiled-in X.509 certificates [ 2.998140] zswap: loaded using pool lzo/zbud [ 3.018707] Key type big_key registered [ 3.028384] Key type encrypted registered [ 3.029451] ima: No TPM chip found, activating TPM-bypass! [ 3.030750] ima: Allocated hash algorithm: sha1 [ 3.031836] ima: No architecture policies found [ 3.032905] evm: Initialising EVM extended attributes: [ 3.034192] evm: security.selinux [ 3.034812] evm: security.ima [ 3.035582] evm: security.capability [ 3.036543] evm: HMAC attrs: 0x1 [ 3.038122] rtc_cmos 00:05: setting system clock to 2026-09-05 03:58:35 UTC (1788580715) [ 3.042119] debug: unmapping init [mem 0xffffffffb4a03000-0xffffffffb4bfffff] [ 3.044292] debug: unmapping init [mem 0xffffffffb3782000-0xffffffffb3a58fff] [ 3.052081] Write protecting the kernel read-only data: 28672k [ 3.054367] debug: unmapping init [mem 0xffffffffb1e03000-0xffffffffb1ffffff] [ 3.056120] debug: unmapping init [mem 0xffffffffb2714000-0xffffffffb27fffff] [ 3.079824] 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.088255] systemd[1]: Detected virtualization kvm. [ 3.090021] systemd[1]: Detected architecture x86-64. [ 3.092225] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.119168] systemd[1]: No hostname configured. [ 3.121472] systemd[1]: Set hostname to . [ 3.124256] random: systemd: uninitialized urandom read (16 bytes read) [ 3.128258] systemd[1]: Initializing machine ID from random generator. [ 3.179195] random: ln: uninitialized urandom read (6 bytes read) [ 3.255469] random: systemd: uninitialized urandom read (16 bytes read) [ 3.257744] systemd[1]: Reached target Local File Systems. [ OK ] Reached target Local File Systems. [ 3.261541] systemd[1]: Reached target Slices. [ OK ] Reached target Slices. [ 3.264113] systemd[1]: Reached target Swap. [ OK ] Reached target Swap. [ OK ] Listening on Journal Socket (/dev/log). [ OK ] Reached target Initrd Root Device. [ OK ] Listening on udev Kernel Socket. [ OK ] Listening on Journal Socket. Starting Create Volatile Files and Directories... Starting Apply Kernel Variables... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Paths. [ OK ] Reached target Local Encrypted Volumes. Starting Setup Virtual Console... Starting Journal Service... [ OK ] Listening on udev Control Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Timers. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Started Memstrack Anylazing Service. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Apply Kernel Variables. [ OK ] Started Setup Virtual Console. [ 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 Journal Service. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 3.844774] device-mapper: uevent: version 1.0.3 [ 3.846474] device-mapper: ioctl: 4.46.0-ioctl (2022-02-22) initialised: dm-devel@redhat.com [ OK ] Started dracut pre-udev hook. Starting udev Kernel Device Manager... [ OK ] Started udev Kernel Device Manager. Starting dracut pre-trigger hook... [ OK ] Started dracut pre-trigger hook. Starting udev Coldplug all Devices... Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting dracut initqueue hook... [ 4.600087] virtio_net virtio0 ens2: renamed from eth0 [ 4.656644] scsi host0: ata_piix [ 4.738779] scsi host1: ata_piix [ 4.740551] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc120 irq 14 [ 4.742443] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc128 irq 15 [ 9.552589] random: crng init done [ 9.554240] random: 7 urandom warning(s) missed due to ratelimiting [ 9.857534] dracut-initqueue[588]: RTNETLINK answers: File exists Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Mounting /sysroot... [ 11.860868] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped dracut pre-pivot and cleanup hook. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped target Timers. [ 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 ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped target Basic System. [ OK ] Stopped target Slices. [ OK ] Stopped target Paths. [ OK ] Stopped target Sockets. [ OK ] Stopped target System Initialization. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. Stopping udev Kernel Device Manager... [ OK ] Stopped target Swap. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Closed udev Kernel Socket. [ OK ] Closed udev Control Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 15.142436] printk: systemd: 24 output lines suppressed due to ratelimiting [ 16.225422] SELinux: Disabled at runtime. [ 16.394402] 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) [ 16.419353] systemd[1]: Detected virtualization kvm. [ 16.427865] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 18.312830] systemd[1]: initrd-switch-root.service: Succeeded. [ 18.320193] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 18.333713] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 18.345976] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 18.356926] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 18.395305] systemd[1]: Starting Journal Service... Starting Journal Service... [ 18.412920] systemd[1]: Reached target rpc_pipefs.target. [ OK ] Reached target rpc_pipefs.target. [ OK ] Listening on udev Kernel Socket. [ OK ] Created slice User and Session Slice. Mounting POSIX Message Queue File System... Mounting Kernel Debug File System... [ OK ] Created slice system-getty.slice. [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd File Systems. Mounting Huge Pages File System... [ OK ] Stopped target Initrd Root File System. Starting Remount Root and Kernel File Systems... [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Reached target RPC Port Mapper. [ OK ] Listening on udev Control Socket. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Created slice system-sshd\x2dkeygen.slice. Starting udev Coldplug all Devices... Starting Apply Kernel Variables... [ OK ] Listening on Process Core Dump Socket. [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Reached target Slices. [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Listening on initctl Compatibility Named Pipe. Activating swap /dev/disk/by-label/SWAP... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Paths. [ OK ] Reached target Local Encrypted Volumes. [ 18.934308] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS [ OK ] Started Journal Service. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Mounted Kernel Debug 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 Create list of required sta…vice nodes for the current kernel. [ OK ] Started Apply Kernel Variables. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Reached target Swap. Starting Create Static Device Nodes in /dev... Starting Configure read-only root support... Starting Flush Journal to Persistent Storage... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started udev Coldplug all Devices. Starting udev Kernel Device Manager... [ OK ] Reached target Local File Systems (Pre). Mounting /home/green/git/lustre-release... Mounting /mnt... [ OK ] Mounted /mnt. [ 19.701705] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 20.639894] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 20.645248] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 21.128169] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 21.189215] EDAC sbridge: Ver: 1.1.2 [ 25.008318] Key type dns_resolver registered [* ] A start job is running for Configur…-only root support (7s / no limit)[ 25.872131] NFS: Registering the id_resolver key type [ 25.874882] Key type id_resolver registered [ 25.878846] Key type id_legacy registered [** ] A start job is running for Configur…-only root support (7s / no limit) [*** ] A start job is running for Configur…-only root support (8s / no limit) [ OK ] Started Configure read-only root support. Starting Load/Save Random Seed... [ OK ] Reached target Local File Systems. Starting Rebuild Dynamic Linker Cache... Starting Create Volatile Files and Directories... Starting Mark the need to relabel after reboot... [ OK ] Started Load/Save Random Seed. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Mark the need to relabel after reboot. Starting RPC Bind... Starting Update UTMP about System Boot/Shutdown... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Started dnf makecache --timer. [ OK ] Reached target Timers. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. Starting Login Service... [ OK ] Reached target sshd-keygen.target. [ OK ] Started irqbalance daemon. Starting Restore /run/initramfs on shutdown... [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Started D-Bus System Message Bus. Starting Network Manager... [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Login Service. [ OK ] Started Network Manager. [ OK ] Reached target Network. Starting GSSAPI Proxy Daemon... Starting Dynamic System Tuning Daemon... Starting OpenSSH server daemon... Starting Network Manager Wait Online... [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... Starting Hostname Service... [ OK ] Started OpenSSH server daemon. [ OK ] Started Permit User Sessions. [ OK ] Started Serial Getty on ttyS1. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Getty on tty1. [ OK ] Reached target Login Prompts. [ OK ] Started Command Scheduler. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting Notify NFS peers of a restart... Starting System Logging Service... Starting Crash recovery kernel arming... [ 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 oleg147-client login: [ 98.822663] libcfs: loading out-of-tree module taints kernel. [ 99.273568] Key type ._llcrypt registered [ 99.276749] Key type .llcrypt registered [ 100.119489] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [ 100.142581] alg: No test for adler32 (adler32-zlib) [ 101.648689] Lustre: Lustre: Build Version: 2.17.57_103_g3d8212a [ 102.814453] LNet: Added LNI 192.168.201.47@tcp [8/256/0/180] [ 104.623222] Key type lgssc registered [ 106.629892] Lustre: Echo OBD driver; http://www.lustre.org/ [ 239.696195] hrtimer: interrupt took 12184638 ns [ 240.414552] Lustre: Mounted lustre-client - version 2.17.57_103_g3d8212a [ 246.360907] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 259.566757] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing check_logdir /tmp/testlogs/ [ 265.254282] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing yml_node [ 266.212140] Lustre: lustre-OST0000-osc-ffffa086d0876800: disconnect after 23s idle [ 270.099852] Lustre: DEBUG MARKER: Client: 2.17.57.103 [ 272.961155] Lustre: DEBUG MARKER: MDS: 2.17.57.103 [ 276.041469] Lustre: DEBUG MARKER: OSS: 2.17.57.103 [ 277.630523] Lustre: DEBUG MARKER: -----============= acceptance-small: replay-single ============----- Sat Sep 5 00:03:08 EDT 2026 [ 296.403744] Lustre: DEBUG MARKER: excepting tests: 59 36 [ 299.377141] Lustre: DEBUG MARKER: === replay-single: start setup 00:03:29 (1788581009) === [ 307.860325] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing check_config_client /mnt/lustre [ 326.331641] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 338.888934] Lustre: DEBUG MARKER: === replay-single: finish setup 00:04:10 (1788581050) === [ 342.000448] Lustre: DEBUG MARKER: == replay-single test 0a: empty replay =================== 00:04:12 (1788581052) [ 347.103055] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 363.487666] Lustre: lustre-OST0000-osc-ffffa086d0876800: disconnect after 20s idle [ 363.499173] Lustre: Skipped 1 previous similar message [ 368.607945] Lustre: 2356:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788581065/real 1788581065] req@ffffa086c5703480 x1875462916684800/t0(0) o400->lustre-MDT0000-mdc-ffffa086d0876800@192.168.201.147@tcp:12/10 lens 224/224 e 0 to 1 dl 1788581081 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 368.632760] Lustre: lustre-MDT0000-mdc-ffffa086d0876800: Connection to lustre-MDT0000 (at 192.168.201.147@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 368.643367] LustreError: MGC192.168.201.147@tcp: Connection to MGS (at 192.168.201.147@tcp) was lost; in progress operations using this service will fail [ 373.539290] Lustre: 2357:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788581070/real 1788581070] req@ffffa086d0ee5c00 x1875462916685312/t0(0) o400->lustre-MDT0000-mdc-ffffa086d0876800@192.168.201.147@tcp:12/10 lens 224/224 e 0 to 1 dl 1788581086 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 373.567341] Lustre: 2357:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 378.847211] Lustre: 2356:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788581075/real 1788581075] req@ffffa086c5703b80 x1875462916685824/t0(0) o400->lustre-MDT0000-mdc-ffffa086d0876800@192.168.201.147@tcp:12/10 lens 224/224 e 0 to 1 dl 1788581091 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 378.865091] Lustre: Evicted from MGS (at 192.168.201.147@tcp) after server handle changed from 0x83bb3162d487e0eb to 0x83bb3162d487e3ed [ 378.923745] Lustre: MGC192.168.201.147@tcp: Connection restored to 192.168.201.147@tcp (at 192.168.201.147@tcp) [ 384.991184] Lustre: 2358:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788581081/real 1788581081] req@ffffa086d0d71500 x1875462916686336/t0(0) o400->lustre-MDT0000-mdc-ffffa086d0876800@192.168.201.147@tcp:12/10 lens 224/224 e 0 to 1 dl 1788581097 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 394.219425] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 396.193342] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 405.221705] Lustre: DEBUG MARKER: == replay-single test 0b: ensure object created after recover exists. (3284) ========================================================== 00:05:16 (1788581116) [ 409.570409] Lustre: lustre-OST0000-osc-ffffa086d0876800: Connection to lustre-OST0000 (at 192.168.201.147@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 419.807429] Lustre: lustre-OST0001-osc-ffffa086d0876800: disconnect after 22s idle [ 419.809901] Lustre: Skipped 1 previous similar message [ 430.203432] Lustre: lustre-OST0000-osc-ffffa086d0876800: Connection restored to 192.168.201.147@tcp (at 192.168.201.147@tcp) [ 430.214420] Lustre: Skipped 1 previous similar message [ 446.987495] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 449.037625] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 459.462242] Lustre: DEBUG MARKER: == replay-single test 0c: check replay-barrier =========== 00:06:10 (1788581170) [ 464.268248] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 464.453749] Lustre: Unmounted lustre-client [ 505.078322] LustreError: lustre-MDT0000-mdc-ffffa086d0979000: operation mds_connect to node 192.168.201.147@tcp failed: rc = -16 [ 510.482587] LustreError: lustre-MDT0000-mdc-ffffa086d0979000: operation mds_connect to node 192.168.201.147@tcp failed: rc = -16 [ 515.571218] LustreError: lustre-MDT0000-mdc-ffffa086d0979000: operation mds_connect to node 192.168.201.147@tcp failed: rc = -16 [ 520.705766] LustreError: lustre-MDT0000-mdc-ffffa086d0979000: operation mds_connect to node 192.168.201.147@tcp failed: rc = -16 [ 525.819532] LustreError: lustre-MDT0000-mdc-ffffa086d0979000: operation mds_connect to node 192.168.201.147@tcp failed: rc = -16 [ 536.076172] LustreError: lustre-MDT0000-mdc-ffffa086d0979000: operation mds_connect to node 192.168.201.147@tcp failed: rc = -16 [ 536.082187] LustreError: Skipped 1 previous similar message [ 556.561535] LustreError: lustre-MDT0000-mdc-ffffa086d0979000: operation mds_connect to node 192.168.201.147@tcp failed: rc = -16 [ 556.572504] LustreError: Skipped 3 previous similar messages [ 566.892163] Lustre: Mounted lustre-client - version 2.17.57_103_g3d8212a [ 577.268641] Lustre: DEBUG MARKER: == replay-single test 0d: expired recovery with no clients ========================================================== 00:08:08 (1788581288) [ 581.170133] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 581.297131] Lustre: Unmounted lustre-client [ 610.080422] LustreError: lustre-MDT0000-mdc-ffffa086d0e3a000: operation mds_connect to node 192.168.201.147@tcp failed: rc = -16 [ 610.092119] LustreError: Skipped 1 previous similar message [ 671.922983] Lustre: Mounted lustre-client - version 2.17.57_103_g3d8212a [ 682.394674] Lustre: DEBUG MARKER: == replay-single test 1: simple create =================== 00:09:53 (1788581393) [ 686.892962] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 708.076704] LustreError: MGC192.168.201.147@tcp: Connection to MGS (at 192.168.201.147@tcp) was lost; in progress operations using this service will fail [ 708.127551] Lustre: Evicted from MGS (at 192.168.201.147@tcp) after server handle changed from 0x83bb3162d487f2f7 to 0x83bb3162d487f589 [ 708.139751] Lustre: MGC192.168.201.147@tcp: Connection restored to 192.168.201.147@tcp (at 192.168.201.147@tcp) [ 709.091363] Lustre: 2358:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788581405/real 1788581405] req@ffffa086d0e14380 x1875462916742144/t0(0) o400->lustre-MDT0000-mdc-ffffa086d0e3a000@192.168.201.147@tcp:12/10 lens 224/224 e 0 to 1 dl 1788581421 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 709.127732] Lustre: lustre-MDT0000-mdc-ffffa086d0e3a000: Connection to lustre-MDT0000 (at 192.168.201.147@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 709.230741] Lustre: 14160:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.201.147@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 719.327195] Lustre: 2357:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788581415/real 1788581415] req@ffffa086c5701180 x1875462916743168/t0(0) o400->lustre-MDT0000-mdc-ffffa086d0e3a000@192.168.201.147@tcp:12/10 lens 224/224 e 0 to 1 dl 1788581431 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 719.357068] Lustre: 2357:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 719.567049] Lustre: lustre-MDT0000-mdc-ffffa086d0e3a000: Connection restored to 192.168.201.147@tcp (at 192.168.201.147@tcp) [ 731.427822] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 733.111053] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 741.288687] Lustre: DEBUG MARKER: == replay-single test 2a: touch ========================== 00:10:52 (1788581452) [ 745.543531] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 766.431212] Lustre: 2359:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788581462/real 1788581462] req@ffffa086d0e60700 x1875462916753024/t0(0) o400->MGC192.168.201.147@tcp@192.168.201.147@tcp:26/25 lens 224/224 e 0 to 1 dl 1788581478 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 766.431587] Lustre: lustre-MDT0000-mdc-ffffa086d0e3a000: Connection to lustre-MDT0000 (at 192.168.201.147@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 766.480174] Lustre: 2359:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 766.480264] LustreError: MGC192.168.201.147@tcp: Connection to MGS (at 192.168.201.147@tcp) was lost; in progress operations using this service will fail [ 775.717916] Lustre: Evicted from MGS (at 192.168.201.147@tcp) after server handle changed from 0x83bb3162d487f589 to 0x83bb3162d487fa2f [ 775.734197] Lustre: MGC192.168.201.147@tcp: Connection restored to 192.168.201.147@tcp (at 192.168.201.147@tcp) [ 792.102680] LustreError: 2355:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffffa086d0e14e00 x1875462916752128/t21474836484(21474836484) o101->lustre-MDT0000-mdc-ffffa086d0e3a000@192.168.201.147@tcp:12/10 lens 592/608 e 0 to 0 dl 1788581520 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'touch.0' uid:0 gid:0 projid:0 [ 792.238883] Lustre: lustre-MDT0000-mdc-ffffa086d0e3a000: Connection restored to 192.168.201.147@tcp (at 192.168.201.147@tcp) [ 798.260147] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 800.464030] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 810.237533] Lustre: DEBUG MARKER: == replay-single test 2b: touch ========================== 00:12:01 (1788581521) [ 814.361902] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 834.018733] Lustre: 2358:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788581530/real 1788581530] req@ffffa086d0e15f80 x1875462916764544/t0(0) o400->lustre-MDT0000-mdc-ffffa086d0e3a000@192.168.201.147@tcp:12/10 lens 224/224 e 0 to 1 dl 1788581546 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 834.049075] Lustre: 2358:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 834.066609] Lustre: lustre-MDT0000-mdc-ffffa086d0e3a000: Connection to lustre-MDT0000 (at 192.168.201.147@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 834.096728] LustreError: MGC192.168.201.147@tcp: Connection to MGS (at 192.168.201.147@tcp) was lost; in progress operations using this service will fail [ 844.281719] Lustre: Evicted from MGS (at 192.168.201.147@tcp) after server handle changed from 0x83bb3162d487fa2f to 0x83bb3162d488002c [ 844.293664] Lustre: MGC192.168.201.147@tcp: Connection restored to 192.168.201.147@tcp (at 192.168.201.147@tcp) [ 844.332486] LustreError: 2355:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffffa086d0e62680 x1875462916763520/t25769803781(25769803781) o101->lustre-MDT0000-mdc-ffffa086d0e3a000@192.168.201.147@tcp:12/10 lens 592/608 e 0 to 0 dl 1788581572 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'touch.0' uid:0 gid:0 projid:0 [ 859.314537] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 861.077605] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 869.728705] Lustre: DEBUG MARKER: == replay-single test 2c: setstripe replay =============== 00:13:00 (1788581580) [ 874.019621] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 896.479500] LustreError: MGC192.168.201.147@tcp: Connection to MGS (at 192.168.201.147@tcp) was lost; in progress operations using this service will fail [ 896.498223] Lustre: lustre-MDT0000-mdc-ffffa086d0e3a000: Connection to lustre-MDT0000 (at 192.168.201.147@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 900.640096] Lustre: 2358:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788581597/real 1788581597] req@ffffa086d0e62d80 x1875462916776320/t0(0) o400->lustre-MDT0000-mdc-ffffa086d0e3a000@192.168.201.147@tcp:12/10 lens 224/224 e 0 to 1 dl 1788581613 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 900.659663] Lustre: 2358:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 6 previous similar messages [ 905.699037] Lustre: Evicted from MGS (at 192.168.201.147@tcp) after server handle changed from 0x83bb3162d488002c to 0x83bb3162d4880534 [ 905.713757] Lustre: MGC192.168.201.147@tcp: Connection restored to 192.168.201.147@tcp (at 192.168.201.147@tcp) [ 905.728095] Lustre: Skipped 1 previous similar message [ 906.767653] LustreError: 2355:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffffa086c5701f80 x1875462916774144/t30064771076(30064771076) o101->lustre-MDT0000-mdc-ffffa086d0e3a000@192.168.201.147@tcp:12/10 lens 536/608 e 0 to 0 dl 1788581635 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'lfs.0' uid:0 gid:0 projid:0 [ 920.166574] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 921.853493] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 930.666526] Lustre: DEBUG MARKER: == replay-single test 2d: setdirstripe replay ============ 00:14:01 (1788581641) [ 934.554112] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 952.799348] Lustre: lustre-MDT0000-mdc-ffffa086d0e3a000: Connection to lustre-MDT0000 (at 192.168.201.147@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 952.820268] LustreError: MGC192.168.201.147@tcp: Connection to MGS (at 192.168.201.147@tcp) was lost; in progress operations using this service will fail [ 963.047609] Lustre: Evicted from MGS (at 192.168.201.147@tcp) after server handle changed from 0x83bb3162d4880534 to 0x83bb3162d48809a9 [ 972.808540] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 974.350558] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 983.644918] Lustre: DEBUG MARKER: == replay-single test 2e: O_CREAT|O_EXCL create replay === 00:14:54 (1788581694) [ 990.748425] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1006.561791] Lustre: lustre-MDT0000-mdc-ffffa086d0e3a000: Connection to lustre-MDT0000 (at 192.168.201.147@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1010.143267] LustreError: MGC192.168.201.147@tcp: Connection to MGS (at 192.168.201.147@tcp) was lost; in progress operations using this service will fail [ 1017.506826] Lustre: lustre-MDT0000-mdc-ffffa086d0e3a000: Connection restored to 192.168.201.147@tcp (at 192.168.201.147@tcp) [ 1017.520293] Lustre: Skipped 3 previous similar messages [ 1020.467656] Lustre: Evicted from MGS (at 192.168.201.147@tcp) after server handle changed from 0x83bb3162d48809a9 to 0x83bb3162d4880fb4 [ 1029.341455] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1031.498317] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1041.455646] Lustre: DEBUG MARKER: == replay-single test 3a: replay failed open(O_DIRECTORY) ========================================================== 00:15:52 (1788581752) [ 1046.328301] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1067.491634] Lustre: 2357:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788581763/real 1788581763] req@ffffa086c5700e00 x1875462916806144/t0(0) o400->lustre-MDT0000-mdc-ffffa086d0e3a000@192.168.201.147@tcp:12/10 lens 224/224 e 0 to 1 dl 1788581779 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1067.531120] Lustre: 2357:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 12 previous similar messages [ 1067.541279] LustreError: MGC192.168.201.147@tcp: Connection to MGS (at 192.168.201.147@tcp) was lost; in progress operations using this service will fail [ 1077.782476] Lustre: Evicted from MGS (at 192.168.201.147@tcp) after server handle changed from 0x83bb3162d4880fb4 to 0x83bb3162d48810c5 [ 1096.706340] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1098.475243] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1107.228393] Lustre: DEBUG MARKER: == replay-single test 3b: replay failed open -ENOMEM ===== 00:16:58 (1788581818) [ 1111.399295] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1134.559383] Lustre: lustre-MDT0000-mdc-ffffa086d0e3a000: Connection to lustre-MDT0000 (at 192.168.201.147@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1134.573914] Lustre: Skipped 1 previous similar message [ 1134.578354] LustreError: MGC192.168.201.147@tcp: Connection to MGS (at 192.168.201.147@tcp) was lost; in progress operations using this service will fail [ 1144.806599] Lustre: Evicted from MGS (at 192.168.201.147@tcp) after server handle changed from 0x83bb3162d48810c5 to 0x83bb3162d488168a [ 1157.158769] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1159.137102] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1168.033464] Lustre: DEBUG MARKER: == replay-single test 3c: replay failed open -ENOMEM ===== 00:17:59 (1788581879) [ 1171.891245] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1196.022723] Lustre: MGC192.168.201.147@tcp: Connection restored to 192.168.201.147@tcp (at 192.168.201.147@tcp) [ 1196.040421] Lustre: Skipped 5 previous similar messages [ 1207.786482] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1209.277521] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1217.897150] Lustre: DEBUG MARKER: == replay-single test 4a: |x| 10 open(O_CREAT)s ========== 00:18:48 (1788581928) [ 1222.090672] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1244.398053] Lustre: 14160:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.201.147@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 1253.429169] LustreError: 2355:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffffa086d0e60e00 x1875462916835840/t55834574851(55834574851) o101->lustre-MDT0000-mdc-ffffa086d0e3a000@192.168.201.147@tcp:12/10 lens 592/608 e 0 to 0 dl 1788581981 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'bash.0' uid:0 gid:0 projid:0 [ 1267.034350] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1269.251369] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1279.525037] Lustre: DEBUG MARKER: == replay-single test 4b: |x| rm 10 files ================ 00:19:50 (1788581990) [ 1283.671824] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1301.489048] LustreError: lustre-MDT0000-mdc-ffffa086d0e3a000: operation mds_batch to node 192.168.201.147@tcp failed: rc = -107 [ 1301.498507] LustreError: Skipped 11 previous similar messages [ 1301.501692] Lustre: lustre-MDT0000-mdc-ffffa086d0e3a000: Connection to lustre-MDT0000 (at 192.168.201.147@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1301.532314] Lustre: Skipped 2 previous similar messages [ 1305.375573] LustreError: MGC192.168.201.147@tcp: Connection to MGS (at 192.168.201.147@tcp) was lost; in progress operations using this service will fail [ 1305.388696] LustreError: Skipped 2 previous similar messages [ 1305.422206] Lustre: Evicted from MGS (at 192.168.201.147@tcp) after server handle changed from 0x83bb3162d4881fac to 0x83bb3162d4882a72 [ 1305.452070] Lustre: Skipped 2 previous similar messages [ 1306.664108] Lustre: 14160:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.201.147@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 1333.738503] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1335.437908] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1344.028344] Lustre: DEBUG MARKER: == replay-single test 5: |x| 220 open(O_CREAT) =========== 00:20:54 (1788582054) [ 1348.157116] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1374.176200] Lustre: 2359:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788582070/real 1788582070] req@ffffa086c30af100 x1875462917071872/t0(0) o400->MGC192.168.201.147@tcp@192.168.201.147@tcp:26/25 lens 224/224 e 0 to 1 dl 1788582086 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1374.235486] Lustre: 2359:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 20 previous similar messages [ 1384.513828] LustreError: 2355:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffffa086d8b38000 x1875462916889216/t64424509443(64424509443) o101->lustre-MDT0000-mdc-ffffa086d0e3a000@192.168.201.147@tcp:12/10 lens 592/608 e 0 to 0 dl 1788582112 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'bash.0' uid:0 gid:0 projid:0 [ 1384.568101] LustreError: 2355:0:(client.c:3448:ptlrpc_replay_interpret()) Skipped 9 previous similar messages [ 1394.781150] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1397.344706] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1424.774804] Lustre: DEBUG MARKER: == replay-single test 6a: mkdir + contained create ======= 00:22:15 (1788582135) [ 1429.180186] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1452.524101] Lustre: 14160:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.201.147@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 1462.511965] Lustre: lustre-MDT0000-mdc-ffffa086d0e3a000: Connection restored to 192.168.201.147@tcp (at 192.168.201.147@tcp) [ 1462.530029] Lustre: Skipped 8 previous similar messages [ 1474.025153] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1475.861416] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1487.405423] Lustre: DEBUG MARKER: == replay-single test 6b: |X| rmdir ====================== 00:23:18 (1788582198) [ 1491.619599] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1528.846103] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1531.533409] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1541.909979] Lustre: DEBUG MARKER: == replay-single test 7: mkdir |X| contained create ====== 00:24:12 (1788582252) [ 1547.353364] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1569.759319] LustreError: MGC192.168.201.147@tcp: Connection to MGS (at 192.168.201.147@tcp) was lost; in progress operations using this service will fail [ 1569.773599] LustreError: Skipped 3 previous similar messages [ 1569.795071] Lustre: lustre-MDT0000-mdc-ffffa086d0e3a000: Connection to lustre-MDT0000 (at 192.168.201.147@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1569.824469] Lustre: Skipped 3 previous similar messages [ 1580.009564] Lustre: Evicted from MGS (at 192.168.201.147@tcp) after server handle changed from 0x83bb3162d488c9e3 to 0x83bb3162d488ceeb [ 1580.030306] Lustre: Skipped 3 previous similar messages [ 1589.801785] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1591.781739] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1601.691693] Lustre: DEBUG MARKER: == replay-single test 8: creat open |X| close ============ 00:25:12 (1788582312) [ 1605.797558] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1628.175089] LustreError: 2355:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffffa086c30ad880 x1875462917387520/t81604378634(81604378634) o101->lustre-MDT0000-mdc-ffffa086d0e3a000@192.168.201.147@tcp:12/10 lens 664/608 e 0 to 0 dl 1788582356 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'multiop.0' uid:0 gid:0 projid:0 [ 1628.204384] LustreError: 2355:0:(client.c:3448:ptlrpc_replay_interpret()) Skipped 219 previous similar messages [ 1639.250261] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1641.306891] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1651.345755] Lustre: DEBUG MARKER: == replay-single test 9: |X| create (same inum/gen) ====== 00:26:02 (1788582362) [ 1655.659687] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1694.734509] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1696.262052] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1704.873458] Lustre: DEBUG MARKER: == replay-single test 10: create |X| rename unlink ======= 00:26:55 (1788582415) [ 1709.103085] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1742.658461] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1744.363485] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1752.967841] Lustre: DEBUG MARKER: == replay-single test 11: create open write rename |X| create-old-name read ========================================================== 00:27:44 (1788582464) [ 1756.903922] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1801.208838] LustreError: 2355:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffffa086c60d2a00 x1875462917420288/t94489280522(94489280522) o101->lustre-MDT0000-mdc-ffffa086d0e3a000@192.168.201.147@tcp:12/10 lens 592/608 e 0 to 0 dl 1788582529 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'bash.0' uid:0 gid:0 projid:0 [ 1806.111882] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1807.849936] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1818.813668] Lustre: DEBUG MARKER: == replay-single test 12: open, unlink |X| close ========= 00:28:49 (1788582529) [ 1824.560688] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1853.491304] LustreError: 2355:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffffa086c30ace00 x1875462917421056/t94489280524(94489280524) o101->lustre-MDT0000-mdc-ffffa086d0e3a000@192.168.201.147@tcp:12/10 lens 576/608 e 0 to 0 dl 1788582581 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'grep.0' uid:0 gid:0 projid:0 [ 1853.524336] LustreError: 2355:0:(client.c:3448:ptlrpc_replay_interpret()) Skipped 1 previous similar message [ 1860.915430] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1862.912296] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1873.013796] Lustre: DEBUG MARKER: == replay-single test 13: open chmod 0 |x| write close === 00:29:43 (1788582583) [ 1877.064866] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1900.513812] Lustre: 2357:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788582596/real 1788582596] req@ffffa086d0e61880 x1875462917446400/t0(0) o400->lustre-MDT0000-mdc-ffffa086d0e3a000@192.168.201.147@tcp:12/10 lens 224/224 e 0 to 1 dl 1788582612 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1900.555601] Lustre: 2357:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 35 previous similar messages [ 1915.124791] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1916.881593] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1928.416220] Lustre: DEBUG MARKER: == replay-single test 14: open(O_CREAT), unlink |X| close ========================================================== 00:30:39 (1788582639) [ 1933.698947] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1981.523713] LustreError: 2355:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffffa086c30ace00 x1875462917421056/t94489280524(94489280524) o101->lustre-MDT0000-mdc-ffffa086d0e3a000@192.168.201.147@tcp:12/10 lens 576/608 e 0 to 0 dl 1788582709 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'grep.0' uid:0 gid:0 projid:0 [ 1981.574506] LustreError: 2355:0:(client.c:3448:ptlrpc_replay_interpret()) Skipped 3 previous similar messages [ 1981.699145] Lustre: lustre-MDT0000-mdc-ffffa086d0e3a000: Connection restored to 192.168.201.147@tcp (at 192.168.201.147@tcp) [ 1981.719437] Lustre: Skipped 17 previous similar messages [ 1988.443878] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1990.300986] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1999.270310] Lustre: DEBUG MARKER: == replay-single test 15: open(O_CREAT), unlink |X| touch new, close ========================================================== 00:31:50 (1788582710) [ 2003.614815] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2056.301455] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2058.377819] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2068.137513] Lustre: DEBUG MARKER: == replay-single test 16: |X| open(O_CREAT), unlink, touch new, unlink new ========================================================== 00:32:59 (1788582779) [ 2073.620602] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2095.071553] Lustre: lustre-MDT0000-mdc-ffffa086d0e3a000: Connection to lustre-MDT0000 (at 192.168.201.147@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 2095.093694] Lustre: Skipped 8 previous similar messages [ 2095.098034] LustreError: MGC192.168.201.147@tcp: Connection to MGS (at 192.168.201.147@tcp) was lost; in progress operations using this service will fail [ 2095.108479] LustreError: Skipped 8 previous similar messages [ 2105.334953] Lustre: Evicted from MGS (at 192.168.201.147@tcp) after server handle changed from 0x83bb3162d488f4df to 0x83bb3162d488fad5 [ 2105.343453] Lustre: Skipped 8 previous similar messages [ 2121.296423] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2123.516499] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2133.154801] Lustre: DEBUG MARKER: == replay-single test 17: |X| open(O_CREAT), |replay| close ========================================================== 00:34:04 (1788582844) [ 2136.592137] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2167.851838] LustreError: 2355:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffffa086c30ace00 x1875462917421056/t94489280524(94489280524) o101->lustre-MDT0000-mdc-ffffa086d0e3a000@192.168.201.147@tcp:12/10 lens 576/608 e 0 to 0 dl 1788582896 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'grep.0' uid:0 gid:0 projid:0 [ 2167.890873] LustreError: 2355:0:(client.c:3448:ptlrpc_replay_interpret()) Skipped 5 previous similar messages [ 2181.980602] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2184.378525] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2193.790479] Lustre: DEBUG MARKER: == replay-single test 18: open(O_CREAT), unlink, touch new, close, touch, unlink ========================================================== 00:35:04 (1788582904) [ 2199.222441] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2251.043328] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2252.970979] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2263.565420] Lustre: DEBUG MARKER: == replay-single test 19: mcreate, open, write, rename === 00:36:14 (1788582974) [ 2267.173346] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2318.012613] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2319.261070] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2327.937590] Lustre: DEBUG MARKER: == replay-single test 20a: |X| open(O_CREAT), unlink, replay, close (test mds_cleanup_orphans) ========================================================== 00:37:19 (1788583039) [ 2332.918469] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2384.940109] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2386.486940] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2394.929123] Lustre: DEBUG MARKER: == replay-single test 20b: write, unlink, eviction, replay (test mds_cleanup_orphans) ========================================================== 00:38:26 (1788583106) [ 2402.236474] LustreError: lustre-MDT0000-mdc-ffffa086d0e3a000: operation mds_statfs to node 192.168.201.147@tcp failed: rc = -107 [ 2402.256547] LustreError: lustre-MDT0000-mdc-ffffa086d0e3a000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 2407.335264] LustreError: lustre-MDT0000-mdc-ffffa086d0e3a000: operation mds_getxattr to node 192.168.201.147@tcp failed: rc = -19 [ 2452.299349] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2454.559685] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2475.793490] Lustre: DEBUG MARKER: before 4096, after 4096 [ 2482.904568] Lustre: DEBUG MARKER: == replay-single test 20c: check that client eviction does not affect file content ========================================================== 00:39:53 (1788583193) [ 2485.248716] LustreError: lustre-MDT0000-mdc-ffffa086d0e3a000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 2491.992286] Lustre: DEBUG MARKER: == replay-single test 21: |X| open(O_CREAT), unlink touch new, replay, close (test mds_cleanup_orphans) ========================================================== 00:40:03 (1788583203) [ 2496.128233] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2516.960388] Lustre: 2356:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788583213/real 1788583213] req@ffffa086d0e60380 x1875462917650432/t0(0) o400->lustre-MDT0000-mdc-ffffa086d0e3a000@192.168.201.147@tcp:12/10 lens 224/224 e 0 to 1 dl 1788583229 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2517.019184] Lustre: 2356:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 37 previous similar messages [ 2527.259079] LustreError: 2355:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffffa086c30ad180 x1875462917648512/t141733920773(141733920773) o101->lustre-MDT0000-mdc-ffffa086d0e3a000@192.168.201.147@tcp:12/10 lens 592/608 e 0 to 0 dl 1788583255 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'multiop.0' uid:0 gid:0 projid:0 [ 2527.279933] LustreError: 2355:0:(client.c:3448:ptlrpc_replay_interpret()) Skipped 7 previous similar messages [ 2537.013992] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2539.277465] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2547.954165] Lustre: DEBUG MARKER: == replay-single test 22: open(O_CREAT), |X| unlink, replay, close (test mds_cleanup_orphans) ========================================================== 00:40:59 (1788583259) [ 2552.335985] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2574.850324] Lustre: 14160:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.201.147@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 2584.745912] Lustre: lustre-MDT0000-mdc-ffffa086d0e3a000: Connection restored to 192.168.201.147@tcp (at 192.168.201.147@tcp) [ 2584.758089] Lustre: Skipped 19 previous similar messages [ 2598.071327] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2599.940250] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2608.651167] Lustre: DEBUG MARKER: == replay-single test 23: open(O_CREAT), |X| unlink touch new, replay, close (test mds_cleanup_orphans) ========================================================== 00:41:59 (1788583319) [ 2613.392717] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2650.668403] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2652.301322] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2661.739716] Lustre: DEBUG MARKER: == replay-single test 24: open(O_CREAT), replay, unlink, close (test mds_cleanup_orphans) ========================================================== 00:42:52 (1788583372) [ 2666.822643] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2712.371917] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2714.506880] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2724.559694] Lustre: DEBUG MARKER: == replay-single test 25: open(O_CREAT), unlink, replay, close (test mds_cleanup_orphans) ========================================================== 00:43:55 (1788583435) [ 2728.848030] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2750.239890] LustreError: MGC192.168.201.147@tcp: Connection to MGS (at 192.168.201.147@tcp) was lost; in progress operations using this service will fail [ 2750.254650] LustreError: Skipped 9 previous similar messages [ 2750.257847] Lustre: lustre-MDT0000-mdc-ffffa086d0e3a000: Connection to lustre-MDT0000 (at 192.168.201.147@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 2750.267066] Lustre: Skipped 11 previous similar messages [ 2759.670929] Lustre: Evicted from MGS (at 192.168.201.147@tcp) after server handle changed from 0x83bb3162d48928ef to 0x83bb3162d4892dd4 [ 2759.683835] Lustre: Skipped 9 previous similar messages [ 2767.738171] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2769.768460] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2778.798977] Lustre: DEBUG MARKER: == replay-single test 26: |X| open(O_CREAT), unlink two, close one, replay, close one (test mds_cleanup_orphans) ========================================================== 00:44:49 (1788583489) [ 2783.387170] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2807.734247] Lustre: 14160:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.201.147@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 2830.169746] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2832.347759] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2843.066923] Lustre: DEBUG MARKER: == replay-single test 27: |X| open(O_CREAT), unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 00:45:53 (1788583553) [ 2847.779105] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2886.489961] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2888.304775] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2898.595729] Lustre: DEBUG MARKER: == replay-single test 28: open(O_CREAT), |X| unlink two, close one, replay, close one (test mds_cleanup_orphans) ========================================================== 00:46:49 (1788583609) [ 2903.423331] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2927.210238] Lustre: 14160:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.201.147@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 2948.860651] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2951.093822] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2962.202734] Lustre: DEBUG MARKER: == replay-single test 29: open(O_CREAT), |X| unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 00:47:52 (1788583672) [ 2967.505159] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3018.473493] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3020.645457] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3030.622852] Lustre: DEBUG MARKER: == replay-single test 30: open(O_CREAT) two, unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 00:49:01 (1788583741) [ 3034.862412] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3065.208469] LustreError: 2355:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffffa086c30ae300 x1875462917764608/t180388626437(180388626437) o101->lustre-MDT0000-mdc-ffffa086d0e3a000@192.168.201.147@tcp:12/10 lens 592/608 e 0 to 0 dl 1788583793 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'multiop.0' uid:0 gid:0 projid:0 [ 3065.244469] LustreError: 2355:0:(client.c:3448:ptlrpc_replay_interpret()) Skipped 15 previous similar messages [ 3078.981126] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3080.454693] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3089.739691] Lustre: DEBUG MARKER: == replay-single test 31: open(O_CREAT) two, unlink one, |X| unlink one, close two (test mds_cleanup_orphans) ========================================================== 00:50:00 (1788583800) [ 3093.997702] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3117.992853] Lustre: 14160:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.201.147@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 3121.119504] Lustre: 2359:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788583817/real 1788583817] req@ffffa086c30ac380 x1875462917782912/t0(0) o400->lustre-MDT0000-mdc-ffffa086d0e3a000@192.168.201.147@tcp:12/10 lens 224/224 e 0 to 1 dl 1788583833 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3121.163072] Lustre: 2359:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 46 previous similar messages [ 3139.569617] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3141.338767] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3149.177425] Lustre: DEBUG MARKER: == replay-single test 32: close() notices client eviction; close() after client eviction ========================================================== 00:51:00 (1788583860) [ 3151.859465] LustreError: lustre-MDT0000-mdc-ffffa086d0e3a000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 3159.952284] Lustre: DEBUG MARKER: == replay-single test 33a: fid seq shouldn't be reused after abort recovery ========================================================== 00:51:10 (1788583870) [ 3163.660642] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3177.535395] LustreError: lustre-MDT0000-mdc-ffffa086d0e3a000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 3193.130681] Lustre: DEBUG MARKER: == replay-single test 33b: test fid seq allocation ======= 00:51:43 (1788583903) [ 3197.056340] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3213.301098] Lustre: MGC192.168.201.147@tcp: Connection restored to 192.168.201.147@tcp (at 192.168.201.147@tcp) [ 3213.310378] Lustre: Skipped 21 previous similar messages [ 3213.389790] LustreError: lustre-MDT0000-mdc-ffffa086d0e3a000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 3229.050906] Lustre: DEBUG MARKER: == replay-single test 34: abort recovery before client does replay (test mds_cleanup_orphans) ========================================================== 00:52:19 (1788583939) [ 3233.366468] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3251.312911] LustreError: lustre-MDT0000-mdc-ffffa086d0e3a000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 3267.972040] Lustre: DEBUG MARKER: == replay-single test 35: test recovery from llog for unlink op ========================================================== 00:52:58 (1788583978) [ 3285.032323] LustreError: lustre-MDT0000-mdc-ffffa086d0e3a000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 3300.813327] Lustre: DEBUG MARKER: SKIP: replay-single test_36 skipping ALWAYS excluded test 36 [ 3303.062207] Lustre: DEBUG MARKER: == replay-single test 37: abort recovery before client does replay (test mds_cleanup_orphans for directories) ========================================================== 00:53:33 (1788584013) [ 3307.642924] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3326.094604] LustreError: lustre-MDT0000-mdc-ffffa086d0e3a000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 3342.767105] Lustre: DEBUG MARKER: == replay-single test 38: test recovery from unlink llog (test llog_gen_rec) ========================================================== 00:54:13 (1788584053) [ 3379.104555] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3397.603841] LustreError: MGC192.168.201.147@tcp: Connection to MGS (at 192.168.201.147@tcp) was lost; in progress operations using this service will fail [ 3397.618239] LustreError: Skipped 11 previous similar messages [ 3397.631486] Lustre: lustre-MDT0000-mdc-ffffa086d0e3a000: Connection to lustre-MDT0000 (at 192.168.201.147@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 3397.648975] Lustre: Skipped 12 previous similar messages [ 3407.858843] Lustre: Evicted from MGS (at 192.168.201.147@tcp) after server handle changed from 0x83bb3162d4897777 to 0x83bb3162d48a5d27 [ 3407.887965] Lustre: Skipped 11 previous similar messages [ 3409.208014] Lustre: 14160:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.201.147@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 3429.882099] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3431.404725] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3455.314615] Lustre: DEBUG MARKER: == replay-single test 39: test recovery from unlink llog (test llog_gen_rec) ========================================================== 00:56:06 (1788584166) [ 3483.082682] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3516.783705] Lustre: 14160:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.201.147@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 3539.380511] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3541.195313] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3569.133818] Lustre: DEBUG MARKER: == replay-single test 41: read from a valid osc while other oscs are invalid ========================================================== 00:57:59 (1788584279) [ 3580.629202] Lustre: DEBUG MARKER: == replay-single test 42: recovery after ost failure ===== 00:58:11 (1788584291) [ 3608.095966] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-OST0000 [ 3709.418107] Lustre: DEBUG MARKER: == replay-single test 43: mds osc import failure during recovery; don't LBUG ========================================================== 01:00:20 (1788584420) [ 3714.748587] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3736.351476] Lustre: 2357:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788584432/real 1788584432] req@ffffa086c49bdf80 x1875462920495872/t0(0) o400->lustre-MDT0000-mdc-ffffa086d0e3a000@192.168.201.147@tcp:12/10 lens 224/224 e 0 to 1 dl 1788584448 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3736.424958] Lustre: 2357:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 11 previous similar messages [ 3760.449549] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3762.228215] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3785.143001] Lustre: DEBUG MARKER: == replay-single test 44a: race in target handle connect ========================================================== 01:01:35 (1788584495) [ 3820.811532] Lustre: lustre-MDT0000-mdc-ffffa086d0e3a000: Connection restored to 192.168.201.147@tcp (at 192.168.201.147@tcp) [ 3820.829404] Lustre: Skipped 16 previous similar messages [ 3878.622353] Lustre: DEBUG MARKER: == replay-single test 44b: race in target handle connect ========================================================== 01:03:09 (1788584589) [ 3901.508172] LustreError: 87190:0:(lmv_obd.c:1471:lmv_statfs()) lustre-MDT0000-mdc-ffffa086d0e3a000: can't stat MDS #0: rc = -114 [ 3924.486070] LustreError: 87212:0:(lmv_obd.c:1471:lmv_statfs()) lustre-MDT0000-mdc-ffffa086d0e3a000: can't stat MDS #0: rc = -114 [ 3947.518613] LustreError: 87237:0:(lmv_obd.c:1471:lmv_statfs()) lustre-MDT0000-mdc-ffffa086d0e3a000: can't stat MDS #0: rc = -114 [ 3971.077672] LustreError: 87259:0:(lmv_obd.c:1471:lmv_statfs()) lustre-MDT0000-mdc-ffffa086d0e3a000: can't stat MDS #0: rc = -114 [ 3994.166716] LustreError: 87282:0:(lmv_obd.c:1471:lmv_statfs()) lustre-MDT0000-mdc-ffffa086d0e3a000: can't stat MDS #0: rc = -114 [ 4017.641240] LustreError: 87304:0:(lmv_obd.c:1471:lmv_statfs()) lustre-MDT0000-mdc-ffffa086d0e3a000: can't stat MDS #0: rc = -114 [ 4040.639459] LustreError: 87327:0:(lmv_obd.c:1471:lmv_statfs()) lustre-MDT0000-mdc-ffffa086d0e3a000: can't stat MDS #0: rc = -114 [ 4086.654635] LustreError: 87373:0:(lmv_obd.c:1471:lmv_statfs()) lustre-MDT0000-mdc-ffffa086d0e3a000: can't stat MDS #0: rc = -114 [ 4086.661979] LustreError: 87373:0:(lmv_obd.c:1471:lmv_statfs()) Skipped 1 previous similar message [ 4119.937130] Lustre: DEBUG MARKER: == replay-single test 44c: race in target handle connect ========================================================== 01:07:10 (1788584830) [ 4124.784156] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4145.125136] LustreError: MGC192.168.201.147@tcp: Connection to MGS (at 192.168.201.147@tcp) was lost; in progress operations using this service will fail [ 4145.139132] Lustre: lustre-MDT0000-mdc-ffffa086d0e3a000: Connection to lustre-MDT0000 (at 192.168.201.147@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 4145.147780] LustreError: Skipped 2 previous similar messages [ 4145.172816] Lustre: Evicted from MGS (at 192.168.201.147@tcp) after server handle changed from 0x83bb3162d48d966a to 0x83bb3162d48da71f [ 4145.177142] Lustre: Skipped 14 previous similar messages [ 4145.198161] Lustre: Skipped 2 previous similar messages [ 4145.390075] LustreError: lustre-MDT0000-mdc-ffffa086d0e3a000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 4187.277749] Lustre: 14160:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.201.147@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 4212.090877] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4215.094954] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4225.081566] Lustre: DEBUG MARKER: == replay-single test 45: Handle failed close ============ 01:08:55 (1788584935) [ 4225.797272] Lustre: setting import lustre-MDT0000_UUID INACTIVE by administrator request [ 4225.818257] LustreError: 89762:0:(file.c:251:ll_close_inode_openhandle()) lustre-clilmv-ffffa086d0e3a000: inode [0x20001a9e1:0x1:0x0] mdc close failed: rc = -108 [ 4225.875130] LustreError: lustre-MDT0000-mdc-ffffa086d0e3a000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 4236.323093] Lustre: DEBUG MARKER: == replay-single test 46: Don't leak file handle after open resend (3325) ========================================================== 01:09:07 (1788584947) [ 4306.652467] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4308.913733] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4321.719448] Lustre: DEBUG MARKER: == replay-single test 47: MDS->OSC failure during precreate cleanup (2824) ========================================================== 01:10:32 (1788585032) [ 4369.879793] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 4372.369864] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4447.309429] Lustre: DEBUG MARKER: == replay-single test 48: MDS->OSC failure during precreate cleanup (2824) ========================================================== 01:12:37 (1788585157) [ 4452.885689] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4476.392065] Lustre: 2358:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788585172/real 1788585172] req@ffffa086c49c1500 x1875462920661504/t0(0) o400->lustre-MDT0000-mdc-ffffa086d0e3a000@192.168.201.147@tcp:12/10 lens 224/224 e 0 to 1 dl 1788585188 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4476.422050] Lustre: 2358:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 15 previous similar messages [ 4476.451878] Lustre: MGC192.168.201.147@tcp: Connection restored to 192.168.201.147@tcp (at 192.168.201.147@tcp) [ 4476.459551] Lustre: Skipped 16 previous similar messages [ 4478.134762] LustreError: 2355:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffffa086c49ded80 x1875462920648320/t236223201383(236223201383) o101->lustre-MDT0000-mdc-ffffa086d0e3a000@192.168.201.147@tcp:12/10 lens 592/608 e 0 to 0 dl 1788585206 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'createmany.0' uid:0 gid:0 projid:0 [ 4478.166553] LustreError: 2355:0:(client.c:3448:ptlrpc_replay_interpret()) Skipped 3 previous similar messages [ 4556.704424] Lustre: DEBUG MARKER: == replay-single test 50: Double OSC recovery, don't LASSERT (3812) ========================================================== 01:14:27 (1788585267) [ 4572.138945] Lustre: DEBUG MARKER: == replay-single test 52: time out lock replay (3764) ==== 01:14:43 (1788585283) [ 4628.558821] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4630.453629] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4641.184550] Lustre: DEBUG MARKER: == replay-single test 53a: |X| close request while two MDC requests in flight ========================================================== 01:15:51 (1788585351) [ 4649.038542] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4674.481215] Lustre: 14160:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.201.147@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 4705.168130] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4707.667435] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4720.417703] Lustre: DEBUG MARKER: == replay-single test 53b: |X| open request while two MDC requests in flight ========================================================== 01:17:10 (1788585430) [ 4728.745689] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4748.831339] LustreError: MGC192.168.201.147@tcp: Connection to MGS (at 192.168.201.147@tcp) was lost; in progress operations using this service will fail [ 4748.850340] LustreError: Skipped 5 previous similar messages [ 4759.033754] Lustre: Evicted from MGS (at 192.168.201.147@tcp) after server handle changed from 0x83bb3162d48dd74d to 0x83bb3162d48ddd2e [ 4759.046473] Lustre: Skipped 5 previous similar messages [ 4778.852324] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4780.883894] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4791.019469] Lustre: DEBUG MARKER: == replay-single test 53c: |X| open request and close request while two MDC requests in flight ========================================================== 01:18:21 (1788585501) [ 4800.630592] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4809.183426] Lustre: lustre-MDT0000-mdc-ffffa086d0e3a000: Connection to lustre-MDT0000 (at 192.168.201.147@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 4809.201280] Lustre: Skipped 10 previous similar messages [ 4832.115424] Lustre: 14160:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.201.147@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 4859.136084] Lustre: DEBUG MARKER: == replay-single test 53d: close reply while two MDC requests in flight ========================================================== 01:19:29 (1788585569) [ 4888.832543] Lustre: 14160:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.201.147@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 4912.459363] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4914.253956] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4925.602332] Lustre: DEBUG MARKER: == replay-single test 53e: |X| open reply while two MDC requests in flight ========================================================== 01:20:36 (1788585636) [ 4935.456947] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4981.384526] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4983.232366] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4992.985515] Lustre: DEBUG MARKER: == replay-single test 53f: |X| open reply and close reply while two MDC requests in flight ========================================================== 01:21:44 (1788585704) [ 5000.834846] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5046.116875] Lustre: DEBUG MARKER: == replay-single test 53g: |X| drop open reply and close request while close and open are both in flight ========================================================== 01:22:37 (1788585757) [ 5054.479862] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5077.983513] Lustre: 2357:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788585774/real 1788585774] req@ffffa086c48f9180 x1875462920801536/t0(0) o400->lustre-MDT0000-mdc-ffffa086d0e3a000@192.168.201.147@tcp:12/10 lens 224/224 e 0 to 1 dl 1788585790 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5078.010390] Lustre: 2357:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 36 previous similar messages [ 5084.089500] Lustre: MGC192.168.201.147@tcp: Connection restored to 192.168.201.147@tcp (at 192.168.201.147@tcp) [ 5084.107525] Lustre: Skipped 15 previous similar messages [ 5098.150985] Lustre: DEBUG MARKER: == replay-single test 53h: open request and close reply while two MDC requests in flight ========================================================== 01:23:29 (1788585809) [ 5107.035853] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5131.560643] Lustre: 14160:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.201.147@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 5156.823537] Lustre: DEBUG MARKER: == replay-single test 55: let MDS_CHECK_RESENT return the original return code instead of 0 ========================================================== 01:24:27 (1788585867) [ 5184.931405] Lustre: DEBUG MARKER: == replay-single test 56: don't replay a symlink open request (3440) ========================================================== 01:24:55 (1788585895) [ 5189.739579] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5215.092183] Lustre: 14160:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.201.147@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 5236.323984] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5238.137515] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5258.335619] Lustre: DEBUG MARKER: == replay-single test 57: test recovery from llog for setattr op ========================================================== 01:26:09 (1788585969) [ 5265.216234] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5318.246683] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5320.600788] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5342.424928] Lustre: DEBUG MARKER: == replay-single test 58a: test recovery from llog for setattr op (test llog_gen_rec) ========================================================== 01:27:32 (1788586052) [ 5394.025066] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5412.835613] LustreError: MGC192.168.201.147@tcp: Connection to MGS (at 192.168.201.147@tcp) was lost; in progress operations using this service will fail [ 5412.851326] LustreError: Skipped 8 previous similar messages [ 5412.855260] Lustre: lustre-MDT0000-mdc-ffffa086d0e3a000: Connection to lustre-MDT0000 (at 192.168.201.147@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 5412.867667] Lustre: Skipped 8 previous similar messages [ 5423.088806] Lustre: Evicted from MGS (at 192.168.201.147@tcp) after server handle changed from 0x83bb3162d48e0aed to 0x83bb3162d48f655f [ 5423.098077] Lustre: Skipped 8 previous similar messages [ 5424.372159] Lustre: 14160:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.201.147@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 5445.787505] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5447.547615] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5513.336789] Lustre: DEBUG MARKER: == replay-single test 58b: test replay of setxattr op ==== 01:30:24 (1788586224) [ 5514.033810] Lustre: Mounted lustre-client - version 2.17.57_103_g3d8212a [ 5518.629542] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5533.159348] LustreError: lustre-MDT0000-mdc-ffffa086d0e3a000: operation mds_batch to node 192.168.201.147@tcp failed: rc = -107 [ 5567.311583] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5569.019534] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5575.494653] Lustre: Unmounted lustre-client [ 5584.588320] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount FULL mgc.*.mgs_server_uuid 1475 0 [ 5587.621741] Lustre: DEBUG MARKER: mgc.*.mgs_server_uuid in FULL state after 0 sec [ 5599.248622] Lustre: DEBUG MARKER: == replay-single test 58c: resend/reconstruct setxattr op ========================================================== 01:31:48 (1788586308) [ 5605.240612] Lustre: Mounted lustre-client - version 2.17.57_103_g3d8212a [ 5647.205203] Lustre: Unmounted lustre-client [ 5656.477799] Lustre: DEBUG MARKER: SKIP: replay-single test_59 skipping ALWAYS excluded test 59 [ 5659.143969] Lustre: DEBUG MARKER: == replay-single test 60: test llog post recovery init vs llog unlink ========================================================== 01:32:49 (1788586369) [ 5674.313868] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5699.552095] Lustre: 2359:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788586395/real 1788586395] req@ffffa086d1b04000 x1875462923749248/t0(0) o400->MGC192.168.201.147@tcp@192.168.201.147@tcp:26/25 lens 224/224 e 0 to 1 dl 1788586411 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5699.575829] Lustre: 2359:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 27 previous similar messages [ 5699.593484] Lustre: MGC192.168.201.147@tcp: Connection restored to 192.168.201.147@tcp (at 192.168.201.147@tcp) [ 5699.598764] Lustre: Skipped 15 previous similar messages [ 5701.430953] Lustre: 14160:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.201.147@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 5724.716945] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5726.650228] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5739.839584] Lustre: DEBUG MARKER: == replay-single test 61a: test race llog recovery vs llog cleanup ========================================================== 01:34:10 (1788586450) [ 5761.691982] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-OST0000 [ 5861.580423] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 5863.451340] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 5906.685983] Lustre: DEBUG MARKER: == replay-single test 61b: test race mds llog sync vs llog cleanup ========================================================== 01:36:57 (1788586617) [ 6003.146996] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6004.830710] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6014.044530] Lustre: DEBUG MARKER: == replay-single test 61c: test race mds llog sync vs llog cleanup ========================================================== 01:38:45 (1788586725) [ 6032.372904] Lustre: lustre-OST0000-osc-ffffa086d0e3a000: Connection to lustre-OST0000 (at 192.168.201.147@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 6032.385498] Lustre: Skipped 7 previous similar messages [ 6068.097529] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 6070.126811] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 6082.154553] Lustre: DEBUG MARKER: == replay-single test 61d: error in llog_setup should cleanup the llog context correctly ========================================================== 01:39:52 (1788586792) [ 6105.057199] LustreError: MGC192.168.201.147@tcp: Connection to MGS (at 192.168.201.147@tcp) was lost; in progress operations using this service will fail [ 6105.075454] LustreError: Skipped 4 previous similar messages [ 6115.306208] Lustre: Evicted from MGS (at 192.168.201.147@tcp) after server handle changed from 0x83bb3162d4935829 to 0x83bb3162d4935d31 [ 6115.337729] Lustre: Skipped 4 previous similar messages [ 6127.400844] Lustre: DEBUG MARKER: == replay-single test 62: don't mis-drop resent replay === 01:40:37 (1788586837) [ 6131.783339] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 6157.692570] Lustre: 14160:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.201.147@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 6157.711158] Lustre: 14160:0:(mgc_request.c:1900:mgc_process_log()) Skipped 1 previous similar message [ 6192.095236] LustreError: 2355:0:(client.c:3398:ptlrpc_replay_interpret()) @@@ request replay timed out req@ffffa086c48d4e00 x1875462924455040/t313532612612(313532612612) o101->lustre-MDT0000-mdc-ffffa086d0e3a000@192.168.201.147@tcp:12/10 lens 592/664 e 0 to 1 dl 1788586904 ref 2 fl Interpret:EXQU/604/ffffffff rc -110/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 6192.295444] LustreError: 2355:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffffa086c48d4e00 x1875462924455040/t313532612612(313532612612) o101->lustre-MDT0000-mdc-ffffa086d0e3a000@192.168.201.147@tcp:12/10 lens 592/608 e 0 to 0 dl 1788586920 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'createmany.0' uid:0 gid:0 projid:0 [ 6192.320157] LustreError: 2355:0:(client.c:3448:ptlrpc_replay_interpret()) Skipped 19 previous similar messages [ 6200.608657] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6202.133224] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6214.190253] Lustre: DEBUG MARKER: == replay-single test 65a: AT: verify early replies ====== 01:42:04 (1788586924) [ 6274.944269] Lustre: DEBUG MARKER: == replay-single test 65b: AT: verify early replies on packed reply / bulk ========================================================== 01:43:06 (1788586986) [ 6329.347635] Lustre: DEBUG MARKER: == replay-single test 66a: AT: verify MDT service time adjusts with no early replies ========================================================== 01:44:00 (1788587040) [ 6398.322680] Lustre: DEBUG MARKER: == replay-single test 66b: AT: verify net latency adjusts ========================================================== 01:45:09 (1788587109) [ 6426.435884] LustreError: 125532:0:(client.c:1694:after_reply()) cfs_fail_timeout id 50c sleeping for 10000ms [ 6436.447200] LustreError: 125532:0:(client.c:1694:after_reply()) cfs_fail_timeout id 50c awake [ 6436.479263] LustreError: 125532:0:(client.c:1694:after_reply()) cfs_fail_timeout id 50c sleeping for 10000ms [ 6446.575930] LustreError: 125532:0:(client.c:1694:after_reply()) cfs_fail_timeout id 50c awake [ 6446.597679] LustreError: 125532:0:(client.c:1694:after_reply()) cfs_fail_timeout id 50c sleeping for 10000ms [ 6456.599164] LustreError: 125532:0:(client.c:1694:after_reply()) cfs_fail_timeout id 50c awake [ 6456.624737] LustreError: 125532:0:(client.c:1694:after_reply()) cfs_fail_timeout id 50c sleeping for 10000ms [ 6466.649537] LustreError: 125532:0:(client.c:1694:after_reply()) cfs_fail_timeout id 50c awake [ 6466.672450] LustreError: 2357:0:(client.c:1694:after_reply()) cfs_fail_timeout id 50c sleeping for 10000ms [ 6476.679909] LustreError: 2357:0:(client.c:1694:after_reply()) cfs_fail_timeout id 50c awake [ 6476.691082] LustreError: 125532:0:(client.c:1694:after_reply()) cfs_fail_timeout id 50c sleeping for 10000ms [ 6486.711099] LustreError: 125532:0:(client.c:1694:after_reply()) cfs_fail_timeout id 50c awake [ 6494.358990] Lustre: DEBUG MARKER: == replay-single test 67a: AT: verify slow request processing doesn't induce reconnects ========================================================== 01:46:45 (1788587205) [ 6575.561760] Lustre: DEBUG MARKER: == replay-single test 67b: AT: verify instant slowdown doesn't induce reconnects ========================================================== 01:48:06 (1788587286) [ 6610.643341] Lustre: DEBUG MARKER: phase 2 [ 6619.927629] Lustre: DEBUG MARKER: == replay-single test 68: AT: verify slowing locks ======= 01:48:51 (1788587331) [ 6651.240825] LustreError: 31439:0:(ldlm_request.c:1533:ldlm_cli_cancel_req()) cfs_fail_timeout id 312 sleeping for 19000ms [ 6670.327150] LustreError: 31439:0:(ldlm_request.c:1533:ldlm_cli_cancel_req()) cfs_fail_timeout id 312 awake [ 6704.321835] Lustre: DEBUG MARKER: == replay-single test 70a: check multi client t-f ======== 01:50:15 (1788587415) [ 6706.335498] Lustre: DEBUG MARKER: SKIP: replay-single test_70a Need two or more clients, have 1 [ 6709.197787] Lustre: DEBUG MARKER: == replay-single test 70b: dbench 1mdts recovery; 1 clients ========================================================== 01:50:19 (1788587419) [ 6716.321723] Lustre: DEBUG MARKER: Started rundbench load pid=128813 ... [ 6723.707463] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 6727.074289] Lustre: DEBUG MARKER: test_70b fail mds1 1 times [ 6749.164137] LustreError: MGC192.168.201.147@tcp: Connection to MGS (at 192.168.201.147@tcp) was lost; in progress operations using this service will fail [ 6749.179718] LustreError: Skipped 1 previous similar message [ 6749.193723] Lustre: Evicted from MGS (at 192.168.201.147@tcp) after server handle changed from 0x83bb3162d493635f to 0x83bb3162d493c096 [ 6749.203406] Lustre: Skipped 1 previous similar message [ 6749.215603] Lustre: MGC192.168.201.147@tcp: Connection restored to 192.168.201.147@tcp (at 192.168.201.147@tcp) [ 6749.222771] Lustre: Skipped 9 previous similar messages [ 6751.216089] Lustre: 14160:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.201.147@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 6752.223368] Lustre: 128854:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788587442/real 1788587442] req@ffffa086c4fc7480 x1875462924811648/t0(0) o101->lustre-MDT0000-mdc-ffffa086d0e3a000@192.168.201.147@tcp:12/10 lens 584/1152 e 0 to 1 dl 1788587464 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'dbench.0' uid:0 gid:0 projid:0 [ 6752.238020] Lustre: 128854:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 17 previous similar messages [ 6752.241810] Lustre: lustre-MDT0000-mdc-ffffa086d0e3a000: Connection to lustre-MDT0000 (at 192.168.201.147@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 6752.250723] Lustre: Skipped 2 previous similar messages [ 6762.551122] LustreError: 2355:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffffa086c4fc6680 x1875462924668416/t317827580301(317827580301) o101->lustre-MDT0000-mdc-ffffa086d0e3a000@192.168.201.147@tcp:12/10 lens 576/608 e 0 to 0 dl 1788587490 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'dbench.0' uid:0 gid:0 projid:0 [ 6762.591158] LustreError: 2355:0:(client.c:3448:ptlrpc_replay_interpret()) Skipped 24 previous similar messages [ 6773.688670] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6775.946208] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6783.619889] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 6786.711552] Lustre: DEBUG MARKER: test_70b fail mds1 2 times [ 6789.156584] LustreError: lustre-MDT0000-mdc-ffffa086d0e3a000: operation mds_readpage to node 192.168.201.147@tcp failed: rc = -19 [ 6829.136591] LustreError: 2355:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffffa086c4fc6680 x1875462924668416/t317827580301(317827580301) o101->lustre-MDT0000-mdc-ffffa086d0e3a000@192.168.201.147@tcp:12/10 lens 576/608 e 0 to 0 dl 1788587557 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'dbench.0' uid:0 gid:0 projid:0 [ 6829.183539] LustreError: 2355:0:(client.c:3448:ptlrpc_replay_interpret()) Skipped 33 previous similar messages [ 6840.417807] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6842.997721] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6869.912841] Lustre: DEBUG MARKER: == replay-single test 70c: tar 1mdts recovery ============ 01:53:00 (1788587580) [ 6995.896509] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 7007.934383] Lustre: DEBUG MARKER: test_70c fail mds1 1 times [ 7010.548874] LustreError: lustre-MDT0000-mdc-ffffa086d0e3a000: operation ldlm_enqueue to node 192.168.201.147@tcp failed: rc = -19 [ 7048.407196] LustreError: 2355:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status -116, old was 0 req@ffffa086c304d880 x1875462928817792/t326417522062(326417522062) o35->lustre-MDT0000-mdc-ffffa086d0e3a000@192.168.201.147@tcp:23/10 lens 392/456 e 0 to 0 dl 1788587776 ref 2 fl Interpret:RQU/604/0 rc -116/-116 job:'tar.0' uid:0 gid:0 projid:0 [ 7048.445533] LustreError: 2355:0:(client.c:3448:ptlrpc_replay_interpret()) Skipped 27 previous similar messages [ 7061.806513] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 7063.677852] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7114.126466] Lustre: DEBUG MARKER: == replay-single test 70d: mkdir/rmdir striped dir 1mdts recovery ========================================================== 01:57:04 (1788587824) [ 7116.447785] Lustre: DEBUG MARKER: SKIP: replay-single test_70d needs >= 2 MDTs [ 7118.749861] Lustre: DEBUG MARKER: == replay-single test 70e: rename cross-MDT with random fails ========================================================== 01:57:09 (1788587829) [ 7120.736986] Lustre: DEBUG MARKER: SKIP: replay-single test_70e needs >= 2 MDTs [ 7122.984566] Lustre: DEBUG MARKER: == replay-single test 70f: OSS O_DIRECT recovery with 1 clients ========================================================== 01:57:13 (1788587833) [ 7132.590162] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-OST0000 [ 7135.550528] Lustre: DEBUG MARKER: test_70f failing OST 1 times [ 7176.226915] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 7178.971137] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 7192.769439] Lustre: DEBUG MARKER: == replay-single test 71a: mkdir/rmdir striped dir with 2 mdts recovery ========================================================== 01:58:23 (1788587903) [ 7194.876844] Lustre: DEBUG MARKER: SKIP: replay-single test_71a needs >= 2 MDTs [ 7198.229381] Lustre: DEBUG MARKER: == replay-single test 73a: open(O_CREAT), unlink, replay, reconnect before open replay, close ========================================================== 01:58:28 (1788587908) [ 7203.608992] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 7242.719451] LustreError: 2355:0:(client.c:3398:ptlrpc_replay_interpret()) @@@ request replay timed out req@ffffa086d108b800 x1875462930476800/t330712484661(330712484661) o101->lustre-MDT0000-mdc-ffffa086d0e3a000@192.168.201.147@tcp:12/10 lens 592/664 e 0 to 1 dl 1788587955 ref 2 fl Interpret:EXPQU/604/ffffffff rc -110/-1 job:'multiop.0' uid:0 gid:0 projid:0 [ 7242.859235] LustreError: 2355:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffffa086d108b800 x1875462930476800/t330712484661(330712484661) o101->lustre-MDT0000-mdc-ffffa086d0e3a000@192.168.201.147@tcp:12/10 lens 592/608 e 0 to 0 dl 1788587971 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'multiop.0' uid:0 gid:0 projid:0 [ 7242.878232] LustreError: 2355:0:(client.c:3448:ptlrpc_replay_interpret()) Skipped 114 previous similar messages [ 7251.462246] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 7253.542401] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7264.344534] Lustre: DEBUG MARKER: == replay-single test 73b: open(O_CREAT), unlink, replay, reconnect at open_replay reply, close ========================================================== 01:59:35 (1788587975) [ 7270.235113] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 7320.543538] LustreError: 2355:0:(client.c:3398:ptlrpc_replay_interpret()) @@@ request replay timed out req@ffffa086d15eed80 x1875462930488576/t335007449091(335007449091) o101->lustre-MDT0000-mdc-ffffa086d0e3a000@192.168.201.147@tcp:12/10 lens 592/664 e 0 to 1 dl 1788588033 ref 2 fl Interpret:EXPQU/604/ffffffff rc -110/-1 job:'multiop.0' uid:0 gid:0 projid:0 [ 7327.303591] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 7329.409915] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7340.402936] Lustre: DEBUG MARKER: == replay-single test 74: Ensure applications don't fail waiting for OST recovery ========================================================== 02:00:51 (1788588051) [ 7343.315920] Lustre: Unmounted lustre-client [ 7387.856914] Lustre: Mounted lustre-client - version 2.17.57_103_g3d8212a [ 7415.597320] Lustre: DEBUG MARKER: == replay-single test 80a: DNE: create remote dir, drop update rep from MDT0, fail MDT0 ========================================================== 02:02:06 (1788588126) [ 7417.273881] Lustre: DEBUG MARKER: SKIP: replay-single test_80a needs >= 2 MDTs [ 7419.553355] Lustre: DEBUG MARKER: == replay-single test 80b: DNE: create remote dir, drop update rep from MDT0, fail MDT1 ========================================================== 02:02:10 (1788588130) [ 7421.472928] Lustre: DEBUG MARKER: SKIP: replay-single test_80b needs >= 2 MDTs [ 7424.048993] Lustre: DEBUG MARKER: == replay-single test 80c: DNE: create remote dir, drop update rep from MDT1, fail MDT[0,1] ========================================================== 02:02:14 (1788588134) [ 7426.186867] Lustre: DEBUG MARKER: SKIP: replay-single test_80c needs >= 2 MDTs [ 7428.241807] Lustre: DEBUG MARKER: == replay-single test 80d: DNE: create remote dir, drop update rep from MDT1, fail 2 MDTs ========================================================== 02:02:18 (1788588138) [ 7431.270767] Lustre: DEBUG MARKER: SKIP: replay-single test_80d needs >= 2 MDTs [ 7434.004190] Lustre: DEBUG MARKER: == replay-single test 80e: DNE: create remote dir, drop MDT1 rep, fail MDT0 ========================================================== 02:02:24 (1788588144) [ 7436.029696] Lustre: DEBUG MARKER: SKIP: replay-single test_80e needs >= 2 MDTs [ 7438.752687] Lustre: DEBUG MARKER: == replay-single test 80f: DNE: create remote dir, drop MDT1 rep, fail MDT1 ========================================================== 02:02:28 (1788588148) [ 7440.898714] Lustre: DEBUG MARKER: SKIP: replay-single test_80f needs >= 2 MDTs [ 7442.399618] Lustre: DEBUG MARKER: == replay-single test 80g: DNE: create remote dir, drop MDT1 rep, fail MDT0, then MDT1 ========================================================== 02:02:33 (1788588153) [ 7444.797766] Lustre: DEBUG MARKER: SKIP: replay-single test_80g needs >= 2 MDTs [ 7446.537546] Lustre: DEBUG MARKER: == replay-single test 80h: DNE: create remote dir, drop MDT1 rep, fail 2 MDTs ========================================================== 02:02:37 (1788588157) [ 7449.181278] Lustre: DEBUG MARKER: SKIP: replay-single test_80h needs >= 2 MDTs [ 7452.261209] Lustre: DEBUG MARKER: == replay-single test 81a: DNE: unlink remote dir, drop MDT0 update rep, fail MDT1 ========================================================== 02:02:42 (1788588162) [ 7454.534252] Lustre: DEBUG MARKER: SKIP: replay-single test_81a needs >= 2 MDTs [ 7457.404053] Lustre: DEBUG MARKER: == replay-single test 81b: DNE: unlink remote dir, drop MDT0 update reply, fail MDT0 ========================================================== 02:02:47 (1788588167) [ 7458.850293] Lustre: DEBUG MARKER: SKIP: replay-single test_81b needs >= 2 MDTs [ 7460.902928] Lustre: DEBUG MARKER: == replay-single test 81c: DNE: unlink remote dir, drop MDT0 update reply, fail MDT0,MDT1 ========================================================== 02:02:51 (1788588171) [ 7463.127549] Lustre: DEBUG MARKER: SKIP: replay-single test_81c needs >= 2 MDTs [ 7465.745743] Lustre: DEBUG MARKER: == replay-single test 81d: DNE: unlink remote dir, drop MDT0 update reply, fail 2 MDTs ========================================================== 02:02:55 (1788588175) [ 7468.572605] Lustre: DEBUG MARKER: SKIP: replay-single test_81d needs >= 2 MDTs [ 7471.556780] Lustre: DEBUG MARKER: == replay-single test 81e: DNE: unlink remote dir, drop MDT1 req reply, fail MDT0 ========================================================== 02:03:01 (1788588181) [ 7473.980473] Lustre: DEBUG MARKER: SKIP: replay-single test_81e needs >= 2 MDTs [ 7476.365375] Lustre: DEBUG MARKER: == replay-single test 81f: DNE: unlink remote dir, drop MDT1 req reply, fail MDT1 ========================================================== 02:03:06 (1788588186) [ 7479.280390] Lustre: DEBUG MARKER: SKIP: replay-single test_81f needs >= 2 MDTs [ 7482.060678] Lustre: DEBUG MARKER: == replay-single test 81g: DNE: unlink remote dir, drop req reply, fail M0, then M1 ========================================================== 02:03:12 (1788588192) [ 7484.858756] Lustre: DEBUG MARKER: SKIP: replay-single test_81g needs >= 2 MDTs [ 7487.504408] Lustre: DEBUG MARKER: == replay-single test 81h: DNE: unlink remote dir, drop request reply, fail 2 MDTs ========================================================== 02:03:17 (1788588197) [ 7489.858642] Lustre: DEBUG MARKER: SKIP: replay-single test_81h needs >= 2 MDTs [ 7492.542697] Lustre: DEBUG MARKER: == replay-single test 84a: stale open during export disconnect ========================================================== 02:03:22 (1788588202) [ 7495.659216] Lustre: lustre-MDT0000-mdc-ffffa086c440b800: Connection to lustre-MDT0000 (at 192.168.201.147@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 7495.674312] Lustre: Skipped 5 previous similar messages [ 7495.684866] LustreError: lustre-MDT0000-mdc-ffffa086c440b800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 7495.710674] Lustre: lustre-MDT0000-mdc-ffffa086c440b800: Connection restored to 192.168.201.147@tcp (at 192.168.201.147@tcp) [ 7495.727986] Lustre: Skipped 9 previous similar messages [ 7504.867883] Lustre: DEBUG MARKER: == replay-single test 85a: check the cancellation of unused locks during recovery(IBITS) ========================================================== 02:03:35 (1788588215) [ 7532.511465] Lustre: 2358:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788588228/real 1788588228] req@ffffa086d038c700 x1875462930643968/t0(0) o400->lustre-MDT0000-mdc-ffffa086c440b800@192.168.201.147@tcp:12/10 lens 224/224 e 0 to 1 dl 1788588244 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 7532.569706] Lustre: 2358:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 17 previous similar messages [ 7532.591776] LustreError: MGC192.168.201.147@tcp: Connection to MGS (at 192.168.201.147@tcp) was lost; in progress operations using this service will fail [ 7532.617146] LustreError: Skipped 4 previous similar messages [ 7542.764456] Lustre: Evicted from MGS (at 192.168.201.147@tcp) after server handle changed from 0x83bb3162d499a90d to 0x83bb3162d499cd1e [ 7542.790120] Lustre: Skipped 4 previous similar messages [ 7544.426894] Lustre: 139300:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.201.147@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 7558.154879] LustreError: 2355:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffffa086d15ef800 x1875462930518272/t343597383689(343597383689) o101->lustre-MDT0000-mdc-ffffa086c440b800@192.168.201.147@tcp:12/10 lens 576/608 e 0 to 0 dl 1788588286 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'grep.0' uid:0 gid:0 projid:0 [ 7558.184934] LustreError: 2355:0:(client.c:3448:ptlrpc_replay_interpret()) Skipped 1 previous similar message [ 7566.063619] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 7568.084419] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7580.092366] Lustre: DEBUG MARKER: == replay-single test 85b: check the cancellation of unused locks during recovery(EXTENT) ========================================================== 02:04:50 (1788588290) [ 7640.620199] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 7642.969377] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 7657.651362] Lustre: DEBUG MARKER: == replay-single test 86: umount server after clear nid_stats should not hit LBUG ========================================================== 02:06:08 (1788588368) [ 7661.131192] Lustre: Unmounted lustre-client [ 7682.621884] Lustre: Mounted lustre-client - version 2.17.57_103_g3d8212a [ 7690.631877] Lustre: DEBUG MARKER: == replay-single test 87a: write replay ================== 02:06:41 (1788588401) [ 7695.978375] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-OST0000 [ 7734.766851] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 7737.671949] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 7748.239910] Lustre: DEBUG MARKER: == replay-single test 87b: write replay with changed data (checksum resend) ========================================================== 02:07:38 (1788588458) [ 7753.516772] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-OST0000 [ 7797.442900] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 7798.973632] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 7809.980774] Lustre: DEBUG MARKER: == replay-single test 88: MDS should not assign same objid to different files ========================================================== 02:08:40 (1788588520) [ 7813.670840] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-OST0000 [ 7817.937158] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 7892.528741] LustreError: 2355:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffffa086c35ed180 x1875462930939520/t352187318288(352187318288) o101->lustre-MDT0000-mdc-ffffa086d10c1800@192.168.201.147@tcp:12/10 lens 576/608 e 0 to 0 dl 1788588620 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'md5sum.0' uid:0 gid:0 projid:0 [ 7892.559605] LustreError: 2355:0:(client.c:3448:ptlrpc_replay_interpret()) Skipped 99 previous similar messages [ 7927.750549] Lustre: DEBUG MARKER: == replay-single test 89: no disk space leak on late ost connection ========================================================== 02:10:38 (1788588638) [ 7986.319185] Lustre: Unmounted lustre-client [ 8001.806889] Lustre: Mounted lustre-client - version 2.17.57_103_g3d8212a [ 8001.842781] LustreError: lustre-OST0000-osc-ffffa086d0e95800: operation ost_connect to node 192.168.201.147@tcp failed: rc = -16 [ 8007.183792] LustreError: lustre-OST0000-osc-ffffa086d0e95800: operation ost_connect to node 192.168.201.147@tcp failed: rc = -16 [ 8012.305996] LustreError: lustre-OST0000-osc-ffffa086d0e95800: operation ost_connect to node 192.168.201.147@tcp failed: rc = -16 [ 8017.410536] LustreError: lustre-OST0000-osc-ffffa086d0e95800: operation ost_connect to node 192.168.201.147@tcp failed: rc = -16 [ 8022.505085] LustreError: lustre-OST0000-osc-ffffa086d0e95800: operation ost_connect to node 192.168.201.147@tcp failed: rc = -16 [ 8032.763171] LustreError: lustre-OST0000-osc-ffffa086d0e95800: operation ost_connect to node 192.168.201.147@tcp failed: rc = -16 [ 8032.772192] LustreError: Skipped 1 previous similar message [ 8053.231934] LustreError: lustre-OST0000-osc-ffffa086d0e95800: operation ost_connect to node 192.168.201.147@tcp failed: rc = -16 [ 8053.247099] LustreError: Skipped 3 previous similar messages [ 8070.364954] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 59 sec [ 8089.911736] Lustre: DEBUG MARKER: free_before: 7520256 free_after: 7520256 [ 8099.172876] Lustre: DEBUG MARKER: == replay-single test 90: lfs find identifies the missing striped file segments ========================================================== 02:13:29 (1788588809) [ 8149.716599] Lustre: DEBUG MARKER: == replay-single test 93a: replay + reconnect ============ 02:14:20 (1788588860) [ 8155.624917] LustreError: lustre-OST0000-osc-ffffa086d0e95800: operation ost_sync to node 192.168.201.147@tcp failed: rc = -107 [ 8155.636866] LustreError: Skipped 2 previous similar messages [ 8155.641599] Lustre: lustre-OST0000-osc-ffffa086d0e95800: Connection to lustre-OST0000 (at 192.168.201.147@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 8155.672571] Lustre: Skipped 8 previous similar messages [ 8191.967558] Lustre: 2355:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788588888/real 1788588888] req@ffffa086c6f0aa00 x1875462931077760/t0(0) o400->lustre-OST0000-osc-ffffa086d0e95800@192.168.201.147@tcp:28/4 lens 224/224 e 0 to 1 dl 1788588904 ref 1 fl Rpc:XQr/2c0/ffffffff rc 0/-1 job:'ptlrpcd_rcv.0' uid:0 gid:0 projid:4294967295 [ 8192.026289] Lustre: 2355:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 14 previous similar messages [ 8215.897849] Lustre: lustre-OST0000-osc-ffffa086d0e95800: Connection restored to 192.168.201.147@tcp (at 192.168.201.147@tcp) [ 8215.925390] Lustre: Skipped 9 previous similar messages [ 8223.832707] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 8226.157234] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 8236.482561] Lustre: DEBUG MARKER: == replay-single test 93b: replay + reconnect on mds ===== 02:15:47 (1788588947) [ 8260.066836] LustreError: MGC192.168.201.147@tcp: Connection to MGS (at 192.168.201.147@tcp) was lost; in progress operations using this service will fail [ 8260.074785] LustreError: Skipped 2 previous similar messages [ 8260.081487] Lustre: Evicted from MGS (at 192.168.201.147@tcp) after server handle changed from 0x83bb3162d49a2be4 to 0x83bb3162d49a34f1 [ 8260.087389] Lustre: Skipped 2 previous similar messages [ 8261.294068] Lustre: 154325:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.201.147@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 8261.304433] Lustre: 154325:0:(mgc_request.c:1900:mgc_process_log()) Skipped 1 previous similar message [ 8358.960094] Lustre: DEBUG MARKER: oleg147-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 8361.331698] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8374.874706] Lustre: DEBUG MARKER: == replay-single test complete, duration 8094 sec ======== 02:18:04 (1788589084) [ 8376.986437] Lustre: DEBUG MARKER: === replay-single: start cleanup 02:18:07 (1788589087) === [ 8391.948678] Lustre: DEBUG MARKER: === replay-single: finish cleanup 02:18:22 (1788589102) === [ 8416.472530] Lustre: Unmounted lustre-client [ 8457.286110] Key type lgssc unregistered [ 8457.576730] LNet: 160677:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 8457.583920] LNetError: 160677:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 8457.603622] LNet: Removed LNI 192.168.201.47@tcp [ 8458.785188] Key type .llcrypt unregistered [ 8458.788256] Key type ._llcrypt unregistered