[ 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-8.fc42 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 451423263 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 0x00000000BFFE2421 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE22BD 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 00227D (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE2331 000090 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE23C1 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE23F9 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe22bd-0xbffe2330] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe22bc] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe2331-0xbffe23c0] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe23c1-0xbffe23f8] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe23f9-0xbffe2420] [ 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.001011] APIC: Switch to symmetric I/O mode setup [ 0.003335] x2apic enabled [ 0.004008] Switched APIC routing to physical x2apic. [ 0.005014] kvm-guest: setup PV IPIs [ 0.007778] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.008000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.008024] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.009014] pid_max: default: 32768 minimum: 301 [ 0.010123] LSM: Security Framework initializing [ 0.011055] Yama: becoming mindful. [ 0.012040] SELinux: Initializing. [ 0.013076] *** VALIDATE selinux *** [ 0.021604] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.025731] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.026152] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.028112] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.029109] *** VALIDATE tmpfs *** [ 0.031211] *** VALIDATE proc *** [ 0.032226] *** VALIDATE cgroup *** [ 0.033010] *** VALIDATE cgroup2 *** [ 0.034279] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.035138] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.036008] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.037032] Spectre V2 : User space: Vulnerable [ 0.038011] Speculative Store Bypass: Vulnerable [ 0.041453] debug: unmapping init [mem 0xffffffff9e859000-0xffffffff9e860fff] [ 0.043314] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.044813] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.045028] ... version: 2 [ 0.046011] ... bit width: 48 [ 0.047011] ... generic registers: 4 [ 0.048013] ... value mask: 0000ffffffffffff [ 0.049015] ... max period: 00007fffffffffff [ 0.050015] ... fixed-purpose events: 3 [ 0.051015] ... event mask: 000000070000000f [ 0.053237] rcu: Hierarchical SRCU implementation. [ 0.055427] smp: Bringing up secondary CPUs ... [ 0.056566] x86: Booting SMP configuration: [ 0.057027] .... node #0, CPUs: #1 #2 #3 [ 0.061026] smp: Brought up 1 node, 4 CPUs [ 0.063018] smpboot: Max logical packages: 1 [ 0.064020] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.208054] node 0 deferred pages initialised in 141ms [ 0.211098] devtmpfs: initialized [ 0.213418] x86/mm: Memory block size: 128MB [ 0.218183] gcov: version magic: 0x41383552 [ 0.221356] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.222095] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.225469] pinctrl core: initialized pinctrl subsystem [ 0.227279] [ 0.228011] ************************************************************* [ 0.231023] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.234023] ** ** [ 0.236023] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.239037] ** ** [ 0.242024] ** This means that this kernel is built to expose internal ** [ 0.244020] ** IOMMU data structures, which may compromise security on ** [ 0.247025] ** your system. ** [ 0.249022] ** ** [ 0.252037] ** If you see this message and you are not debugging the ** [ 0.254021] ** kernel, report this immediately to your vendor! ** [ 0.257025] ** ** [ 0.260018] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.262020] ************************************************************* [ 0.265796] NET: Registered protocol family 16 [ 0.268603] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.271062] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.274068] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.278035] cpuidle: using governor menu [ 0.280567] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.283502] PCI: Using configuration type 1 for base access [ 0.285154] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.293156] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.296043] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.300123] cryptd: max_cpu_qlen set to 1000 [ 0.303228] ACPI: Added _OSI(Module Device) [ 0.305016] ACPI: Added _OSI(Processor Device) [ 0.307012] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.309029] ACPI: Added _OSI(Processor Aggregator Device) [ 0.314080] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.319275] ACPI: Interpreter enabled [ 0.321062] ACPI: PM: (supports S0 S3 S4 S5) [ 0.323013] ACPI: Using IOAPIC for interrupt routing [ 0.325098] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.328357] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.338575] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.340034] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.342021] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.345110] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.349475] acpiphp: Slot [2] registered [ 0.351113] acpiphp: Slot [5] registered [ 0.352131] acpiphp: Slot [6] registered [ 0.353102] acpiphp: Slot [3] registered [ 0.354068] acpiphp: Slot [4] registered [ 0.355178] acpiphp: Slot [7] registered [ 0.357089] acpiphp: Slot [8] registered [ 0.358112] acpiphp: Slot [9] registered [ 0.360140] acpiphp: Slot [10] registered [ 0.361073] acpiphp: Slot [11] registered [ 0.363086] acpiphp: Slot [12] registered [ 0.364104] acpiphp: Slot [13] registered [ 0.366108] acpiphp: Slot [14] registered [ 0.367135] acpiphp: Slot [15] registered [ 0.369096] acpiphp: Slot [16] registered [ 0.371140] acpiphp: Slot [17] registered [ 0.373116] acpiphp: Slot [18] registered [ 0.374108] acpiphp: Slot [19] registered [ 0.375085] acpiphp: Slot [20] registered [ 0.377112] acpiphp: Slot [21] registered [ 0.378089] acpiphp: Slot [22] registered [ 0.379123] acpiphp: Slot [23] registered [ 0.380103] acpiphp: Slot [24] registered [ 0.382134] acpiphp: Slot [25] registered [ 0.383192] acpiphp: Slot [26] registered [ 0.384083] acpiphp: Slot [27] registered [ 0.385098] acpiphp: Slot [28] registered [ 0.387107] acpiphp: Slot [29] registered [ 0.389101] acpiphp: Slot [30] registered [ 0.391116] acpiphp: Slot [31] registered [ 0.392060] PCI host bridge to bus 0000:00 [ 0.393018] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.396024] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.399027] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.402033] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.405027] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.407027] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.409173] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.412334] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.416463] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.422017] pci 0000:00:01.1: reg 0x20: [io 0xc120-0xc12f] [ 0.426364] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.429022] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.432027] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.434020] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.438372] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.440797] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.443046] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.445964] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.451014] pci 0000:00:02.0: reg 0x10: [io 0xc100-0xc11f] [ 0.461021] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.467017] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.471370] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.479016] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.485013] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.500995] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.511533] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.515817] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.523021] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.542013] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.554400] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.556282] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.558912] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.562499] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.564250] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.568125] iommu: Default domain type: Passthrough [ 0.570453] SCSI subsystem initialized [ 0.572173] ACPI: bus type USB registered [ 0.574123] usbcore: registered new interface driver usbfs [ 0.577114] usbcore: registered new interface driver hub [ 0.579091] usbcore: registered new device driver usb [ 0.580183] pps_core: LinuxPPS API ver. 1 registered [ 0.582015] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.586059] PTP clock support registered [ 0.588158] EDAC MC: Ver: 3.0.0 [ 0.591176] PCI: Using ACPI for IRQ routing [ 0.592771] NetLabel: Initializing [ 0.593015] NetLabel: domain hash size = 128 [ 0.594010] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.595121] NetLabel: unlabeled traffic allowed by default [ 0.597214] vgaarb: loaded [ 0.599220] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.601016] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.607563] clocksource: Switched to clocksource kvm-clock [ 0.728691] VFS: Disk quotas dquot_6.6.0 [ 0.730875] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.734587] *** VALIDATE ramfs *** [ 0.736088] *** VALIDATE hugetlbfs *** [ 0.737816] pnp: PnP ACPI init [ 0.740409] pnp: PnP ACPI: found 6 devices [ 0.758119] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.762047] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.764557] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.767274] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.770253] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.773255] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.776720] NET: Registered protocol family 2 [ 0.779478] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.784816] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.788868] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.794488] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.798492] TCP: Hash tables configured (established 65536 bind 65536) [ 0.801653] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.805234] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.808379] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.811827] NET: Registered protocol family 1 [ 0.814757] RPC: Registered named UNIX socket transport module. [ 0.817253] RPC: Registered udp transport module. [ 0.819201] RPC: Registered tcp transport module. [ 0.821201] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.823652] NET: Registered protocol family 44 [ 0.825460] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.827941] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.830254] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.832702] PCI: CLS 0 bytes, default 64 [ 0.834271] Unpacking initramfs... [ 2.342358] debug: unmapping init [mem 0xffff97713cc64000-0xffff97713ffcffff] [ 2.347591] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.351967] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.355156] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 2.970822] Initialise system trusted keyrings [ 2.972725] Key type blacklist registered [ 2.974958] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.986615] zbud: loaded [ 2.990547] *** VALIDATE nfs *** [ 2.992068] *** VALIDATE nfs4 *** [ 2.994049] pstore: using deflate compression [ 2.997445] Platform Keyring initialized [ 3.130611] NET: Registered protocol family 38 [ 3.132559] Key type asymmetric registered [ 3.134245] Asymmetric key parser 'x509' registered [ 3.136245] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 3.139372] io scheduler mq-deadline registered [ 3.141438] io scheduler kyber registered [ 3.143512] io scheduler bfq registered [ 3.145652] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 3.149524] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 3.152246] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 3.154896] ACPI: Power Button [PWRF] [ 3.160533] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 3.168426] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 3.182781] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 3.211490] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.243453] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.248675] Non-volatile memory driver v1.3 [ 3.250434] Linux agpgart interface v0.103 [ 3.288121] virtio_blk virtio1: [vda] 68040 512-byte logical blocks (34.8 MB/33.2 MiB) [ 3.293501] vda: detected capacity change from 0 to 34836480 [ 3.310611] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.314335] vdb: detected capacity change from 0 to 1073741824 [ 3.323605] libphy: Fixed MDIO Bus: probed [ 3.331427] usbcore: registered new interface driver usbserial_generic [ 3.333950] usbserial: USB Serial support registered for generic [ 3.336095] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.341209] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.343537] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.346452] mousedev: PS/2 mouse device common for all mice [ 3.349428] rtc_cmos 00:05: RTC can wake from S4 [ 3.352322] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.354939] rtc_cmos 00:05: registered as rtc0 [ 3.358764] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.359772] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.362646] intel_pstate: CPU model not supported [ 3.369198] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.369877] hid: raw HID events driver (C) Jiri Kosina [ 3.376314] usbcore: registered new interface driver usbhid [ 3.378732] usbhid: USB HID core driver [ 3.380511] drop_monitor: Initializing network drop monitor service [ 3.383485] Initializing XFRM netlink socket [ 3.385817] NET: Registered protocol family 10 [ 3.389398] Segment Routing with IPv6 [ 3.391270] NET: Registered protocol family 17 [ 3.393225] mpls_gso: MPLS GSO support [ 3.399075] RAS: Correctable Errors collector initialized. [ 3.401627] AVX version of gcm_enc/dec engaged. [ 3.403525] AES CTR mode by8 optimization enabled [ 3.484802] sched_clock: Marking stable (3484766935, 0)->(4412258062, -927491127) [ 3.488809] registered taskstats version 1 [ 3.491638] Loading compiled-in X.509 certificates [ 3.494146] zswap: loaded using pool lzo/zbud [ 3.523600] Key type big_key registered [ 3.537561] Key type encrypted registered [ 3.539365] ima: No TPM chip found, activating TPM-bypass! [ 3.541683] ima: Allocated hash algorithm: sha1 [ 3.543484] ima: No architecture policies found [ 3.545564] evm: Initialising EVM extended attributes: [ 3.547284] evm: security.selinux [ 3.548403] evm: security.ima [ 3.549573] evm: security.capability [ 3.551270] evm: HMAC attrs: 0x1 [ 3.553938] rtc_cmos 00:05: setting system clock to 2026-04-14 14:52:29 UTC (1776178349) [ 3.560510] debug: unmapping init [mem 0xffffffff9f803000-0xffffffff9f9fffff] [ 3.564202] debug: unmapping init [mem 0xffffffff9e582000-0xffffffff9e858fff] [ 3.572089] Write protecting the kernel read-only data: 28672k [ 3.576399] debug: unmapping init [mem 0xffffffff9cc03000-0xffffffff9cdfffff] [ 3.579604] debug: unmapping init [mem 0xffffffff9d514000-0xffffffff9d5fffff] [ 3.617233] 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.629517] systemd[1]: Detected virtualization kvm. [ 3.631618] systemd[1]: Detected architecture x86-64. [ 3.633868] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.662834] systemd[1]: No hostname configured. [ 3.664924] systemd[1]: Set hostname to . [ 3.667359] random: systemd: uninitialized urandom read (16 bytes read) [ 3.670131] systemd[1]: Initializing machine ID from random generator. [ 3.822423] random: systemd: uninitialized urandom read (16 bytes read) [ 3.825243] systemd[1]: Reached target Swap. [ OK ] Reached target Swap. [ 3.829525] random: systemd: uninitialized urandom read (16 bytes read) [ 3.832695] systemd[1]: Listening on Journal Socket (/dev/log). [ OK ] Listening on Journal Socket (/dev/log). [ 3.839508] systemd[1]: Listening on Journal Socket. [ OK ] Listening on Journal Socket. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Listening on udev Control Socket. Starting Setup Virtual Console... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Paths. [ OK ] Reached target Slices. [ OK ] Listening on udev Kernel Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Local File Systems. Starting Create Volatile Files and Directories... [ OK ] Started Memstrack Anylazing Service. [ OK ] Reached target Initrd Root Device. [ OK ] Reached target Timers. Starting Journal Service... [ OK ] Reached target Local Encrypted Volumes. Starting Apply Kernel Variables... [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Setup Virtual Console. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Apply Kernel Variables. Starting dracut cmdline hook... Starting Create Static Device Nodes in /dev... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started Journal Service. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 4.531667] device-mapper: uevent: version 1.0.3 [ 4.534146] device-mapper: ioctl: 4.46.0-ioctl (2022-02-22) initialised: dm-devel@redhat.com [ OK ] Started dracut pre-udev hook. Starting udev Kernel Device Manager... [ OK ] Started udev Kernel Device Manager. Starting dracut pre-trigger hook... [ OK ] Started dracut pre-trigger hook. Starting udev Coldplug all Devices... Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting dracut initqueue hook... [ 5.327972] random: fast init done [ 5.347266] virtio_net virtio0 ens2: renamed from eth0 [ 5.515463] scsi host0: ata_piix [ 5.544315] scsi host1: ata_piix [ 5.546342] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc120 irq 14 [ 5.549118] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc128 irq 15 [ 9.270777] dracut-initqueue[583]: RTNETLINK answers: File exists [ 10.060538] random: crng init done [ 10.061982] random: 7 urandom warning(s) missed due to ratelimiting Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. Mounting /sysroot... [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. [ 10.627892] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped target Timers. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Sockets. [ OK ] Stopped target Paths. [ OK ] Stopped target Slices. [ OK ] Stopped target System Initialization. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped target Swap. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. Stopping udev Kernel Device Manager... [ OK ] Stopped Apply Kernel Variables. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ 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 Control Socket. [ OK ] Closed udev Kernel Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 11.850223] printk: systemd: 26 output lines suppressed due to ratelimiting [ 12.137444] SELinux: Disabled at runtime. [ 12.193964] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 12.203235] systemd[1]: Detected virtualization kvm. [ 12.205652] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 12.780370] systemd[1]: initrd-switch-root.service: Succeeded. [ 12.783487] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 12.788698] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 12.794389] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 12.797713] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 12.805742] systemd[1]: Starting Journal Service... Starting Journal Service... [ 12.809885] systemd[1]: Listening on udev Control Socket. [ OK ] Listening on udev Control Socket. [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd File Systems. [ OK ] Created slice system-serial\x2dgetty.slice. Mounting Kernel Debug File System... Mounting POSIX Message Queue File System... [ OK ] Stopped target Initrd Root File System. Activating swap /dev/disk/by-label/SWAP... Starting Remount Root and Kernel File Systems... [ OK ] Created slice User and Session Slice. [ OK ] Reached target Slices. Mounting Huge Pages File System... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ 12.887632] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS Starting Create list of required st…ce nodes for the current kernel... [ OK ] Reached target rpc_pipefs.target. [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Listening on Process Core Dump Socket. [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Reached target Paths. Starting Apply Kernel Variables... [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Listening on udev Kernel Socket. Starting udev Coldplug all Devices... [ OK ] Created slice system-getty.slice. [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Reached target RPC Port Mapper. [ OK ] Started Journal Service. [ OK ] Mounted Kernel Debug File System. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Activated swap /dev/disk/by-label/SWAP. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Mounted Huge Pages File System. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Apply Kernel Variables. Starting Configure read-only root support... Starting Create Static Device Nodes in /dev... [ OK ] Reached target Swap. Starting Flush Journal to Persistent Storage... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. Starting udev Kernel Device Manager... [ OK ] Reached target Local File Systems (Pre). Mounting /home/green/git/lustre-release... Mounting /mnt... [ OK ] Mounted /mnt. [ OK ] Started udev Coldplug all Devices. [ 13.303585] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 13.586447] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 13.706853] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 13.819438] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 13.838186] EDAC sbridge: Ver: 1.1.2 [ 15.157974] Key type dns_resolver registered [ 15.492862] NFS: Registering the id_resolver key type [ 15.494732] Key type id_resolver registered [ 15.496265] Key type id_legacy registered [ OK ] Started Configure read-only root support. Starting Load/Save Random Seed... [ OK ] Reached target Local File Systems. Starting Rebuild Dynamic Linker Cache... Starting Mark the need to relabel after reboot... Starting Create Volatile Files and Directories... [ OK ] Started Load/Save Random Seed. [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Create Volatile Files and Directories. Starting 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 dnf makecache --timer. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Reached target Timers. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. [ OK ] Started D-Bus System Message Bus. Starting Restore /run/initramfs on shutdown... Starting Login Service... Starting Network Manager... [ OK ] Reached target sshd-keygen.target. [ OK ] Started irqbalance daemon. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ 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... Starting Hostname Service... [ 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... [ OK ] Started OpenSSH server daemon. [ OK ] Started Permit User Sessions. [ OK ] Started Getty on tty1. [ OK ] Started Command Scheduler. [ OK ] Started Serial Getty on ttyS1. [ OK ] Started Serial Getty on ttyS0. [ OK ] Reached target Login Prompts. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting Notify NFS peers of a restart... Starting System Logging Service... Starting Crash recovery kernel arming... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Starting Authorization Manager... [ OK ] Started Authorization Manager. [ OK ] Started Dynamic System Tuning Daemon. [ OK ] Reached target Multi-User System. [ OK ] Reached target Graphical Interface. Starting Update UTMP about System Runlevel Changes... [ OK ] Started Update UTMP about System Runlevel Changes. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg405-client login: [ 49.701083] hrtimer: interrupt took 3075749 ns [ 50.087120] libcfs: loading out-of-tree module taints kernel. [ 50.302915] alg: No test for adler32 (adler32-zlib) [ 51.076457] Key type ._llcrypt registered [ 51.079096] Key type .llcrypt registered [ 51.577450] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [ 52.168299] Lustre: Lustre: Build Version: 2.15.8_13_g05ba8a9 [ 53.181776] LNet: Added LNI 192.168.204.5@tcp [8/256/0/180] [ 53.187328] LNet: Accept secure, port 988 [ 54.991161] Key type lgssc registered [ 56.551043] Lustre: Echo OBD driver; http://www.lustre.org/ [ 191.402189] Lustre: Mounted lustre-client [ 197.081160] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 216.745770] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing check_logdir /tmp/testlogs/ [ 217.055730] Lustre: lustre-OST0000-osc-ffff9771a0be9000: disconnect after 24s idle [ 222.533712] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing yml_node [ 229.314697] Lustre: DEBUG MARKER: Client: 2.15.8.13 [ 233.617237] Lustre: DEBUG MARKER: MDS: 2.15.8.13 [ 238.357387] Lustre: DEBUG MARKER: OSS: 2.15.8.13 [ 241.318834] Lustre: DEBUG MARKER: -----============= acceptance-small: replay-single ============----- Tue Apr 14 10:56:24 EDT 2026 [ 255.127677] Lustre: DEBUG MARKER: excepting tests: 59 [ 266.581524] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing check_config_client /mnt/lustre [ 286.864635] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 295.758443] Lustre: DEBUG MARKER: == replay-single test 0a: empty replay =================== 10:57:20 (1776178640) [ 299.607732] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 311.775536] Lustre: 2218:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776178650/real 1776178650] req@000000001f298c96 x1862458040917504/t0(0) o400->lustre-MDT0000-mdc-ffff9771a0be9000@192.168.204.105@tcp:12/10 lens 224/224 e 0 to 1 dl 1776178657 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:0.0' [ 311.813372] Lustre: lustre-MDT0000-mdc-ffff9771a0be9000: Connection to lustre-MDT0000 (at 192.168.204.105@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 316.895275] Lustre: lustre-OST0000-osc-ffff9771a0be9000: disconnect after 20s idle [ 316.898279] Lustre: Skipped 1 previous similar message [ 316.901121] Lustre: 2218:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776178655/real 1776178655] req@00000000869e7d34 x1862458040917760/t0(0) o400->lustre-MDT0000-mdc-ffff9771a0be9000@192.168.204.105@tcp:12/10 lens 224/224 e 0 to 1 dl 1776178662 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:2.0' [ 321.958851] LustreError: 166-1: MGC192.168.204.105@tcp: Connection to MGS (at 192.168.204.105@tcp) was lost; in progress operations using this service will fail [ 321.973296] Lustre: Evicted from MGS (at 192.168.204.105@tcp) after server handle changed from 0x389fb0410f0bf4c to 0x389fb0410f0c2be [ 321.982592] Lustre: MGC192.168.204.105@tcp: Connection restored to 192.168.204.105@tcp (at 192.168.204.105@tcp) [ 328.235994] Lustre: lustre-MDT0000-mdc-ffff9771a0be9000: Connection restored to 192.168.204.105@tcp (at 192.168.204.105@tcp) [ 335.020574] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 336.684344] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 344.847984] Lustre: DEBUG MARKER: == replay-single test 0b: ensure object created after recover exists. (3284) ========================================================== 10:58:09 (1776178689) [ 348.658376] Lustre: lustre-OST0000-osc-ffff9771a0be9000: Connection to lustre-OST0000 (at 192.168.204.105@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 358.879353] Lustre: lustre-OST0001-osc-ffff9771a0be9000: disconnect after 20s idle [ 358.917443] Lustre: Skipped 1 previous similar message [ 369.867830] Lustre: lustre-OST0000-osc-ffff9771a0be9000: Connection restored to 192.168.204.105@tcp (at 192.168.204.105@tcp) [ 381.269325] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 382.972536] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 390.651606] Lustre: DEBUG MARKER: == replay-single test 0c: check replay-barrier =========== 10:58:55 (1776178735) [ 394.149885] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 394.293146] Lustre: Unmounted lustre-client [ 420.523876] LustreError: 11-0: lustre-MDT0000-mdc-ffff9771a0920800: operation mds_connect to node 192.168.204.105@tcp failed: rc = -16 [ 426.003796] LustreError: 11-0: lustre-MDT0000-mdc-ffff9771a0920800: operation mds_connect to node 192.168.204.105@tcp failed: rc = -16 [ 426.011152] LustreError: Skipped 1 previous similar message [ 431.096835] LustreError: 11-0: lustre-MDT0000-mdc-ffff9771a0920800: operation mds_connect to node 192.168.204.105@tcp failed: rc = -16 [ 436.252705] LustreError: 11-0: lustre-MDT0000-mdc-ffff9771a0920800: operation mds_connect to node 192.168.204.105@tcp failed: rc = -16 [ 441.354435] LustreError: 11-0: lustre-MDT0000-mdc-ffff9771a0920800: operation mds_connect to node 192.168.204.105@tcp failed: rc = -16 [ 451.598828] LustreError: 11-0: lustre-MDT0000-mdc-ffff9771a0920800: operation mds_connect to node 192.168.204.105@tcp failed: rc = -16 [ 451.613273] LustreError: Skipped 1 previous similar message [ 472.061950] LustreError: 11-0: lustre-MDT0000-mdc-ffff9771a0920800: operation mds_connect to node 192.168.204.105@tcp failed: rc = -16 [ 472.078694] LustreError: Skipped 3 previous similar messages [ 482.347430] Lustre: Mounted lustre-client [ 490.564280] Lustre: DEBUG MARKER: == replay-single test 0d: expired recovery with no clients ========================================================== 11:00:34 (1776178834) [ 494.449805] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 494.575762] Lustre: Unmounted lustre-client [ 529.929739] LustreError: 11-0: lustre-MDT0000-mdc-ffff977188904800: operation mds_connect to node 192.168.204.105@tcp failed: rc = -16 [ 529.936110] LustreError: Skipped 1 previous similar message [ 591.415419] Lustre: Mounted lustre-client [ 600.404781] Lustre: DEBUG MARKER: == replay-single test 1: simple create =================== 11:02:24 (1776178944) [ 604.904044] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 618.911759] Lustre: 2216:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776178957/real 1776178957] req@00000000a45720aa x1862458040943040/t0(0) o400->lustre-MDT0000-mdc-ffff977188904800@192.168.204.105@tcp:12/10 lens 224/224 e 0 to 1 dl 1776178964 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:0.0' [ 618.948251] Lustre: lustre-MDT0000-mdc-ffff977188904800: Connection to lustre-MDT0000 (at 192.168.204.105@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 624.031196] Lustre: 2215:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776178962/real 1776178962] req@000000008a03efcb x1862458040943296/t0(0) o400->lustre-MDT0000-mdc-ffff977188904800@192.168.204.105@tcp:12/10 lens 224/224 e 0 to 1 dl 1776178969 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:0.0' [ 629.223042] LustreError: 166-1: MGC192.168.204.105@tcp: Connection to MGS (at 192.168.204.105@tcp) was lost; in progress operations using this service will fail [ 629.259347] Lustre: Evicted from MGS (at 192.168.204.105@tcp) after server handle changed from 0x389fb0410f0cfd0 to 0x389fb0410f0d3ce [ 629.269552] Lustre: MGC192.168.204.105@tcp: Connection restored to (at 192.168.204.105@tcp) [ 635.632409] Lustre: lustre-MDT0000-mdc-ffff977188904800: Connection restored to 192.168.204.105@tcp (at 192.168.204.105@tcp) [ 641.148132] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 642.501707] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 650.824364] Lustre: DEBUG MARKER: == replay-single test 2a: touch ========================== 11:03:15 (1776178995) [ 655.350671] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 667.103197] Lustre: 2218:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776179006/real 1776179006] req@0000000079c8f03e x1862458040947840/t0(0) o400->lustre-MDT0000-mdc-ffff977188904800@192.168.204.105@tcp:12/10 lens 224/224 e 0 to 1 dl 1776179013 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:1.0' [ 667.145476] Lustre: lustre-MDT0000-mdc-ffff977188904800: Connection to lustre-MDT0000 (at 192.168.204.105@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 667.162721] LustreError: 166-1: MGC192.168.204.105@tcp: Connection to MGS (at 192.168.204.105@tcp) was lost; in progress operations using this service will fail [ 684.456161] Lustre: Evicted from MGS (at 192.168.204.105@tcp) after server handle changed from 0x389fb0410f0d3ce to 0x389fb0410f0d6d0 [ 684.469563] Lustre: MGC192.168.204.105@tcp: Connection restored to 192.168.204.105@tcp (at 192.168.204.105@tcp) [ 700.987896] LustreError: 2214:0:(client.c:3161:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@000000002b2c7c59 x1862458040947264/t21474836484(21474836484) o101->lustre-MDT0000-mdc-ffff977188904800@192.168.204.105@tcp:12/10 lens 592/600 e 0 to 0 dl 1776179053 ref 2 fl Interpret:RQU/4/0 rc 301/301 job:'touch.0' [ 701.088173] Lustre: lustre-MDT0000-mdc-ffff977188904800: Connection restored to 192.168.204.105@tcp (at 192.168.204.105@tcp) [ 707.416346] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 708.764301] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 715.294373] Lustre: DEBUG MARKER: == replay-single test 2b: touch ========================== 11:04:20 (1776179060) [ 718.804959] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 728.415537] Lustre: 2215:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776179067/real 1776179067] req@000000005d29a73e x1862458040953088/t0(0) o400->lustre-MDT0000-mdc-ffff977188904800@192.168.204.105@tcp:12/10 lens 224/224 e 0 to 1 dl 1776179074 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:2.0' [ 728.427721] Lustre: 2215:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 728.432417] Lustre: lustre-MDT0000-mdc-ffff977188904800: Connection to lustre-MDT0000 (at 192.168.204.105@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 728.543309] LustreError: 166-1: MGC192.168.204.105@tcp: Connection to MGS (at 192.168.204.105@tcp) was lost; in progress operations using this service will fail [ 745.961087] Lustre: Evicted from MGS (at 192.168.204.105@tcp) after server handle changed from 0x389fb0410f0d6d0 to 0x389fb0410f0db76 [ 745.971159] Lustre: MGC192.168.204.105@tcp: Connection restored to 192.168.204.105@tcp (at 192.168.204.105@tcp) [ 761.375096] LustreError: 2214:0:(client.c:3161:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@000000004d63d16c x1862458040952576/t25769803781(25769803781) o101->lustre-MDT0000-mdc-ffff977188904800@192.168.204.105@tcp:12/10 lens 592/600 e 0 to 0 dl 1776179114 ref 2 fl Interpret:RQU/4/0 rc 301/301 job:'touch.0' [ 766.621446] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 767.798904] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 775.620841] Lustre: DEBUG MARKER: == replay-single test 2c: setstripe replay =============== 11:05:20 (1776179120) [ 779.176818] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 788.895848] Lustre: 2218:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776179127/real 1776179127] req@0000000060d49792 x1862458040958208/t0(0) o400->MGC192.168.204.105@tcp@192.168.204.105@tcp:26/25 lens 224/224 e 0 to 1 dl 1776179134 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:4.0' [ 788.927992] Lustre: 2218:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 788.939489] LustreError: 166-1: MGC192.168.204.105@tcp: Connection to MGS (at 192.168.204.105@tcp) was lost; in progress operations using this service will fail [ 788.958843] Lustre: lustre-MDT0000-mdc-ffff977188904800: Connection to lustre-MDT0000 (at 192.168.204.105@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 805.360865] Lustre: Evicted from MGS (at 192.168.204.105@tcp) after server handle changed from 0x389fb0410f0db76 to 0x389fb0410f0e007 [ 821.776441] LustreError: 2214:0:(client.c:3161:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@00000000b43c1914 x1862458040957632/t30064771076(30064771076) o101->lustre-MDT0000-mdc-ffff977188904800@192.168.204.105@tcp:12/10 lens 536/600 e 0 to 0 dl 1776179174 ref 2 fl Interpret:RQU/4/0 rc 301/301 job:'lfs.0' [ 821.871411] Lustre: lustre-MDT0000-mdc-ffff977188904800: Connection restored to 192.168.204.105@tcp (at 192.168.204.105@tcp) [ 821.880899] Lustre: Skipped 2 previous similar messages [ 826.867092] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 828.397586] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 835.563434] Lustre: DEBUG MARKER: == replay-single test 2d: setdirstripe replay ============ 11:06:20 (1776179180) [ 839.260573] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 849.311379] Lustre: 2217:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776179188/real 1776179188] req@00000000adec4ea1 x1862458040963264/t0(0) o400->lustre-MDT0000-mdc-ffff977188904800@192.168.204.105@tcp:12/10 lens 224/224 e 0 to 1 dl 1776179195 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:3.0' [ 849.332346] Lustre: 2217:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 849.337780] Lustre: lustre-MDT0000-mdc-ffff977188904800: Connection to lustre-MDT0000 (at 192.168.204.105@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 849.349906] LustreError: 166-1: MGC192.168.204.105@tcp: Connection to MGS (at 192.168.204.105@tcp) was lost; in progress operations using this service will fail [ 866.794797] Lustre: Evicted from MGS (at 192.168.204.105@tcp) after server handle changed from 0x389fb0410f0e007 to 0x389fb0410f0e48a [ 888.336137] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 890.105556] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 899.805657] Lustre: DEBUG MARKER: == replay-single test 2e: O_CREAT|O_EXCL create replay === 11:07:24 (1776179244) [ 906.020861] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 919.007311] Lustre: 21168:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776179246/real 1776179246] req@00000000efc13116 x1862458040967680/t0(0) o35->lustre-MDT0000-mdc-ffff977188904800@192.168.204.105@tcp:23/10 lens 392/624 e 0 to 1 dl 1776179264 ref 2 fl Rpc:XQr/0/ffffffff rc 0/-1 job:'openfile.0' [ 919.045854] Lustre: 21168:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 919.067185] Lustre: lustre-MDT0000-mdc-ffff977188904800: Connection to lustre-MDT0000 (at 192.168.204.105@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 919.970044] LustreError: 166-1: MGC192.168.204.105@tcp: Connection to MGS (at 192.168.204.105@tcp) was lost; in progress operations using this service will fail [ 936.425080] Lustre: Evicted from MGS (at 192.168.204.105@tcp) after server handle changed from 0x389fb0410f0e48a to 0x389fb0410f0ea3a [ 944.759559] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 946.248837] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 953.252099] Lustre: DEBUG MARKER: == replay-single test 3a: replay failed open(O_DIRECTORY) ========================================================== 11:08:18 (1776179298) [ 957.075366] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 968.159278] LustreError: 166-1: MGC192.168.204.105@tcp: Connection to MGS (at 192.168.204.105@tcp) was lost; in progress operations using this service will fail [ 985.575207] Lustre: Evicted from MGS (at 192.168.204.105@tcp) after server handle changed from 0x389fb0410f0ea3a to 0x389fb0410f0edd6 [ 985.596090] Lustre: MGC192.168.204.105@tcp: Connection restored to 192.168.204.105@tcp (at 192.168.204.105@tcp) [ 985.603734] Lustre: Skipped 4 previous similar messages [ 1003.078733] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1005.342424] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1014.872827] Lustre: DEBUG MARKER: == replay-single test 3b: replay failed open -ENOMEM ===== 11:09:19 (1776179359) [ 1019.266697] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1033.695519] LustreError: 166-1: MGC192.168.204.105@tcp: Connection to MGS (at 192.168.204.105@tcp) was lost; in progress operations using this service will fail [ 1033.712734] Lustre: lustre-MDT0000-mdc-ffff977188904800: Connection to lustre-MDT0000 (at 192.168.204.105@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1033.727785] Lustre: Skipped 1 previous similar message [ 1050.083167] Lustre: Evicted from MGS (at 192.168.204.105@tcp) after server handle changed from 0x389fb0410f0edd6 to 0x389fb0410f0f22f [ 1063.368647] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1065.278253] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1074.474398] Lustre: DEBUG MARKER: == replay-single test 3c: replay failed open -ENOMEM ===== 11:10:19 (1776179419) [ 1078.207387] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1093.023240] Lustre: 2218:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776179431/real 1776179431] req@00000000b3d3bd96 x1862458040984064/t0(0) o400->lustre-MDT0000-mdc-ffff977188904800@192.168.204.105@tcp:12/10 lens 224/224 e 0 to 1 dl 1776179438 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:0.0' [ 1093.063601] Lustre: 2218:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 9 previous similar messages [ 1122.715690] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1124.314420] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1133.603867] Lustre: DEBUG MARKER: == replay-single test 4a: |x| 10 open(O_CREAT)s ========== 11:11:18 (1776179478) [ 1137.753996] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1165.851107] LustreError: 2214:0:(client.c:3161:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@000000005c5bdd14 x1862458040989120/t55834574851(55834574851) o101->lustre-MDT0000-mdc-ffff977188904800@192.168.204.105@tcp:12/10 lens 592/600 e 0 to 0 dl 1776179518 ref 2 fl Interpret:RQU/4/0 rc 301/301 job:'bash.0' [ 1171.341276] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1172.495543] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1180.277940] Lustre: DEBUG MARKER: == replay-single test 4b: |x| rm 10 files ================ 11:12:05 (1776179525) [ 1184.141485] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1193.444767] Lustre: lustre-MDT0000-mdc-ffff977188904800: Connection to lustre-MDT0000 (at 192.168.204.105@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1193.465520] Lustre: Skipped 2 previous similar messages [ 1193.473876] LustreError: 166-1: MGC192.168.204.105@tcp: Connection to MGS (at 192.168.204.105@tcp) was lost; in progress operations using this service will fail [ 1193.494723] LustreError: Skipped 2 previous similar messages [ 1210.860471] Lustre: Evicted from MGS (at 192.168.204.105@tcp) after server handle changed from 0x389fb0410f0fc85 to 0x389fb0410f10457 [ 1210.873071] Lustre: Skipped 2 previous similar messages [ 1232.104640] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1233.678952] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1241.355279] Lustre: DEBUG MARKER: == replay-single test 5: |x| 220 open(O_CREAT) =========== 11:13:06 (1776179586) [ 1245.341423] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1281.003323] Lustre: MGC192.168.204.105@tcp: Connection restored to 192.168.204.105@tcp (at 192.168.204.105@tcp) [ 1281.011725] Lustre: Skipped 9 previous similar messages [ 1283.105985] LustreError: 2214:0:(client.c:3161:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@00000000d9ff077a x1862458041013312/t64424509443(64424509443) o101->lustre-MDT0000-mdc-ffff977188904800@192.168.204.105@tcp:12/10 lens 592/600 e 0 to 0 dl 1776179635 ref 2 fl Interpret:RQU/4/0 rc 301/301 job:'bash.0' [ 1283.129298] LustreError: 2214:0:(client.c:3161:ptlrpc_replay_interpret()) Skipped 9 previous similar messages [ 1293.739646] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1295.210832] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1318.461144] Lustre: DEBUG MARKER: == replay-single test 6a: mkdir + contained create ======= 11:14:23 (1776179663) [ 1321.635863] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1366.489779] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1367.992079] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1377.903605] Lustre: DEBUG MARKER: == replay-single test 6b: |X| rmdir ====================== 11:15:22 (1776179722) [ 1382.146806] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1394.655445] Lustre: 2215:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776179733/real 1776179733] req@0000000002a5eae5 x1862458041250880/t0(0) o400->MGC192.168.204.105@tcp@192.168.204.105@tcp:26/25 lens 224/224 e 0 to 1 dl 1776179740 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:4.0' [ 1394.690212] Lustre: 2215:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 14 previous similar messages [ 1434.115820] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1435.919511] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1445.136790] Lustre: DEBUG MARKER: == replay-single test 7: mkdir |X| contained create ====== 11:16:29 (1776179789) [ 1449.056162] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1460.194198] Lustre: lustre-MDT0000-mdc-ffff977188904800: Connection to lustre-MDT0000 (at 192.168.204.105@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1460.203542] Lustre: Skipped 3 previous similar messages [ 1460.211412] LustreError: 166-1: MGC192.168.204.105@tcp: Connection to MGS (at 192.168.204.105@tcp) was lost; in progress operations using this service will fail [ 1460.225251] LustreError: Skipped 3 previous similar messages [ 1477.621454] Lustre: Evicted from MGS (at 192.168.204.105@tcp) after server handle changed from 0x389fb0410f19589 to 0x389fb0410f19b6a [ 1477.629103] Lustre: Skipped 3 previous similar messages [ 1482.276210] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1483.835811] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1490.237903] Lustre: DEBUG MARKER: == replay-single test 8: creat open |X| close ============ 11:17:15 (1776179835) [ 1493.447256] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1539.076522] LustreError: 2214:0:(client.c:3161:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@000000009864c5fa x1862458041262080/t81604378634(81604378634) o101->lustre-MDT0000-mdc-ffff977188904800@192.168.204.105@tcp:12/10 lens 664/600 e 0 to 0 dl 1776179892 ref 2 fl Interpret:RPQU/4/0 rc 301/301 job:'multiop.0' [ 1539.100809] LustreError: 2214:0:(client.c:3161:ptlrpc_replay_interpret()) Skipped 219 previous similar messages [ 1544.408656] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1545.728934] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1553.018291] Lustre: DEBUG MARKER: == replay-single test 9: |X| create (same inum/gen) ====== 11:18:17 (1776179897) [ 1557.396795] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1605.075244] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1606.220569] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1613.478025] Lustre: DEBUG MARKER: == replay-single test 10: create |X| rename unlink ======= 11:19:18 (1776179958) [ 1617.368529] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1658.525834] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1660.069480] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1668.296425] Lustre: DEBUG MARKER: == replay-single test 11: create open write rename |X| create-old-name read ========================================================== 11:20:12 (1776180012) [ 1671.732865] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1701.076806] LustreError: 2214:0:(client.c:3161:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@00000000f656d548 x1862458041280000/t94489280521(94489280521) o101->lustre-MDT0000-mdc-ffff977188904800@192.168.204.105@tcp:12/10 lens 592/600 e 0 to 0 dl 1776180053 ref 2 fl Interpret:RQU/4/0 rc 301/301 job:'bash.0' [ 1713.941543] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1715.694247] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1723.545731] Lustre: DEBUG MARKER: == replay-single test 12: open, unlink |X| close ========= 11:21:08 (1776180068) [ 1727.955502] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1770.529318] LustreError: 2214:0:(client.c:3161:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@000000007386eb90 x1862458041280320/t94489280523(94489280523) o101->lustre-MDT0000-mdc-ffff977188904800@192.168.204.105@tcp:12/10 lens 576/600 e 0 to 0 dl 1776180123 ref 2 fl Interpret:RPQU/4/0 rc 301/301 job:'grep.0' [ 1770.576501] LustreError: 2214:0:(client.c:3161:ptlrpc_replay_interpret()) Skipped 1 previous similar message [ 1777.387402] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1778.905074] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1786.340172] Lustre: DEBUG MARKER: == replay-single test 13: open chmod 0 |x| write close === 11:22:11 (1776180131) [ 1790.071688] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1820.646058] Lustre: MGC192.168.204.105@tcp: Connection restored to 192.168.204.105@tcp (at 192.168.204.105@tcp) [ 1820.651258] Lustre: Skipped 17 previous similar messages [ 1827.299162] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1829.392568] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1838.101469] Lustre: DEBUG MARKER: == replay-single test 14: open(O_CREAT), unlink |X| close ========================================================== 11:23:02 (1776180182) [ 1842.409435] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1870.912043] LustreError: 2214:0:(client.c:3161:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@000000007386eb90 x1862458041280320/t94489280523(94489280523) o101->lustre-MDT0000-mdc-ffff977188904800@192.168.204.105@tcp:12/10 lens 576/600 e 0 to 0 dl 1776180223 ref 2 fl Interpret:RPQU/4/0 rc 301/301 job:'grep.0' [ 1870.931544] LustreError: 2214:0:(client.c:3161:ptlrpc_replay_interpret()) Skipped 3 previous similar messages [ 1887.818473] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1890.049653] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1899.054556] Lustre: DEBUG MARKER: == replay-single test 15: open(O_CREAT), unlink |X| touch new, close ========================================================== 11:24:03 (1776180243) [ 1903.697519] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1913.759994] Lustre: 2218:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776180252/real 1776180252] req@00000000ce57ce33 x1862458041306176/t0(0) o400->MGC192.168.204.105@tcp@192.168.204.105@tcp:26/25 lens 224/224 e 0 to 1 dl 1776180259 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:2.0' [ 1913.784684] Lustre: 2218:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 27 previous similar messages [ 1952.991676] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1954.352502] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1962.370887] Lustre: DEBUG MARKER: == replay-single test 16: |X| open(O_CREAT), unlink, touch new, unlink new ========================================================== 11:25:07 (1776180307) [ 1966.171068] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1979.359251] Lustre: lustre-MDT0000-mdc-ffff977188904800: Connection to lustre-MDT0000 (at 192.168.204.105@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1979.382978] Lustre: Skipped 8 previous similar messages [ 1985.520965] LustreError: 166-1: MGC192.168.204.105@tcp: Connection to MGS (at 192.168.204.105@tcp) was lost; in progress operations using this service will fail [ 1985.528760] LustreError: Skipped 8 previous similar messages [ 1998.717914] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2000.604224] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2010.132163] Lustre: DEBUG MARKER: == replay-single test 17: |X| open(O_CREAT), |replay| close ========================================================== 11:25:54 (1776180354) [ 2015.431105] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2045.932711] Lustre: Evicted from MGS (at 192.168.204.105@tcp) after server handle changed from 0x389fb0410f1c67b to 0x389fb0410f1ca25 [ 2045.944821] Lustre: Skipped 9 previous similar messages [ 2061.355981] LustreError: 2214:0:(client.c:3161:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@000000007386eb90 x1862458041280320/t94489280523(94489280523) o101->lustre-MDT0000-mdc-ffff977188904800@192.168.204.105@tcp:12/10 lens 576/600 e 0 to 0 dl 1776180414 ref 2 fl Interpret:RPQU/4/0 rc 301/301 job:'grep.0' [ 2061.396324] LustreError: 2214:0:(client.c:3161:ptlrpc_replay_interpret()) Skipped 5 previous similar messages [ 2067.363887] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2068.454258] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2075.707471] Lustre: DEBUG MARKER: == replay-single test 18: open(O_CREAT), unlink, touch new, close, touch, unlink ========================================================== 11:27:00 (1776180420) [ 2079.539396] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2119.143913] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2120.418684] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2128.089821] Lustre: DEBUG MARKER: == replay-single test 19: mcreate, open, write, rename === 11:27:52 (1776180472) [ 2131.873590] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2175.681640] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2177.162057] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2184.356461] Lustre: DEBUG MARKER: == replay-single test 20a: |X| open(O_CREAT), unlink, replay, close (test mds_cleanup_orphans) ========================================================== 11:28:49 (1776180529) [ 2189.568459] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2228.707778] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2230.093274] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2237.362801] Lustre: DEBUG MARKER: == replay-single test 20b: write, unlink, eviction, replay (test mds_cleanup_orphans) ========================================================== 11:29:42 (1776180582) [ 2242.630931] LustreError: 11-0: lustre-MDT0000-mdc-ffff977188904800: operation ldlm_enqueue to node 192.168.204.105@tcp failed: rc = -107 [ 2242.644105] LustreError: Skipped 11 previous similar messages [ 2242.656142] LustreError: lustre-MDT0000-mdc-ffff977188904800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 2242.668446] LustreError: 55252:0:(file.c:5205:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -5 [ 2242.672408] LustreError: 55267:0:(file.c:246:ll_close_inode_openhandle()) lustre-clilmv-ffff977188904800: inode [0x200001b71:0x118:0x0] mdc close failed: rc = -108 [ 2242.672755] LustreError: 55207:0:(vvp_io.c:1864:vvp_io_init()) lustre: refresh file layout [0x200001b71:0x132:0x0] error -108. [ 2242.699442] LustreError: 55267:0:(file.c:246:ll_close_inode_openhandle()) Skipped 1 previous similar message [ 2285.896434] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2287.305231] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2306.717635] Lustre: DEBUG MARKER: before 6144, after 6144 [ 2313.243625] Lustre: DEBUG MARKER: == replay-single test 20c: check that client eviction does not affect file content ========================================================== 11:30:57 (1776180657) [ 2316.904394] LustreError: 11-0: lustre-MDT0000-mdc-ffff977188904800: operation ldlm_enqueue to node 192.168.204.105@tcp failed: rc = -107 [ 2316.916318] LustreError: lustre-MDT0000-mdc-ffff977188904800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 2316.926757] LustreError: 57223:0:(ldlm_resource.c:1127:ldlm_resource_complain()) lustre-MDT0000-mdc-ffff977188904800: namespace resource [0x200000007:0x1:0x0].0x0 (0000000030a2a142) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 2316.940129] LustreError: 57208:0:(file.c:5205:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -5 [ 2328.057218] Lustre: DEBUG MARKER: == replay-single test 21: |X| open(O_CREAT), unlink touch new, replay, close (test mds_cleanup_orphans) ========================================================== 11:31:12 (1776180672) [ 2331.559775] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2374.663796] LustreError: 2214:0:(client.c:3161:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@000000007ccce3d0 x1862458041354560/t141733920773(141733920773) o101->lustre-MDT0000-mdc-ffff977188904800@192.168.204.105@tcp:12/10 lens 592/600 e 0 to 0 dl 1776180727 ref 2 fl Interpret:RPQU/4/0 rc 301/301 job:'multiop.0' [ 2374.707028] LustreError: 2214:0:(client.c:3161:ptlrpc_replay_interpret()) Skipped 8 previous similar messages [ 2382.878403] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2384.542339] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2393.967952] Lustre: DEBUG MARKER: == replay-single test 22: open(O_CREAT), |X| unlink, replay, close (test mds_cleanup_orphans) ========================================================== 11:32:18 (1776180738) [ 2397.728758] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2424.814706] Lustre: MGC192.168.204.105@tcp: Connection restored to 192.168.204.105@tcp (at 192.168.204.105@tcp) [ 2424.820961] Lustre: Skipped 21 previous similar messages [ 2437.456618] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2439.389318] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2447.081162] Lustre: DEBUG MARKER: == replay-single test 23: open(O_CREAT), |X| unlink touch new, replay, close (test mds_cleanup_orphans) ========================================================== 11:33:11 (1776180791) [ 2450.520479] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2501.504274] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2503.019259] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2510.300374] Lustre: DEBUG MARKER: == replay-single test 24: open(O_CREAT), replay, unlink, close (test mds_cleanup_orphans) ========================================================== 11:34:15 (1776180855) [ 2513.425230] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2522.079506] Lustre: 2217:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776180861/real 1776180861] req@00000000f25c095b x1862458041374656/t0(0) o400->lustre-MDT0000-mdc-ffff977188904800@192.168.204.105@tcp:12/10 lens 224/224 e 0 to 1 dl 1776180868 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:4.0' [ 2522.118250] Lustre: 2217:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 26 previous similar messages [ 2544.206741] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2545.162283] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2550.977815] Lustre: DEBUG MARKER: == replay-single test 25: open(O_CREAT), unlink, replay, close (test mds_cleanup_orphans) ========================================================== 11:34:55 (1776180895) [ 2553.781754] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2592.675716] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2594.013799] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2602.142808] Lustre: DEBUG MARKER: == replay-single test 26: |X| open(O_CREAT), unlink two, close one, replay, close one (test mds_cleanup_orphans) ========================================================== 11:35:46 (1776180946) [ 2605.733730] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2616.223271] Lustre: lustre-MDT0000-mdc-ffff977188904800: Connection to lustre-MDT0000 (at 192.168.204.105@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 2616.238485] Lustre: Skipped 12 previous similar messages [ 2616.245559] LustreError: 166-1: MGC192.168.204.105@tcp: Connection to MGS (at 192.168.204.105@tcp) was lost; in progress operations using this service will fail [ 2616.262661] LustreError: Skipped 10 previous similar messages [ 2655.538513] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2657.306523] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2665.430850] Lustre: DEBUG MARKER: == replay-single test 27: |X| open(O_CREAT), unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 11:36:49 (1776181009) [ 2669.029115] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2698.215135] Lustre: Evicted from MGS (at 192.168.204.105@tcp) after server handle changed from 0x389fb0410f1fb72 to 0x389fb0410f20210 [ 2698.223319] Lustre: Skipped 10 previous similar messages [ 2710.117628] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2711.816223] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2721.292148] Lustre: DEBUG MARKER: == replay-single test 28: open(O_CREAT), |X| unlink two, close one, replay, close one (test mds_cleanup_orphans) ========================================================== 11:37:45 (1776181065) [ 2726.018418] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2774.726734] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2776.349271] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2783.935780] Lustre: DEBUG MARKER: == replay-single test 29: open(O_CREAT), |X| unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 11:38:48 (1776181128) [ 2787.267462] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2829.972712] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2832.496593] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2842.389710] Lustre: DEBUG MARKER: == replay-single test 30: open(O_CREAT) two, unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 11:39:46 (1776181186) [ 2846.561084] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2892.834135] LustreError: 2214:0:(client.c:3161:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@0000000067b06a60 x1862458041412608/t180388626437(180388626437) o101->lustre-MDT0000-mdc-ffff977188904800@192.168.204.105@tcp:12/10 lens 592/600 e 0 to 0 dl 1776181245 ref 2 fl Interpret:RPQU/4/0 rc 301/301 job:'multiop.0' [ 2892.849334] LustreError: 2214:0:(client.c:3161:ptlrpc_replay_interpret()) Skipped 15 previous similar messages [ 2898.729928] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2900.181358] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2907.151608] Lustre: DEBUG MARKER: == replay-single test 31: open(O_CREAT) two, unlink one, |X| unlink one, close two (test mds_cleanup_orphans) ========================================================== 11:40:51 (1776181251) [ 2911.591280] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2949.114622] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2950.413889] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2957.621351] Lustre: DEBUG MARKER: == replay-single test 32: close() notices client eviction; close() after client eviction ========================================================== 11:41:42 (1776181302) [ 2960.545653] LustreError: 11-0: lustre-MDT0000-mdc-ffff977188904800: operation ldlm_enqueue to node 192.168.204.105@tcp failed: rc = -107 [ 2960.572403] LustreError: lustre-MDT0000-mdc-ffff977188904800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 2960.595261] LustreError: 73998:0:(file.c:5205:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -5 [ 2967.320240] Lustre: DEBUG MARKER: == replay-single test 33a: fid seq shouldn't be reused after abort recovery ========================================================== 11:41:52 (1776181312) [ 2970.121698] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2980.846778] LustreError: lustre-MDT0000-mdc-ffff977188904800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 2994.757573] Lustre: DEBUG MARKER: == replay-single test 33b: test fid seq allocation ======= 11:42:19 (1776181339) [ 2998.677988] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3009.560525] LustreError: lustre-MDT0000-mdc-ffff977188904800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 3025.385775] Lustre: DEBUG MARKER: == replay-single test 34: abort recovery before client does replay (test mds_cleanup_orphans) ========================================================== 11:42:49 (1776181369) [ 3029.213704] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3040.252791] Lustre: MGC192.168.204.105@tcp: Connection restored to 192.168.204.105@tcp (at 192.168.204.105@tcp) [ 3040.267767] Lustre: Skipped 24 previous similar messages [ 3040.341359] LustreError: lustre-MDT0000-mdc-ffff977188904800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 3051.518215] Lustre: DEBUG MARKER: == replay-single test 35: test recovery from llog for unlink op ========================================================== 11:43:16 (1776181396) [ 3065.866511] LustreError: lustre-MDT0000-mdc-ffff977188904800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 3081.055485] Lustre: DEBUG MARKER: == replay-single test 36: don't resend cancel ============ 11:43:45 (1776181425) [ 3086.150968] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3126.660859] Lustre: DEBUG MARKER: == replay-single test 37: abort recovery before client does replay (test mds_cleanup_orphans for directories) ========================================================== 11:44:31 (1776181471) [ 3131.164357] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3143.647695] Lustre: 2215:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776181482/real 1776181482] req@000000009553f00f x1862458041470016/t0(0) o400->MGC192.168.204.105@tcp@192.168.204.105@tcp:26/25 lens 224/224 e 0 to 1 dl 1776181489 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:1.0' [ 3143.689178] Lustre: 2215:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 26 previous similar messages [ 3145.711667] LustreError: lustre-MDT0000-mdc-ffff977188904800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 3159.792544] Lustre: DEBUG MARKER: == replay-single test 38: test recovery from unlink llog (test llog_gen_rec) ========================================================== 11:45:04 (1776181504) [ 3181.953277] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3223.909712] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3225.114665] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3242.217649] Lustre: DEBUG MARKER: == replay-single test 39: test recovery from unlink llog (test llog_gen_rec) ========================================================== 11:46:27 (1776181587) [ 3263.556918] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3281.887306] LustreError: 166-1: MGC192.168.204.105@tcp: Connection to MGS (at 192.168.204.105@tcp) was lost; in progress operations using this service will fail [ 3281.896465] LustreError: Skipped 12 previous similar messages [ 3298.279511] Lustre: Evicted from MGS (at 192.168.204.105@tcp) after server handle changed from 0x389fb0410f2e56d to 0x389fb0410f3ee78 [ 3298.287526] Lustre: Skipped 11 previous similar messages [ 3303.401606] Lustre: lustre-MDT0000-mdc-ffff977188904800: Connection to lustre-MDT0000 (at 192.168.204.105@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 3303.416431] Lustre: Skipped 13 previous similar messages [ 3314.309786] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3315.556989] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3333.165048] Lustre: DEBUG MARKER: == replay-single test 40: cause recovery in ptlrpc, ensure IO continues ========================================================== 11:47:57 (1776181677) [ 3334.510932] Lustre: DEBUG MARKER: SKIP: replay-single test_40 layout_lock needs MDS connection for IO [ 3335.787254] Lustre: DEBUG MARKER: == replay-single test 41: read from a valid osc while other oscs are invalid ========================================================== 11:48:00 (1776181680) [ 3343.185134] Lustre: DEBUG MARKER: == replay-single test 42: recovery after ost failure ===== 11:48:08 (1776181688) [ 3361.058734] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-OST0000 [ 3444.504181] Lustre: DEBUG MARKER: == replay-single test 43: mds osc import failure during recovery; don't LBUG ========================================================== 11:49:49 (1776181789) [ 3447.807529] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3487.267070] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3488.287500] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3508.319704] Lustre: DEBUG MARKER: == replay-single test 44a: race in target handle connect ========================================================== 11:50:52 (1776181852) [ 3593.905980] Lustre: DEBUG MARKER: == replay-single test 44b: race in target handle connect ========================================================== 11:52:18 (1776181938) [ 3602.951755] LustreError: 89182:0:(lmv_obd.c:1273:lmv_statfs()) lustre-MDT0000-mdc-ffff977188904800: can't stat MDS #0: rc = -114 [ 3604.357791] LustreError: 89202:0:(lmv_obd.c:1273:lmv_statfs()) lustre-MDT0000-mdc-ffff977188904800: can't stat MDS #0: rc = -114 [ 3606.093471] LustreError: 89221:0:(lmv_obd.c:1273:lmv_statfs()) lustre-MDT0000-mdc-ffff977188904800: can't stat MDS #0: rc = -114 [ 3609.088538] LustreError: 89259:0:(lmv_obd.c:1273:lmv_statfs()) lustre-MDT0000-mdc-ffff977188904800: can't stat MDS #0: rc = -114 [ 3609.093728] LustreError: 89259:0:(lmv_obd.c:1273:lmv_statfs()) Skipped 1 previous similar message [ 3613.149829] LustreError: 89317:0:(lmv_obd.c:1273:lmv_statfs()) lustre-MDT0000-mdc-ffff977188904800: can't stat MDS #0: rc = -114 [ 3613.158403] LustreError: 89317:0:(lmv_obd.c:1273:lmv_statfs()) Skipped 2 previous similar messages [ 3621.587339] Lustre: DEBUG MARKER: == replay-single test 44c: race in target handle connect ========================================================== 11:52:46 (1776181966) [ 3625.293705] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3638.291518] LustreError: lustre-MDT0000-mdc-ffff977188904800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 3673.060211] Lustre: MGC192.168.204.105@tcp: Connection restored to 192.168.204.105@tcp (at 192.168.204.105@tcp) [ 3673.071261] Lustre: Skipped 26 previous similar messages [ 3696.874207] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3698.867514] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3706.713104] Lustre: DEBUG MARKER: == replay-single test 45: Handle failed close ============ 11:54:11 (1776182051) [ 3706.944825] Lustre: setting import lustre-MDT0000_UUID INACTIVE by administrator request [ 3706.954866] LustreError: 91738:0:(file.c:246:ll_close_inode_openhandle()) lustre-clilmv-ffff977188904800: inode [0x20001b1b1:0x1:0x0] mdc close failed: rc = -108 [ 3706.995805] LustreError: lustre-MDT0000-mdc-ffff977188904800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 3713.150444] Lustre: DEBUG MARKER: == replay-single test 46: Don't leak file handle after open resend (3325) ========================================================== 11:54:18 (1776182058) [ 3755.930503] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3757.412567] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3765.044304] Lustre: DEBUG MARKER: == replay-single test 47: MDS->OSC failure during precreate cleanup (2824) ========================================================== 11:55:09 (1776182109) [ 3799.246779] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 3800.533123] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 3874.886515] Lustre: DEBUG MARKER: == replay-single test 48: MDS->OSC failure during precreate cleanup (2824) ========================================================== 11:56:59 (1776182219) [ 3880.207114] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3889.631292] Lustre: 2216:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776182228/real 1776182228] req@000000006998663d x1862458042531584/t0(0) o400->MGC192.168.204.105@tcp@192.168.204.105@tcp:26/25 lens 224/224 e 0 to 1 dl 1776182235 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:4.0' [ 3889.650462] Lustre: 2216:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 32 previous similar messages [ 3889.653975] LustreError: 166-1: MGC192.168.204.105@tcp: Connection to MGS (at 192.168.204.105@tcp) was lost; in progress operations using this service will fail [ 3889.664306] LustreError: Skipped 4 previous similar messages [ 3907.044573] Lustre: Evicted from MGS (at 192.168.204.105@tcp) after server handle changed from 0x389fb0410f56abd to 0x389fb0410f5783f [ 3907.052370] Lustre: Skipped 4 previous similar messages [ 3910.642150] Lustre: lustre-MDT0000-mdc-ffff977188904800: Connection to lustre-MDT0000 (at 192.168.204.105@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 3910.659032] Lustre: Skipped 20 previous similar messages [ 3910.772437] LustreError: 2214:0:(client.c:3161:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@00000000b1a1db87 x1862458042526528/t240518168679(240518168679) o101->lustre-MDT0000-mdc-ffff977188904800@192.168.204.105@tcp:12/10 lens 592/600 e 0 to 0 dl 1776182299 ref 2 fl Interpret:RQU/4/0 rc 301/301 job:'createmany.0' [ 3910.811789] LustreError: 2214:0:(client.c:3161:ptlrpc_replay_interpret()) Skipped 4 previous similar messages [ 3984.732372] Lustre: DEBUG MARKER: == replay-single test 50: Double OSC recovery, don't LASSERT (3812) ========================================================== 11:58:49 (1776182329) [ 3997.195582] Lustre: DEBUG MARKER: == replay-single test 52: time out lock replay (3764) ==== 11:59:01 (1776182341) [ 4073.128577] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4074.772754] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4083.424904] Lustre: DEBUG MARKER: == replay-single test 53a: |X| close request while two MDC requests in flight ========================================================== 12:00:27 (1776182427) [ 4089.673925] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4133.172808] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4134.760807] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4144.962757] Lustre: DEBUG MARKER: == replay-single test 53b: |X| open request while two MDC requests in flight ========================================================== 12:01:28 (1776182488) [ 4150.975445] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4189.896246] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4191.025878] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4197.364950] Lustre: DEBUG MARKER: == replay-single test 53c: |X| open request and close request while two MDC requests in flight ========================================================== 12:02:22 (1776182542) [ 4202.667563] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4242.117114] Lustre: DEBUG MARKER: == replay-single test 53d: close reply while two MDC requests in flight ========================================================== 12:03:05 (1776182585) [ 4274.538380] Lustre: MGC192.168.204.105@tcp: Connection restored to 192.168.204.105@tcp (at 192.168.204.105@tcp) [ 4274.544867] Lustre: Skipped 17 previous similar messages [ 4279.616076] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4280.843863] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4288.100336] Lustre: DEBUG MARKER: == replay-single test 53e: |X| open reply while two MDC requests in flight ========================================================== 12:03:52 (1776182632) [ 4294.008632] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4334.773941] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4336.933483] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4345.625849] Lustre: DEBUG MARKER: == replay-single test 53f: |X| open reply and close reply while two MDC requests in flight ========================================================== 12:04:50 (1776182690) [ 4353.382154] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4397.004386] Lustre: DEBUG MARKER: == replay-single test 53g: |X| drop open reply and close request while close and open are both in flight ========================================================== 12:05:41 (1776182741) [ 4405.443853] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4453.473523] Lustre: DEBUG MARKER: == replay-single test 53h: open request and close reply while two MDC requests in flight ========================================================== 12:06:38 (1776182798) [ 4461.876604] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4509.855440] Lustre: 2217:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776182814/real 1776182814] req@0000000076877eae x1862458042610688/t0(0) o400->lustre-MDT0000-mdc-ffff977188904800@192.168.204.105@tcp:12/10 lens 224/224 e 0 to 1 dl 1776182855 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:0.0' [ 4509.879423] Lustre: 2217:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 46 previous similar messages [ 4510.237833] Lustre: DEBUG MARKER: == replay-single test 55: let MDS_CHECK_RESENT return the original return code instead of 0 ========================================================== 12:07:35 (1776182855) [ 4552.672219] Lustre: lustre-MDT0000-mdc-ffff977188904800: Connection to lustre-MDT0000 (at 192.168.204.105@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 4552.681271] Lustre: Skipped 10 previous similar messages [ 4559.429419] Lustre: DEBUG MARKER: == replay-single test 56: don't replay a symlink open request (3440) ========================================================== 12:08:24 (1776182904) [ 4563.113091] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4574.111578] LustreError: 166-1: MGC192.168.204.105@tcp: Connection to MGS (at 192.168.204.105@tcp) was lost; in progress operations using this service will fail [ 4574.135068] LustreError: Skipped 9 previous similar messages [ 4591.597444] Lustre: Evicted from MGS (at 192.168.204.105@tcp) after server handle changed from 0x389fb0410f5b8dc to 0x389fb0410f5bddd [ 4591.603809] Lustre: Skipped 9 previous similar messages [ 4609.049855] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4610.609692] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4630.365580] Lustre: DEBUG MARKER: == replay-single test 57: test recovery from llog for setattr op ========================================================== 12:09:34 (1776182974) [ 4635.923559] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4674.789597] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4676.702737] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4696.364352] Lustre: DEBUG MARKER: == replay-single test 58a: test recovery from llog for setattr op (test llog_gen_rec) ========================================================== 12:10:40 (1776183040) [ 4743.985257] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4786.255367] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4788.201840] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4863.117402] Lustre: DEBUG MARKER: == replay-single test 58b: test replay of setxattr op ==== 12:13:27 (1776183207) [ 4863.714393] Lustre: Mounted lustre-client [ 4867.740480] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4887.528927] Lustre: MGC192.168.204.105@tcp: Connection restored to (at 192.168.204.105@tcp) [ 4887.533824] Lustre: Skipped 16 previous similar messages [ 4907.482161] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4909.109910] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4913.556760] Lustre: Unmounted lustre-client [ 4918.966657] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount FULL mgc.*.mgs_server_uuid [ 4920.814369] Lustre: DEBUG MARKER: mgc.*.mgs_server_uuid in FULL state after 0 sec [ 4927.422819] Lustre: DEBUG MARKER: == replay-single test 58c: resend/reconstruct setxattr op ========================================================== 12:14:32 (1776183272) [ 4933.009716] Lustre: Mounted lustre-client [ 5025.548483] Lustre: Unmounted lustre-client [ 5031.028987] Lustre: DEBUG MARKER: SKIP: replay-single test_59 skipping ALWAYS excluded test 59 [ 5032.417376] Lustre: DEBUG MARKER: == replay-single test 60: test llog post recovery init vs llog unlink ========================================================== 12:16:17 (1776183377) [ 5041.905195] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5076.615920] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 5078.301273] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5087.893536] Lustre: DEBUG MARKER: == replay-single test 61a: test race llog recovery vs llog cleanup ========================================================== 12:17:12 (1776183432) [ 5108.777626] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-OST0000 [ 5164.522411] LustreError: 11-0: lustre-OST0000-osc-ffff977188904800: operation ost_disconnect to node 192.168.204.105@tcp failed: rc = -107 [ 5191.697298] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 5193.348975] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 5233.339428] Lustre: DEBUG MARKER: == replay-single test 61b: test race mds llog sync vs llog cleanup ========================================================== 12:19:38 (1776183578) [ 5236.205852] Lustre: lustre-MDT0000-mdc-ffff977188904800: Connection to lustre-MDT0000 (at 192.168.204.105@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 5236.223741] Lustre: Skipped 9 previous similar messages [ 5248.479106] Lustre: 2218:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776183587/real 1776183587] req@0000000081db711e x1862458044507584/t0(0) o400->MGC192.168.204.105@tcp@192.168.204.105@tcp:26/25 lens 224/224 e 0 to 1 dl 1776183594 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:0.0' [ 5248.504438] Lustre: 2218:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 46 previous similar messages [ 5248.511528] LustreError: 166-1: MGC192.168.204.105@tcp: Connection to MGS (at 192.168.204.105@tcp) was lost; in progress operations using this service will fail [ 5248.523267] LustreError: Skipped 4 previous similar messages [ 5254.697203] Lustre: Evicted from MGS (at 192.168.204.105@tcp) after server handle changed from 0x389fb0410fa0804 to 0x389fb0410fb08e2 [ 5254.706463] Lustre: Skipped 4 previous similar messages [ 5322.303052] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 5323.786703] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5331.377487] Lustre: DEBUG MARKER: == replay-single test 61c: test race mds llog sync vs llog cleanup ========================================================== 12:21:16 (1776183676) [ 5377.185581] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 5379.015591] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 5387.111535] Lustre: DEBUG MARKER: == replay-single test 61d: error in llog_setup should cleanup the llog context correctly ========================================================== 12:22:11 (1776183731) [ 5411.848269] Lustre: DEBUG MARKER: == replay-single test 62: don't mis-drop resent replay === 12:22:36 (1776183756) [ 5414.782995] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5486.559287] LustreError: 2214:0:(client.c:3110:ptlrpc_replay_interpret()) @@@ request replay timed out req@00000000596448f6 x1862458044521728/t317827579908(317827579908) o101->lustre-MDT0000-mdc-ffff977188904800@192.168.204.105@tcp:12/10 lens 592/656 e 0 to 1 dl 1776183832 ref 2 fl Interpret:EXQU/4/ffffffff rc -110/-1 job:'createmany.0' [ 5486.661157] LustreError: 2214:0:(client.c:3161:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@00000000596448f6 x1862458044521728/t317827579908(317827579908) o101->lustre-MDT0000-mdc-ffff977188904800@192.168.204.105@tcp:12/10 lens 592/600 e 0 to 0 dl 1776183873 ref 2 fl Interpret:RQU/4/0 rc 301/301 job:'createmany.0' [ 5486.685405] LustreError: 2214:0:(client.c:3161:ptlrpc_replay_interpret()) Skipped 19 previous similar messages [ 5492.663816] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 5493.906866] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5501.807335] Lustre: DEBUG MARKER: == replay-single test 65a: AT: verify early replies ====== 12:24:06 (1776183846) [ 5555.006447] Lustre: DEBUG MARKER: == replay-single test 65b: AT: verify early replies on packed reply / bulk ========================================================== 12:24:59 (1776183899) [ 5598.919664] Lustre: DEBUG MARKER: == replay-single test 66a: AT: verify MDT service time adjusts with no early replies ========================================================== 12:25:43 (1776183943) [ 5663.434847] Lustre: DEBUG MARKER: == replay-single test 66b: AT: verify net latency adjusts ========================================================== 12:26:47 (1776184007) [ 5690.464745] LustreError: 128172:0:(fail.c:138:__cfs_fail_timeout_set()) cfs_fail_timeout id 50c sleeping for 6000ms [ 5696.519169] LustreError: 128172:0:(fail.c:149:__cfs_fail_timeout_set()) cfs_fail_timeout id 50c awake [ 5696.547162] LustreError: 128172:0:(fail.c:138:__cfs_fail_timeout_set()) cfs_fail_timeout id 50c sleeping for 6000ms [ 5702.607145] LustreError: 128172:0:(fail.c:149:__cfs_fail_timeout_set()) cfs_fail_timeout id 50c awake [ 5702.627125] LustreError: 2216:0:(fail.c:138:__cfs_fail_timeout_set()) cfs_fail_timeout id 50c sleeping for 6000ms [ 5708.720580] LustreError: 2216:0:(fail.c:149:__cfs_fail_timeout_set()) cfs_fail_timeout id 50c awake [ 5708.744872] LustreError: 128172:0:(fail.c:138:__cfs_fail_timeout_set()) cfs_fail_timeout id 50c sleeping for 6000ms [ 5714.815873] LustreError: 128172:0:(fail.c:149:__cfs_fail_timeout_set()) cfs_fail_timeout id 50c awake [ 5722.460032] Lustre: DEBUG MARKER: == replay-single test 67a: AT: verify slow request processing doesn't induce reconnects ========================================================== 12:27:46 (1776184066) [ 5782.230273] Lustre: DEBUG MARKER: == replay-single test 67b: AT: verify instant slowdown doesn't induce reconnects ========================================================== 12:28:47 (1776184127) [ 5814.256905] Lustre: DEBUG MARKER: phase 2 [ 5821.853211] Lustre: DEBUG MARKER: == replay-single test 68: AT: verify slowing locks ======= 12:29:26 (1776184166) [ 5852.076483] LustreError: 13185:0:(fail.c:138:__cfs_fail_timeout_set()) cfs_fail_timeout id 312 sleeping for 19000ms [ 5871.127123] LustreError: 13185:0:(fail.c:149:__cfs_fail_timeout_set()) cfs_fail_timeout id 312 awake [ 5871.227063] LustreError: 112655:0:(fail.c:138:__cfs_fail_timeout_set()) cfs_fail_timeout id 312 sleeping for 25000ms [ 5896.311156] LustreError: 112655:0:(fail.c:149:__cfs_fail_timeout_set()) cfs_fail_timeout id 312 awake [ 5902.709248] Lustre: DEBUG MARKER: == replay-single test 70a: check multi client t-f ======== 12:30:47 (1776184247) [ 5903.785489] Lustre: DEBUG MARKER: SKIP: replay-single test_70a Need two or more clients, have 1 [ 5905.014417] Lustre: DEBUG MARKER: == replay-single test 70b: dbench 1mdts recovery; 1 clients ========================================================== 12:30:50 (1776184250) [ 5907.724793] Lustre: DEBUG MARKER: Started rundbench load pid=131417 ... [ 5912.945638] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5915.483839] Lustre: DEBUG MARKER: test_70b fail mds1 1 times [ 5917.206636] LustreError: 11-0: lustre-MDT0000-mdc-ffff977188904800: operation mds_reint to node 192.168.204.105@tcp failed: rc = -19 [ 5917.213562] Lustre: lustre-MDT0000-mdc-ffff977188904800: Connection to lustre-MDT0000 (at 192.168.204.105@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 5917.222176] Lustre: Skipped 4 previous similar messages [ 5928.416936] Lustre: 2218:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776184267/real 1776184267] req@00000000134ed395 x1862458044693760/t0(0) o400->MGC192.168.204.105@tcp@192.168.204.105@tcp:26/25 lens 224/224 e 0 to 1 dl 1776184274 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:1.0' [ 5928.444908] Lustre: 2218:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 11 previous similar messages [ 5928.454158] LustreError: 166-1: MGC192.168.204.105@tcp: Connection to MGS (at 192.168.204.105@tcp) was lost; in progress operations using this service will fail [ 5928.467744] LustreError: Skipped 3 previous similar messages [ 5934.627640] Lustre: Evicted from MGS (at 192.168.204.105@tcp) after server handle changed from 0x389fb0410fb1a38 to 0x389fb0410fb6e9a [ 5934.650841] Lustre: Skipped 3 previous similar messages [ 5934.660144] Lustre: MGC192.168.204.105@tcp: Connection restored to 192.168.204.105@tcp (at 192.168.204.105@tcp) [ 5934.672177] Lustre: Skipped 14 previous similar messages [ 5958.697119] LustreError: 2214:0:(client.c:3161:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@000000009173c756 x1862458044612928/t322122547590(322122547590) o101->lustre-MDT0000-mdc-ffff977188904800@192.168.204.105@tcp:12/10 lens 576/600 e 0 to 0 dl 1776184311 ref 2 fl Interpret:RPQU/4/0 rc 301/301 job:'dbench.0' [ 5958.726978] LustreError: 2214:0:(client.c:3161:ptlrpc_replay_interpret()) Skipped 24 previous similar messages [ 5964.822283] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 5966.359849] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5973.738060] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5976.501479] Lustre: DEBUG MARKER: test_70b fail mds1 2 times [ 5979.057846] LustreError: 11-0: lustre-MDT0000-mdc-ffff977188904800: operation ldlm_enqueue to node 192.168.204.105@tcp failed: rc = -19 [ 6018.088510] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 6019.575703] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6027.172066] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 6029.725139] Lustre: DEBUG MARKER: test_70b fail mds1 3 times [ 6031.512926] LustreError: 11-0: lustre-MDT0000-mdc-ffff977188904800: operation mds_reint to node 192.168.204.105@tcp failed: rc = -19 [ 6069.209929] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 6070.444737] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6076.932300] Lustre: DEBUG MARKER: == replay-single test 70c: tar 1mdts recovery ============ 12:33:41 (1776184421) [ 6202.306288] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 6213.830813] Lustre: DEBUG MARKER: test_70c fail mds1 1 times [ 6215.987865] LustreError: 11-0: lustre-MDT0000-mdc-ffff977188904800: operation mds_reint to node 192.168.204.105@tcp failed: rc = -19 [ 6245.408716] LustreError: 2214:0:(client.c:3161:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@00000000b6c7f9e2 x1862458046706816/t335007456135(335007456135) o101->lustre-MDT0000-mdc-ffff977188904800@192.168.204.105@tcp:12/10 lens 584/600 e 0 to 0 dl 1776184598 ref 2 fl Interpret:RQU/4/0 rc 301/301 job:'tar.0' [ 6245.430835] LustreError: 2214:0:(client.c:3161:ptlrpc_replay_interpret()) Skipped 93 previous similar messages [ 6256.775243] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 6258.183824] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6299.765377] Lustre: DEBUG MARKER: == replay-single test 70d: mkdir/rmdir striped dir 1mdts recovery ========================================================== 12:37:24 (1776184644) [ 6301.099438] Lustre: DEBUG MARKER: SKIP: replay-single test_70d needs >= 2 MDTs [ 6302.528722] Lustre: DEBUG MARKER: == replay-single test 70e: rename cross-MDT with random fails ========================================================== 12:37:27 (1776184647) [ 6303.900192] Lustre: DEBUG MARKER: SKIP: replay-single test_70e needs >= 2 MDTs [ 6305.187509] Lustre: DEBUG MARKER: == replay-single test 70f: OSS O_DIRECT recovery with 1 clients ========================================================== 12:37:30 (1776184650) [ 6311.775655] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-OST0000 [ 6314.129471] Lustre: DEBUG MARKER: test_70f failing OST 1 times [ 6348.093296] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 6349.951307] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 6362.287749] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-OST0000 [ 6364.958413] Lustre: DEBUG MARKER: test_70f failing OST 2 times [ 6400.065116] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 6402.150373] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 6413.109397] Lustre: DEBUG MARKER: == replay-single test 71a: mkdir/rmdir striped dir with 2 mdts recovery ========================================================== 12:39:17 (1776184757) [ 6415.035606] Lustre: DEBUG MARKER: SKIP: replay-single test_71a needs >= 2 MDTs [ 6416.772936] Lustre: DEBUG MARKER: == replay-single test 73a: open(O_CREAT), unlink, replay, reconnect before open replay, close ========================================================== 12:39:21 (1776184761) [ 6421.441779] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 6459.359246] LustreError: 2214:0:(client.c:3110:ptlrpc_replay_interpret()) @@@ request replay timed out req@00000000bc3522ec x1862458047599424/t339302419126(339302419126) o101->lustre-MDT0000-mdc-ffff977188904800@192.168.204.105@tcp:12/10 lens 592/656 e 0 to 1 dl 1776184805 ref 2 fl Interpret:EXPQU/4/ffffffff rc -110/-1 job:'multiop.0' [ 6467.901204] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 6470.411484] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6482.738272] Lustre: DEBUG MARKER: == replay-single test 73b: open(O_CREAT), unlink, replay, reconnect at open_replay reply, close ========================================================== 12:40:26 (1776184826) [ 6487.692794] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 6524.895985] LustreError: 2214:0:(client.c:3110:ptlrpc_replay_interpret()) @@@ request replay timed out req@00000000e15cfdab x1862458047605248/t343597383683(343597383683) o101->lustre-MDT0000-mdc-ffff977188904800@192.168.204.105@tcp:12/10 lens 592/656 e 0 to 1 dl 1776184870 ref 2 fl Interpret:EXPQU/4/ffffffff rc -110/-1 job:'multiop.0' [ 6531.565673] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 6532.997945] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6541.663382] Lustre: DEBUG MARKER: == replay-single test 74: Ensure applications don't fail waiting for OST recovery ========================================================== 12:41:26 (1776184886) [ 6544.439546] Lustre: Unmounted lustre-client [ 6585.230396] Lustre: Mounted lustre-client [ 6590.478613] LustreError: 11-0: lustre-OST0000-osc-ffff97719002a800: operation ost_connect to node 192.168.204.105@tcp failed: rc = -16 [ 6608.121441] Lustre: DEBUG MARKER: == replay-single test 80a: DNE: create remote dir, drop update rep from MDT0, fail MDT0 ========================================================== 12:42:32 (1776184952) [ 6609.903119] Lustre: DEBUG MARKER: SKIP: replay-single test_80a needs >= 2 MDTs [ 6611.843920] Lustre: DEBUG MARKER: == replay-single test 80b: DNE: create remote dir, drop update rep from MDT0, fail MDT1 ========================================================== 12:42:36 (1776184956) [ 6613.769787] Lustre: DEBUG MARKER: SKIP: replay-single test_80b needs >= 2 MDTs [ 6615.900075] Lustre: DEBUG MARKER: == replay-single test 80c: DNE: create remote dir, drop update rep from MDT1, fail MDT[0,1] ========================================================== 12:42:40 (1776184960) [ 6617.780795] Lustre: DEBUG MARKER: SKIP: replay-single test_80c needs >= 2 MDTs [ 6619.705130] Lustre: DEBUG MARKER: == replay-single test 80d: DNE: create remote dir, drop update rep from MDT1, fail 2 MDTs ========================================================== 12:42:44 (1776184964) [ 6621.338939] Lustre: DEBUG MARKER: SKIP: replay-single test_80d needs >= 2 MDTs [ 6623.263478] Lustre: DEBUG MARKER: == replay-single test 80e: DNE: create remote dir, drop MDT1 rep, fail MDT0 ========================================================== 12:42:47 (1776184967) [ 6624.780429] Lustre: DEBUG MARKER: SKIP: replay-single test_80e needs >= 2 MDTs [ 6626.578996] Lustre: DEBUG MARKER: == replay-single test 80f: DNE: create remote dir, drop MDT1 rep, fail MDT1 ========================================================== 12:42:51 (1776184971) [ 6628.145876] Lustre: DEBUG MARKER: SKIP: replay-single test_80f needs >= 2 MDTs [ 6629.749160] Lustre: DEBUG MARKER: == replay-single test 80g: DNE: create remote dir, drop MDT1 rep, fail MDT0, then MDT1 ========================================================== 12:42:54 (1776184974) [ 6631.272569] Lustre: DEBUG MARKER: SKIP: replay-single test_80g needs >= 2 MDTs [ 6633.378508] Lustre: DEBUG MARKER: == replay-single test 80h: DNE: create remote dir, drop MDT1 rep, fail 2 MDTs ========================================================== 12:42:57 (1776184977) [ 6634.809725] Lustre: DEBUG MARKER: SKIP: replay-single test_80h needs >= 2 MDTs [ 6636.835607] Lustre: DEBUG MARKER: == replay-single test 81a: DNE: unlink remote dir, drop MDT0 update rep, fail MDT1 ========================================================== 12:43:01 (1776184981) [ 6638.480839] Lustre: DEBUG MARKER: SKIP: replay-single test_81a needs >= 2 MDTs [ 6640.670741] Lustre: DEBUG MARKER: == replay-single test 81b: DNE: unlink remote dir, drop MDT0 update reply, fail MDT0 ========================================================== 12:43:04 (1776184984) [ 6642.490560] Lustre: DEBUG MARKER: SKIP: replay-single test_81b needs >= 2 MDTs [ 6644.380444] Lustre: DEBUG MARKER: == replay-single test 81c: DNE: unlink remote dir, drop MDT0 update reply, fail MDT0,MDT1 ========================================================== 12:43:08 (1776184988) [ 6646.123644] Lustre: DEBUG MARKER: SKIP: replay-single test_81c needs >= 2 MDTs [ 6648.297268] Lustre: DEBUG MARKER: == replay-single test 81d: DNE: unlink remote dir, drop MDT0 update reply, fail 2 MDTs ========================================================== 12:43:12 (1776184992) [ 6650.373411] Lustre: DEBUG MARKER: SKIP: replay-single test_81d needs >= 2 MDTs [ 6652.610648] Lustre: DEBUG MARKER: == replay-single test 81e: DNE: unlink remote dir, drop MDT1 req reply, fail MDT0 ========================================================== 12:43:16 (1776184996) [ 6654.479636] Lustre: DEBUG MARKER: SKIP: replay-single test_81e needs >= 2 MDTs [ 6657.254895] Lustre: DEBUG MARKER: == replay-single test 81f: DNE: unlink remote dir, drop MDT1 req reply, fail MDT1 ========================================================== 12:43:21 (1776185001) [ 6660.469372] Lustre: DEBUG MARKER: SKIP: replay-single test_81f needs >= 2 MDTs [ 6663.871215] Lustre: DEBUG MARKER: == replay-single test 81g: DNE: unlink remote dir, drop req reply, fail M0, then M1 ========================================================== 12:43:26 (1776185006) [ 6665.799229] Lustre: DEBUG MARKER: SKIP: replay-single test_81g needs >= 2 MDTs [ 6668.018887] Lustre: DEBUG MARKER: == replay-single test 81h: DNE: unlink remote dir, drop request reply, fail 2 MDTs ========================================================== 12:43:32 (1776185012) [ 6671.010592] Lustre: DEBUG MARKER: SKIP: replay-single test_81h needs >= 2 MDTs [ 6674.084850] Lustre: DEBUG MARKER: == replay-single test 84a: stale open during export disconnect ========================================================== 12:43:37 (1776185017) [ 6677.486677] Lustre: lustre-MDT0000-mdc-ffff97719002a800: Connection to lustre-MDT0000 (at 192.168.204.105@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 6677.510650] Lustre: Skipped 8 previous similar messages [ 6677.543755] LustreError: lustre-MDT0000-mdc-ffff97719002a800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 6677.603500] Lustre: lustre-MDT0000-mdc-ffff97719002a800: Connection restored to 192.168.204.105@tcp (at 192.168.204.105@tcp) [ 6677.645141] Lustre: Skipped 13 previous similar messages [ 6686.375254] Lustre: DEBUG MARKER: == replay-single test 85a: check the cancellation of unused locks during recovery(IBITS) ========================================================== 12:43:50 (1776185030) [ 6704.096070] Lustre: 2216:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776185043/real 1776185043] req@000000004b18f493 x1862458047674944/t0(0) o400->lustre-MDT0000-mdc-ffff97719002a800@192.168.204.105@tcp:12/10 lens 224/224 e 0 to 1 dl 1776185050 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:3.0' [ 6704.125723] Lustre: 2216:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 15 previous similar messages [ 6704.138727] LustreError: 166-1: MGC192.168.204.105@tcp: Connection to MGS (at 192.168.204.105@tcp) was lost; in progress operations using this service will fail [ 6704.149972] LustreError: Skipped 5 previous similar messages [ 6721.513986] Lustre: Evicted from MGS (at 192.168.204.105@tcp) after server handle changed from 0x389fb04110151a7 to 0x389fb0411017254 [ 6721.531046] Lustre: Skipped 5 previous similar messages [ 6737.948978] LustreError: 2214:0:(client.c:3161:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@0000000065f0cb1f x1862458047619200/t352187318281(352187318281) o101->lustre-MDT0000-mdc-ffff97719002a800@192.168.204.105@tcp:12/10 lens 576/600 e 0 to 0 dl 1776185090 ref 2 fl Interpret:RPQU/4/0 rc 301/301 job:'grep.0' [ 6737.967968] LustreError: 2214:0:(client.c:3161:ptlrpc_replay_interpret()) Skipped 125 previous similar messages [ 6744.672771] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 6746.214901] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6754.926247] Lustre: DEBUG MARKER: == replay-single test 85b: check the cancellation of unused locks during recovery(EXTENT) ========================================================== 12:44:59 (1776185099) [ 6808.696616] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 6810.331402] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 6819.539501] Lustre: DEBUG MARKER: == replay-single test 86: umount server after clear nid_stats should not hit LBUG ========================================================== 12:46:04 (1776185164) [ 6822.059400] Lustre: Unmounted lustre-client [ 6837.722698] Lustre: Mounted lustre-client [ 6844.432792] Lustre: DEBUG MARKER: == replay-single test 87a: write replay ================== 12:46:28 (1776185188) [ 6850.111839] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-OST0000 [ 6884.993939] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 6886.858921] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 6896.717750] Lustre: DEBUG MARKER: == replay-single test 87b: write replay with changed data (checksum resend) ========================================================== 12:47:21 (1776185241) [ 6901.907234] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-OST0000 [ 6941.819619] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 6943.259892] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 6951.450823] Lustre: DEBUG MARKER: == replay-single test 88: MDS should not assign same objid to different files ========================================================== 12:48:15 (1776185295) [ 6955.783364] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-OST0000 [ 6959.415975] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 7044.332506] Lustre: DEBUG MARKER: == replay-single test 89: no disk space leak on late ost connection ========================================================== 12:49:49 (1776185389) [ 7104.606099] Lustre: Unmounted lustre-client [ 7119.126855] LustreError: 11-0: lustre-OST0000-osc-ffff977187cab800: operation ost_connect to node 192.168.204.105@tcp failed: rc = -16 [ 7119.143475] LustreError: Skipped 1 previous similar message [ 7119.146288] Lustre: Mounted lustre-client [ 7139.842357] LustreError: 11-0: lustre-OST0000-osc-ffff977187cab800: operation ost_connect to node 192.168.204.105@tcp failed: rc = -16 [ 7139.849388] LustreError: Skipped 3 previous similar messages [ 7175.685617] LustreError: 11-0: lustre-OST0000-osc-ffff977187cab800: operation ost_connect to node 192.168.204.105@tcp failed: rc = -16 [ 7175.700841] LustreError: Skipped 6 previous similar messages [ 7188.873941] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 59 sec [ 7204.135556] Lustre: DEBUG MARKER: free_before: 7518208 free_after: 7518208 [ 7210.689322] Lustre: DEBUG MARKER: == replay-single test 90: lfs find identifies the missing striped file segments ========================================================== 12:52:35 (1776185555) [ 7247.081923] Lustre: DEBUG MARKER: == replay-single test 93a: replay + reconnect ============ 12:53:11 (1776185591) [ 7307.231264] Lustre: 2214:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776185646/real 1776185646] req@00000000923ccb56 x1862458047909696/t0(0) o400->lustre-OST0000-osc-ffff977187cab800@192.168.204.105@tcp:28/4 lens 224/224 e 0 to 1 dl 1776185653 ref 1 fl Rpc:XQr/c0/ffffffff rc 0/-1 job:'ptlrpcd_rcv.0' [ 7307.250938] Lustre: 2214:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 12 previous similar messages [ 7319.604550] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 7321.636349] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 7331.016543] Lustre: DEBUG MARKER: == replay-single test 93b: replay + reconnect on mds ===== 12:54:35 (1776185675) [ 7345.567190] LustreError: 166-1: MGC192.168.204.105@tcp: Connection to MGS (at 192.168.204.105@tcp) was lost; in progress operations using this service will fail [ 7345.586083] LustreError: Skipped 2 previous similar messages [ 7345.588829] Lustre: lustre-MDT0000-mdc-ffff977187cab800: Connection to lustre-MDT0000 (at 192.168.204.105@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 7345.594745] Lustre: Skipped 10 previous similar messages [ 7363.070725] Lustre: Evicted from MGS (at 192.168.204.105@tcp) after server handle changed from 0x389fb041101d0aa to 0x389fb041101db46 [ 7363.090065] Lustre: Skipped 2 previous similar messages [ 7363.099517] Lustre: MGC192.168.204.105@tcp: Connection restored to 192.168.204.105@tcp (at 192.168.204.105@tcp) [ 7363.114625] Lustre: Skipped 9 previous similar messages [ 7450.904151] Lustre: DEBUG MARKER: oleg405-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 7452.447906] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7461.585755] Lustre: DEBUG MARKER: == replay-single test complete, duration 7218 sec ======== 12:56:46 (1776185806) [ 7471.020037] Lustre: Unmounted lustre-client [ 7495.921481] Key type lgssc unregistered [ 7496.251613] LNet: 165297:0:(lib-ptl.c:992:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 7497.320311] LNet: Removed LNI 192.168.204.5@tcp [ 7498.050275] Key type .llcrypt unregistered [ 7498.053082] Key type ._llcrypt unregistered