[ 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.16.2-1.fc38 04/01/2014 [ 0.000000] Hypervisor detected: KVM [ 0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00 [ 0.000000] kvm-clock: using sched offset of 465119618 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 0x000f5b50-0x000f5b5f] [ 0.000000] RAMDISK: [mem 0xbcc64000-0xbffcffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F5970 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE1BB7 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE1A53 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 001A13 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE1AC7 000090 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE1B57 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE1B8F 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe1a53-0xbffe1ac6] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe1a52] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe1ac7-0xbffe1b56] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe1b57-0xbffe1b8e] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe1b8f-0xbffe1bb6] [ 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 2528MB for crashkernel (System RAM: 4205MB) [ 0.000000] Zone ranges: [ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.000000] DMA32 [mem 0x0000000001000000-0x00000000ffffffff] [ 0.000000] Normal [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Device empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff] [ 0.000000] node 0: [mem 0x0000000000100000-0x00000000bffd9fff] [ 0.000000] node 0: [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Zeroed struct page in unavailable ranges: 4744 pages [ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x0000000146dfffff] [ 0.000000] ACPI: PM-Timer IO Port: 0x608 [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) [ 0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) [ 0.000000] Using ACPI (MADT) for SMP configuration information [ 0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000] TSC deadline timer available [ 0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs [ 0.000000] kvm-guest: KVM setup pv remote TLB flush [ 0.000000] kvm-guest: setup PV sched yield [ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff] [ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff] [ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff] [ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff] [ 0.000000] PM: Registered nosave memory: [mem 0xbffda000-0xbfffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xc0000000-0xfeffbfff] [ 0.000000] PM: Registered nosave memory: [mem 0xfeffc000-0xfeffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xff000000-0xfffbffff] [ 0.000000] PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff] [ 0.000000] [mem 0xc0000000-0xfeffbfff] available for PCI devices [ 0.000000] Booting paravirtualized kernel on KVM [ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns [ 0.000000] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1 [ 0.000000] percpu: Embedded 63 pages/cpu s221184 r8192 d28672 u524288 [ 0.000000] kvm-guest: PV spinlocks enabled [ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1059618 [ 0.000000] Policy zone: Normal [ 0.000000] Kernel command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] Specific versions of hardware are certified with Red Hat Enterprise Linux 8. Please see the list of hardware certified with Red Hat Enterprise Linux 8 at https://catalog.redhat.com. [ 0.000000] audit: disabled (until reboot) [ 0.000000] software IO TLB: area num 4. [ 0.000000] Memory: 2829700K/4306400K available (18435K kernel code, 11221K rwdata, 7248K rodata, 2908K init, 18040K bss, 524580K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] ftrace: allocating 41240 entries in 162 pages [ 0.000000] ftrace: allocated 162 pages with 3 groups [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] rcu: RCU event tracing is enabled. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ 0.000000] rcu: RCU callback double-/use-after-free debug enabled. [ 0.000000] Rude variant of Tasks RCU enabled. [ 0.000000] Tracing variant of Tasks RCU enabled. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 0.000000] NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16 [ 0.000000] random: get_random_bytes called from start_kernel+0x622/0x9a8 with crng_init=0 [ 0.001000] Console: colour *CGA 80x25 [ 0.001000] printk: console [ttyS1] enabled [ 0.001000] ACPI: Core revision 20220331 [ 0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.001012] APIC: Switch to symmetric I/O mode setup [ 0.002535] x2apic enabled [ 0.003015] Switched APIC routing to physical x2apic. [ 0.004019] kvm-guest: setup PV IPIs [ 0.006691] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.007000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.007032] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.009007] pid_max: default: 32768 minimum: 301 [ 0.011183] LSM: Security Framework initializing [ 0.012105] Yama: becoming mindful. [ 0.013061] SELinux: Initializing. [ 0.014086] *** VALIDATE selinux *** [ 0.022858] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.026894] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.028202] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.029155] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.031127] *** VALIDATE tmpfs *** [ 0.033195] *** VALIDATE proc *** [ 0.035054] *** VALIDATE cgroup *** [ 0.036014] *** VALIDATE cgroup2 *** [ 0.038086] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.039198] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.040016] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.041043] Spectre V2 : User space: Vulnerable [ 0.042009] Speculative Store Bypass: Vulnerable [ 0.046179] debug: unmapping init [mem 0xffffffff88859000-0xffffffff88860fff] [ 0.048217] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.049787] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.050031] ... version: 2 [ 0.051017] ... bit width: 48 [ 0.052014] ... generic registers: 4 [ 0.053020] ... value mask: 0000ffffffffffff [ 0.054021] ... max period: 00007fffffffffff [ 0.055017] ... fixed-purpose events: 3 [ 0.056018] ... event mask: 000000070000000f [ 0.058316] rcu: Hierarchical SRCU implementation. [ 0.060788] smp: Bringing up secondary CPUs ... [ 0.061643] x86: Booting SMP configuration: [ 0.062029] .... node #0, CPUs: #1 #2 #3 [ 0.066124] smp: Brought up 1 node, 4 CPUs [ 0.068022] smpboot: Max logical packages: 1 [ 0.069028] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.234937] node 0 deferred pages initialised in 161ms [ 0.238151] devtmpfs: initialized [ 0.239267] x86/mm: Memory block size: 128MB [ 0.241771] gcov: version magic: 0x41383552 [ 0.244435] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.245104] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.246335] pinctrl core: initialized pinctrl subsystem [ 0.247297] [ 0.247696] ************************************************************* [ 0.248018] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.249017] ** ** [ 0.250017] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.251019] ** ** [ 0.252020] ** This means that this kernel is built to expose internal ** [ 0.253017] ** IOMMU data structures, which may compromise security on ** [ 0.254019] ** your system. ** [ 0.255024] ** ** [ 0.256020] ** If you see this message and you are not debugging the ** [ 0.257028] ** kernel, report this immediately to your vendor! ** [ 0.258016] ** ** [ 0.259017] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.260023] ************************************************************* [ 0.262000] NET: Registered protocol family 16 [ 0.263537] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.267091] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.273096] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.278153] cpuidle: using governor menu [ 0.281834] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.285714] PCI: Using configuration type 1 for base access [ 0.291150] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.300072] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.302071] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.308048] cryptd: max_cpu_qlen set to 1000 [ 0.312471] ACPI: Added _OSI(Module Device) [ 0.314022] ACPI: Added _OSI(Processor Device) [ 0.315021] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.317031] ACPI: Added _OSI(Processor Aggregator Device) [ 0.321928] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.329470] ACPI: Interpreter enabled [ 0.332104] ACPI: PM: (supports S0 S3 S4 S5) [ 0.335023] ACPI: Using IOAPIC for interrupt routing [ 0.337180] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.340439] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.351021] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.355069] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.358030] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.361107] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.367000] acpiphp: Slot [2] registered [ 0.368205] acpiphp: Slot [3] registered [ 0.370127] acpiphp: Slot [4] registered [ 0.372124] acpiphp: Slot [5] registered [ 0.373236] acpiphp: Slot [6] registered [ 0.375195] acpiphp: Slot [7] registered [ 0.376131] acpiphp: Slot [8] registered [ 0.377083] acpiphp: Slot [9] registered [ 0.378071] acpiphp: Slot [10] registered [ 0.380151] acpiphp: Slot [11] registered [ 0.381206] acpiphp: Slot [12] registered [ 0.383124] acpiphp: Slot [13] registered [ 0.384102] acpiphp: Slot [14] registered [ 0.386096] acpiphp: Slot [15] registered [ 0.387085] acpiphp: Slot [16] registered [ 0.388127] acpiphp: Slot [17] registered [ 0.389114] acpiphp: Slot [18] registered [ 0.391150] acpiphp: Slot [19] registered [ 0.392128] acpiphp: Slot [20] registered [ 0.394135] acpiphp: Slot [21] registered [ 0.395183] acpiphp: Slot [22] registered [ 0.397134] acpiphp: Slot [23] registered [ 0.399174] acpiphp: Slot [24] registered [ 0.400096] acpiphp: Slot [25] registered [ 0.401115] acpiphp: Slot [26] registered [ 0.403150] acpiphp: Slot [27] registered [ 0.405149] acpiphp: Slot [28] registered [ 0.406153] acpiphp: Slot [29] registered [ 0.408098] acpiphp: Slot [30] registered [ 0.409129] acpiphp: Slot [31] registered [ 0.411077] PCI host bridge to bus 0000:00 [ 0.413029] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.415031] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.417037] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.420036] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.423035] pci_bus 0000:00: root bus resource [mem 0x180000000-0x1ffffffff window] [ 0.426035] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.430225] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.435555] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.440079] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.446000] pci 0000:00:01.1: reg 0x20: [io 0xc120-0xc12f] [ 0.450064] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.453029] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.456027] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.458023] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.460603] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.463725] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.466056] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.469708] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.473016] pci 0000:00:02.0: reg 0x10: [io 0xc100-0xc11f] [ 0.482023] pci 0000:00:02.0: reg 0x20: [mem 0xfebf4000-0xfebf7fff 64bit pref] [ 0.486026] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.491765] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.497021] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.502025] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.512022] pci 0000:00:05.0: reg 0x20: [mem 0xfebf8000-0xfebfbfff 64bit pref] [ 0.519290] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.527020] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.534022] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.547030] pci 0000:00:06.0: reg 0x20: [mem 0xfebfc000-0xfebfffff 64bit pref] [ 0.557000] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.560408] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.563377] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.565402] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.568238] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.573294] iommu: Default domain type: Passthrough [ 0.575446] SCSI subsystem initialized [ 0.576000] ACPI: bus type USB registered [ 0.576000] usbcore: registered new interface driver usbfs [ 0.576000] usbcore: registered new interface driver hub [ 0.579119] usbcore: registered new device driver usb [ 0.581243] pps_core: LinuxPPS API ver. 1 registered [ 0.583015] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.586078] PTP clock support registered [ 0.587336] EDAC MC: Ver: 3.0.0 [ 0.589163] PCI: Using ACPI for IRQ routing [ 0.590784] NetLabel: Initializing [ 0.592016] NetLabel: domain hash size = 128 [ 0.594015] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.596138] NetLabel: unlabeled traffic allowed by default [ 0.597116] vgaarb: loaded [ 0.598315] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.600018] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.605053] clocksource: Switched to clocksource kvm-clock [ 0.712697] VFS: Disk quotas dquot_6.6.0 [ 0.713984] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.716165] *** VALIDATE ramfs *** [ 0.717493] *** VALIDATE hugetlbfs *** [ 0.719061] pnp: PnP ACPI init [ 0.721621] pnp: PnP ACPI: found 6 devices [ 0.740528] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.743883] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.746044] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.748407] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.751028] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.753229] pci_bus 0000:00: resource 8 [mem 0x180000000-0x1ffffffff window] [ 0.756230] NET: Registered protocol family 2 [ 0.758876] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.763826] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.767350] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.772529] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.775846] TCP: Hash tables configured (established 65536 bind 65536) [ 0.778813] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.782209] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.785276] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.788342] NET: Registered protocol family 1 [ 0.790465] RPC: Registered named UNIX socket transport module. [ 0.792869] RPC: Registered udp transport module. [ 0.794542] RPC: Registered tcp transport module. [ 0.795963] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.798282] NET: Registered protocol family 44 [ 0.800064] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.803809] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.805848] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.807635] PCI: CLS 0 bytes, default 64 [ 0.809976] Unpacking initramfs... [ 2.248938] debug: unmapping init [mem 0xffff974ffcc64000-0xffff974ffffcffff] [ 2.254801] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.256981] software IO TLB: mapped [mem 0x00000000b8c64000-0x00000000bcc64000] (64MB) [ 2.260540] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 2.749831] Initialise system trusted keyrings [ 2.751785] Key type blacklist registered [ 2.754065] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.764574] zbud: loaded [ 2.768441] *** VALIDATE nfs *** [ 2.769805] *** VALIDATE nfs4 *** [ 2.771376] pstore: using deflate compression [ 2.774472] Platform Keyring initialized [ 2.889567] NET: Registered protocol family 38 [ 2.891173] Key type asymmetric registered [ 2.892936] Asymmetric key parser 'x509' registered [ 2.894987] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 2.897590] io scheduler mq-deadline registered [ 2.899772] io scheduler kyber registered [ 2.901723] io scheduler bfq registered [ 2.903751] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 2.907161] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 2.910142] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 2.913138] ACPI: Power Button [PWRF] [ 3.007191] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 3.101360] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 3.203464] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 3.238977] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.271198] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.276233] Non-volatile memory driver v1.3 [ 3.278214] Linux agpgart interface v0.103 [ 3.313131] virtio_blk virtio1: [vda] 133848 512-byte logical blocks (68.5 MB/65.4 MiB) [ 3.316096] vda: detected capacity change from 0 to 68530176 [ 3.337866] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.340931] vdb: detected capacity change from 0 to 1073741824 [ 3.347805] libphy: Fixed MDIO Bus: probed [ 3.357167] usbcore: registered new interface driver usbserial_generic [ 3.359594] usbserial: USB Serial support registered for generic [ 3.361864] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.366367] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.368275] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.371259] mousedev: PS/2 mouse device common for all mice [ 3.373995] rtc_cmos 00:05: RTC can wake from S4 [ 3.377206] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.377398] rtc_cmos 00:05: registered as rtc0 [ 3.382214] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.383665] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.387758] intel_pstate: CPU model not supported [ 3.392419] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.395786] hid: raw HID events driver (C) Jiri Kosina [ 3.397897] usbcore: registered new interface driver usbhid [ 3.399951] usbhid: USB HID core driver [ 3.401711] drop_monitor: Initializing network drop monitor service [ 3.404307] Initializing XFRM netlink socket [ 3.406169] NET: Registered protocol family 10 [ 3.412860] Segment Routing with IPv6 [ 3.414575] NET: Registered protocol family 17 [ 3.416963] mpls_gso: MPLS GSO support [ 3.423852] RAS: Correctable Errors collector initialized. [ 3.426134] AVX version of gcm_enc/dec engaged. [ 3.427802] AES CTR mode by8 optimization enabled [ 3.528270] sched_clock: Marking stable (3528227467, 0)->(4451796210, -923568743) [ 3.532652] registered taskstats version 1 [ 3.536966] Loading compiled-in X.509 certificates [ 3.539302] zswap: loaded using pool lzo/zbud [ 3.569523] Key type big_key registered [ 3.582809] Key type encrypted registered [ 3.584230] ima: No TPM chip found, activating TPM-bypass! [ 3.586308] ima: Allocated hash algorithm: sha1 [ 3.587978] ima: No architecture policies found [ 3.589980] evm: Initialising EVM extended attributes: [ 3.591603] evm: security.selinux [ 3.592666] evm: security.ima [ 3.594154] evm: security.capability [ 3.595414] evm: HMAC attrs: 0x1 [ 3.597763] rtc_cmos 00:05: setting system clock to 2025-11-17 01:40:55 UTC (1763343655) [ 3.604680] debug: unmapping init [mem 0xffffffff89803000-0xffffffff899fffff] [ 3.607750] debug: unmapping init [mem 0xffffffff88582000-0xffffffff88858fff] [ 3.613387] Write protecting the kernel read-only data: 28672k [ 3.616770] debug: unmapping init [mem 0xffffffff86c03000-0xffffffff86dfffff] [ 3.619317] debug: unmapping init [mem 0xffffffff87514000-0xffffffff875fffff] [ 3.658859] 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.667370] systemd[1]: Detected virtualization kvm. [ 3.669562] systemd[1]: Detected architecture x86-64. [ 3.671173] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.704672] systemd[1]: No hostname configured. [ 3.706424] systemd[1]: Set hostname to . [ 3.708258] random: systemd: uninitialized urandom read (16 bytes read) [ 3.710250] systemd[1]: Initializing machine ID from random generator. [ 3.867222] random: systemd: uninitialized urandom read (16 bytes read) [ 3.870594] systemd[1]: Listening on udev Control Socket. [ OK ] Listening on udev Control Socket. [ 3.874773] random: systemd: uninitialized urandom read (16 bytes read) [ 3.877910] systemd[1]: Listening on Journal Socket. [ OK ] Listening on Journal Socket. [ 3.886980] systemd[1]: Starting Create list of required static device nodes for the current kernel... Starting Create list of required st…ce nodes for the current kernel... [ OK ] Reached target Local File Systems. Starting Create Volatile Files and Directories... [ OK ] Reached target Slices. [ OK ] Reached target Timers. [ OK ] Reached target Initrd Root Device. [ OK ] Reached target Swap. [ OK ] Listening on Journal Socket (/dev/log). Starting Journal Service... [ OK ] Listening on udev Kernel Socket. [ OK ] Reached target Sockets. Starting Setup Virtual Console... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Paths. Starting Apply Kernel Variables... [ OK ] Started Memstrack Anylazing Service. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Setup Virtual Console. [ OK ] Started Apply Kernel Variables. Starting dracut cmdline hook... Starting Create Static Device Nodes in /dev... [ OK ] Started Journal Service. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 4.516501] device-mapper: uevent: version 1.0.3 [ 4.518683] device-mapper: ioctl: 4.46.0-ioctl (2022-02-22) initialised: dm-devel@redhat.com [ OK ] Started dracut pre-udev hook. Starting udev Kernel Device Manager... [ OK ] Started udev Kernel Device Manager. Starting dracut pre-trigger hook... [ OK ] Started dracut pre-trigger hook. Starting udev Coldplug all Devices... Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. Starting dracut initqueue hook... [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ 5.262846] virtio_net virtio0 ens2: renamed from eth0 [ 5.321335] scsi host0: ata_piix [ 5.333511] scsi host1: ata_piix [ 5.335247] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc120 irq 14 [ 5.337729] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc128 irq 15 [ 9.727135] dracut-initqueue[586]: RTNETLINK answers: File exists[ 9.729776] random: fast init done [ 10.100153] random: crng init done [ 10.101605] random: 7 urandom warning(s) missed due to ratelimiting Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Mounting /sysroot... [ 10.546861] 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... Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped target Timers. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Slices. [ OK ] Stopped target Sockets. [ OK ] Stopped target Paths. [ OK ] Stopped target System Initialization. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped target Swap. [ OK ] Stopped target Local File Systems. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. Stopping udev Kernel Device Manager... [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Closed udev Kernel Socket. [ OK ] Closed udev Control Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 11.723461] printk: systemd: 24 output lines suppressed due to ratelimiting [ 12.001072] SELinux: Disabled at runtime. [ 12.061043] 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.070658] systemd[1]: Detected virtualization kvm. [ 12.072683] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 12.663563] systemd[1]: initrd-switch-root.service: Succeeded. [ 12.666879] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 12.679203] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 12.683797] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 12.687301] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 12.694779] systemd[1]: Starting Journal Service... Starting Journal Service... [ 12.699226] systemd[1]: Started Dispatch Password Requests to Console Directory Watch. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Reached target Paths. Starting Remount Root and Kernel File Systems... Activating swap /dev/disk/by-label/SWAP... [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Created slice system-sshd\x2dkeygen.slice. Starting Apply Kernel Variables... [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd Root Fi[ 12.749731] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS le System. [ OK ] Stopped target Initrd File Systems. [ OK ] Created slice system-serial\x2dgetty.slice. [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 RPC Port Mapper. [ OK ] Created slice User and Session Slice. [ OK ] Reached target Slices. Mounting POSIX Message Queue File System... Mounting Huge Pages File System... [ OK ] Reached target Local Encrypted Volumes. [ OK ] Listening on udev Kernel Socket. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Created slice system-getty.slice. Mounting Kernel Debug File System... [ OK ] Listening on Process Core Dump Socket. [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Listening on udev Control Socket. Starting udev Coldplug all Devices... [ OK ] Reached target rpc_pipefs.target. [ OK ] Started Journal Service. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Started Apply Kernel Variables. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Mounted Huge Pages File System. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Mounted Kernel Debug File System. [ OK ] Reached target Swap. Starting Create Static Device Nodes in /dev... Starting Configure read-only root support... Starting Flush Journal to Persistent Storage... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Reached target Local File Systems (Pre). Mounting /home/green/git/lustre-release... Mounting /mnt... Starting udev Kernel Device Manager... [ OK ] Mounted /mnt. [ 13.064313] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Coldplug all Devices. [ OK ] Started udev Kernel Device Manager. [ 13.412896] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 13.439271] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 13.556697] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 13.575416] EDAC sbridge: Ver: 1.1.2 [ 14.704295] Key type dns_resolver registered [ 15.018150] NFS: Registering the id_resolver key type [ 15.020103] Key type id_resolver registered [ 15.021906] Key type id_legacy registered [ OK ] Started Configure read-only root support. [ 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... Starting Load/Save Random Seed... [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Load/Save Random Seed. [ OK ] Started Create Volatile Files and Directories. Starting RPC Bind... Starting Update UTMP about System Boot/Shutdown... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Started dnf makecache --timer. [ OK ] Reached target Timers. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Reached target sshd-keygen.target. Starting Restore /run/initramfs on shutdown... [ OK ] Started irqbalance daemon. [ OK ] Started D-Bus System Message Bus. Starting Login Service... Starting Network Manager... [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Login Service. [ OK ] Started Network Manager. Starting Network Manager Wait Online... [ OK ] Reached target Network. Starting Dynamic System Tuning Daemon... Starting OpenSSH server daemon... Starting GSSAPI Proxy Daemon... Starting Hostname Service... [ OK ] Started OpenSSH server daemon. [ 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 Permit User Sessions. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Command Scheduler. [ OK ] Started Serial Getty on ttyS1. [ OK ] Started Getty on tty1. [ OK ] Reached target Login Prompts. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting Crash recovery kernel arming... Starting Notify NFS peers of a restart... Starting System Logging Service... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. 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 oleg435-client login: [ 54.022813] libcfs: loading out-of-tree module taints kernel. [ 54.065949] Key type ._llcrypt registered [ 54.090351] Key type .llcrypt registered [ 54.693425] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [ 54.702981] alg: No test for adler32 (adler32-zlib) [ 55.934539] Lustre: Lustre: Build Version: 2.16.61_46_gcd0e473 [ 56.470199] LNet: Added LNI 192.168.204.35@tcp [8/256/0/180] [ 58.183175] Key type lgssc registered [ 59.873083] Lustre: Echo OBD driver; http://www.lustre.org/ [ 131.332021] hrtimer: interrupt took 1491710 ns [ 167.926673] Lustre: Mounted lustre-client [ 172.255249] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 186.580163] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing check_logdir /tmp/testlogs/ [ 190.347292] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing yml_node [ 193.506363] Lustre: lustre-OST0000-osc-ffff975044c09800: disconnect after 24s idle [ 194.984543] Lustre: DEBUG MARKER: Client: 2.16.61.46 [ 197.193225] Lustre: DEBUG MARKER: MDS: 2.16.61.46 [ 199.259834] Lustre: DEBUG MARKER: OSS: 2.16.61.46 [ 200.577575] Lustre: DEBUG MARKER: -----============= acceptance-small: replay-single ============----- Sun Nov 16 20:44:11 EST 2025 [ 213.362980] Lustre: DEBUG MARKER: excepting tests: 59 36 [ 214.518381] Lustre: DEBUG MARKER: === replay-single: start setup 20:44:25 (1763343865) === [ 216.837398] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing check_config_client /mnt/lustre [ 228.411437] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 236.399157] Lustre: DEBUG MARKER: === replay-single: finish setup 20:44:47 (1763343887) === [ 238.111797] Lustre: DEBUG MARKER: == replay-single test 0a: empty replay =================== 20:44:48 (1763343888) [ 241.185243] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 260.063969] Lustre: lustre-OST0000-osc-ffff975044c09800: disconnect after 21s idle [ 260.069226] Lustre: Skipped 1 previous similar message [ 260.069990] Lustre: lustre-MDT0000-mdc-ffff975044c09800: Connection to lustre-MDT0000 (at 192.168.204.135@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 260.089868] LustreError: MGC192.168.204.135@tcp: Connection to MGS (at 192.168.204.135@tcp) was lost; in progress operations using this service will fail [ 260.102394] Lustre: Evicted from MGS (at 192.168.204.135@tcp) after server handle changed from 0x8285adaf8966c874 to 0x8285adaf8966cb68 [ 260.113192] Lustre: MGC192.168.204.135@tcp: Connection restored to 192.168.204.135@tcp (at 192.168.204.135@tcp) [ 261.088071] Lustre: 2362:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763343896/real 1763343896] req@ffff9750586a8000 x1848999891973120/t0(0) o400->lustre-MDT0000-mdc-ffff975044c09800@192.168.204.135@tcp:12/10 lens 224/224 e 0 to 1 dl 1763343912 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 266.017357] Lustre: 2364:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763343901/real 1763343901] req@ffff975049ae9880 x1848999891973632/t0(0) o400->lustre-MDT0000-mdc-ffff975044c09800@192.168.204.135@tcp:12/10 lens 224/224 e 0 to 1 dl 1763343917 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 266.657026] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 267.958539] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 270.305104] Lustre: 2365:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763343906/real 1763343906] req@ffff975049aeaa00 x1848999891974144/t0(0) o400->lustre-MDT0000-mdc-ffff975044c09800@192.168.204.135@tcp:12/10 lens 224/224 e 0 to 1 dl 1763343922 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 274.540695] Lustre: DEBUG MARKER: == replay-single test 0b: ensure object created after recover exists. (3284) ========================================================== 20:45:25 (1763343925) [ 280.548787] Lustre: lustre-OST0000-osc-ffff975044c09800: Connection to lustre-OST0000 (at 192.168.204.135@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 290.783288] Lustre: lustre-OST0001-osc-ffff975044c09800: disconnect after 21s idle [ 290.789311] Lustre: Skipped 1 previous similar message [ 293.480990] Lustre: lustre-OST0000-osc-ffff975044c09800: Connection restored to 192.168.204.135@tcp (at 192.168.204.135@tcp) [ 293.494096] Lustre: Skipped 1 previous similar message [ 302.134825] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 303.327323] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 310.435906] Lustre: DEBUG MARKER: == replay-single test 0c: check replay-barrier =========== 20:46:01 (1763343961) [ 313.272586] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 313.350426] LustreError: 12700:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff975044c09800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 313.363544] LustreError: 12700:0:(obd_class.h:479:obd_check_dev()) Device 5 not setup [ 313.398055] Lustre: Unmounted lustre-client [ 337.425629] LustreError: lustre-MDT0000-mdc-ffff975049936000: operation mds_connect to node 192.168.204.135@tcp failed: rc = -16 [ 342.522926] LustreError: lustre-MDT0000-mdc-ffff975049936000: operation mds_connect to node 192.168.204.135@tcp failed: rc = -16 [ 347.645880] LustreError: lustre-MDT0000-mdc-ffff975049936000: operation mds_connect to node 192.168.204.135@tcp failed: rc = -16 [ 352.761083] LustreError: lustre-MDT0000-mdc-ffff975049936000: operation mds_connect to node 192.168.204.135@tcp failed: rc = -16 [ 357.887804] LustreError: lustre-MDT0000-mdc-ffff975049936000: operation mds_connect to node 192.168.204.135@tcp failed: rc = -16 [ 368.125571] LustreError: lustre-MDT0000-mdc-ffff975049936000: operation mds_connect to node 192.168.204.135@tcp failed: rc = -16 [ 368.130215] LustreError: Skipped 1 previous similar message [ 388.634956] LustreError: lustre-MDT0000-mdc-ffff975049936000: operation mds_connect to node 192.168.204.135@tcp failed: rc = -16 [ 388.660149] LustreError: Skipped 3 previous similar messages [ 398.978402] Lustre: Mounted lustre-client [ 408.247148] Lustre: DEBUG MARKER: == replay-single test 0d: expired recovery with no clients ========================================================== 20:47:38 (1763344058) [ 411.856869] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 411.914564] LustreError: 13690:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff975049936000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 411.930812] LustreError: 13690:0:(lov_obd.c:783:lov_cleanup()) Skipped 1 previous similar message [ 411.943953] LustreError: 13690:0:(obd_class.h:479:obd_check_dev()) Device 5 not setup [ 411.948083] LustreError: 13690:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 411.990665] Lustre: Unmounted lustre-client [ 437.466557] LustreError: lustre-MDT0000-mdc-ffff975049931000: operation mds_connect to node 192.168.204.135@tcp failed: rc = -16 [ 437.472318] LustreError: Skipped 1 previous similar message [ 499.287518] Lustre: Mounted lustre-client [ 507.623725] Lustre: DEBUG MARKER: == replay-single test 1: simple create =================== 20:49:18 (1763344158) [ 511.803214] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 529.898416] LustreError: MGC192.168.204.135@tcp: Connection to MGS (at 192.168.204.135@tcp) was lost; in progress operations using this service will fail [ 529.911933] Lustre: lustre-MDT0000-mdc-ffff975049931000: Connection to lustre-MDT0000 (at 192.168.204.135@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 529.918716] Lustre: Evicted from MGS (at 192.168.204.135@tcp) after server handle changed from 0x8285adaf8966da56 to 0x8285adaf8966dd4a [ 529.944210] Lustre: MGC192.168.204.135@tcp: Connection restored to 192.168.204.135@tcp (at 192.168.204.135@tcp) [ 530.980176] Lustre: 2363:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763344166/real 1763344166] req@ffff97504974bb80 x1848999892026880/t0(0) o400->lustre-MDT0000-mdc-ffff975049931000@192.168.204.135@tcp:12/10 lens 224/224 e 0 to 1 dl 1763344182 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 536.032030] Lustre: 2362:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763344171/real 1763344171] req@ffff97504974b100 x1848999892027392/t0(0) o400->lustre-MDT0000-mdc-ffff975049931000@192.168.204.135@tcp:12/10 lens 224/224 e 0 to 1 dl 1763344187 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 539.729920] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 540.841560] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 547.634470] Lustre: DEBUG MARKER: == replay-single test 2a: touch ========================== 20:49:58 (1763344198) [ 550.440842] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 570.854362] Lustre: lustre-MDT0000-mdc-ffff975049931000: Connection to lustre-MDT0000 (at 192.168.204.135@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 570.887445] LustreError: MGC192.168.204.135@tcp: Connection to MGS (at 192.168.204.135@tcp) was lost; in progress operations using this service will fail [ 570.912987] Lustre: Evicted from MGS (at 192.168.204.135@tcp) after server handle changed from 0x8285adaf8966dd4a to 0x8285adaf8966e2de [ 570.925890] Lustre: MGC192.168.204.135@tcp: Connection restored to 192.168.204.135@tcp (at 192.168.204.135@tcp) [ 570.938546] Lustre: Skipped 1 previous similar message [ 570.956230] LustreError: 2361:0:(client.c:3418:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff975049749f80 x1848999892035456/t21474836484(21474836484) o101->lustre-MDT0000-mdc-ffff975049931000@192.168.204.135@tcp:12/10 lens 592/608 e 0 to 0 dl 1763344238 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'touch.0' uid:0 gid:0 projid:0 [ 571.873677] Lustre: 2364:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763344207/real 1763344207] req@ffff975049925f80 x1848999892036480/t0(0) o400->lustre-MDT0000-mdc-ffff975049931000@192.168.204.135@tcp:12/10 lens 224/224 e 0 to 1 dl 1763344223 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 571.903750] Lustre: 2364:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 579.430373] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 580.847771] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 587.848704] Lustre: DEBUG MARKER: == replay-single test 2b: touch ========================== 20:50:38 (1763344238) [ 591.004672] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 611.827955] Lustre: lustre-MDT0000-mdc-ffff975049931000: Connection to lustre-MDT0000 (at 192.168.204.135@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 611.844900] LustreError: MGC192.168.204.135@tcp: Connection to MGS (at 192.168.204.135@tcp) was lost; in progress operations using this service will fail [ 611.855094] Lustre: Evicted from MGS (at 192.168.204.135@tcp) after server handle changed from 0x8285adaf8966e2de to 0x8285adaf8966e792 [ 611.868434] Lustre: MGC192.168.204.135@tcp: Connection restored to 192.168.204.135@tcp (at 192.168.204.135@tcp) [ 611.875656] Lustre: Skipped 1 previous similar message [ 611.897430] LustreError: 2361:0:(client.c:3418:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff975049926a00 x1848999892045056/t25769803781(25769803781) o101->lustre-MDT0000-mdc-ffff975049931000@192.168.204.135@tcp:12/10 lens 592/608 e 0 to 0 dl 1763344279 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'touch.0' uid:0 gid:0 projid:0 [ 612.832454] Lustre: 2362:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763344248/real 1763344248] req@ffff97504978fb80 x1848999892046336/t0(0) o400->lustre-MDT0000-mdc-ffff975049931000@192.168.204.135@tcp:12/10 lens 224/224 e 0 to 1 dl 1763344264 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 612.888162] Lustre: 2362:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 621.880876] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 623.978944] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 632.196659] Lustre: DEBUG MARKER: == replay-single test 2c: setstripe replay =============== 20:51:22 (1763344282) [ 635.601794] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 653.791224] Lustre: 2365:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763344289/real 1763344289] req@ffff975049aea300 x1848999892056192/t0(0) o400->MGC192.168.204.135@tcp@192.168.204.135@tcp:26/25 lens 224/224 e 0 to 1 dl 1763344305 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 653.818794] Lustre: 2365:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 653.824365] LustreError: MGC192.168.204.135@tcp: Connection to MGS (at 192.168.204.135@tcp) was lost; in progress operations using this service will fail [ 653.837516] Lustre: lustre-MDT0000-mdc-ffff975049931000: Connection to lustre-MDT0000 (at 192.168.204.135@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 653.841705] Lustre: Evicted from MGS (at 192.168.204.135@tcp) after server handle changed from 0x8285adaf8966e792 to 0x8285adaf8966ebb3 [ 653.861903] Lustre: MGC192.168.204.135@tcp: Connection restored to 192.168.204.135@tcp (at 192.168.204.135@tcp) [ 653.866389] Lustre: Skipped 1 previous similar message [ 653.911794] LustreError: 2361:0:(client.c:3418:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff97504978e300 x1848999892055040/t30064771076(30064771076) o101->lustre-MDT0000-mdc-ffff975049931000@192.168.204.135@tcp:12/10 lens 536/608 e 0 to 0 dl 1763344321 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'lfs.0' uid:0 gid:0 projid:0 [ 661.241737] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 662.411872] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 670.302628] Lustre: DEBUG MARKER: == replay-single test 2d: setdirstripe replay ============ 20:52:00 (1763344320) [ 674.564628] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 694.759654] LustreError: MGC192.168.204.135@tcp: Connection to MGS (at 192.168.204.135@tcp) was lost; in progress operations using this service will fail [ 694.762885] Lustre: lustre-MDT0000-mdc-ffff975049931000: Connection to lustre-MDT0000 (at 192.168.204.135@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 694.773973] Lustre: Evicted from MGS (at 192.168.204.135@tcp) after server handle changed from 0x8285adaf8966ebb3 to 0x8285adaf8966f01a [ 694.804063] Lustre: MGC192.168.204.135@tcp: Connection restored to 192.168.204.135@tcp (at 192.168.204.135@tcp) [ 694.811539] Lustre: Skipped 1 previous similar message [ 702.668329] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 703.975086] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 712.139442] Lustre: DEBUG MARKER: == replay-single test 2e: O_CREAT|O_EXCL create replay === 20:52:42 (1763344362) [ 717.266782] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 735.711253] Lustre: 21534:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763344365/real 1763344365] req@ffff975049aea680 x1848999892071936/t0(0) o35->lustre-MDT0000-mdc-ffff975049931000@192.168.204.135@tcp:23/10 lens 392/624 e 0 to 1 dl 1763344387 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'openfile.0' uid:0 gid:0 projid:0 [ 735.714240] LustreError: MGC192.168.204.135@tcp: Connection to MGS (at 192.168.204.135@tcp) was lost; in progress operations using this service will fail [ 735.742570] Lustre: 21534:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 7 previous similar messages [ 735.742627] Lustre: lustre-MDT0000-mdc-ffff975049931000: Connection to lustre-MDT0000 (at 192.168.204.135@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 735.766387] Lustre: Evicted from MGS (at 192.168.204.135@tcp) after server handle changed from 0x8285adaf8966f01a to 0x8285adaf8966f4d5 [ 735.773287] Lustre: MGC192.168.204.135@tcp: Connection restored to 192.168.204.135@tcp (at 192.168.204.135@tcp) [ 735.780572] Lustre: Skipped 1 previous similar message [ 742.269572] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 743.679310] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 750.561641] Lustre: DEBUG MARKER: == replay-single test 3a: replay failed open(O_DIRECTORY) ========================================================== 20:53:21 (1763344401) [ 753.549745] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 772.577017] LustreError: MGC192.168.204.135@tcp: Connection to MGS (at 192.168.204.135@tcp) was lost; in progress operations using this service will fail [ 772.597585] Lustre: Evicted from MGS (at 192.168.204.135@tcp) after server handle changed from 0x8285adaf8966f4d5 to 0x8285adaf8966f801 [ 783.352704] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 784.792518] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 793.709409] Lustre: DEBUG MARKER: == replay-single test 3b: replay failed open -ENOMEM ===== 20:54:04 (1763344444) [ 798.087896] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 818.678645] Lustre: lustre-MDT0000-mdc-ffff975049931000: Connection to lustre-MDT0000 (at 192.168.204.135@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 818.701367] Lustre: Skipped 1 previous similar message [ 818.708779] Lustre: MGC192.168.204.135@tcp: Connection restored to 192.168.204.135@tcp (at 192.168.204.135@tcp) [ 818.720612] Lustre: Skipped 3 previous similar messages [ 828.564181] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 829.844990] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 837.264480] Lustre: DEBUG MARKER: == replay-single test 3c: replay failed open -ENOMEM ===== 20:54:47 (1763344487) [ 840.565967] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 859.628714] LustreError: MGC192.168.204.135@tcp: Connection to MGS (at 192.168.204.135@tcp) was lost; in progress operations using this service will fail [ 859.640241] LustreError: Skipped 1 previous similar message [ 859.650582] Lustre: Evicted from MGS (at 192.168.204.135@tcp) after server handle changed from 0x8285adaf8966fd02 to 0x8285adaf8967013f [ 859.655262] Lustre: Skipped 1 previous similar message [ 865.567314] Lustre: 2364:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763344501/real 1763344501] req@ffff975049ae8380 x1848999892100736/t0(0) o400->lustre-MDT0000-mdc-ffff975049931000@192.168.204.135@tcp:12/10 lens 224/224 e 0 to 1 dl 1763344517 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 865.588812] Lustre: 2364:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 12 previous similar messages [ 868.539969] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 870.091916] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 877.919522] Lustre: DEBUG MARKER: == replay-single test 4a: |x| 10 open(O_CREAT)s ========== 20:55:28 (1763344528) [ 881.531042] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 900.683737] LustreError: 2361:0:(client.c:3418:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff97504978e300 x1848999892108288/t55834574851(55834574851) o101->lustre-MDT0000-mdc-ffff975049931000@192.168.204.135@tcp:12/10 lens 592/608 e 0 to 0 dl 1763344568 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'bash.0' uid:0 gid:0 projid:0 [ 908.719053] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 910.084022] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 918.004207] Lustre: DEBUG MARKER: == replay-single test 4b: |x| rm 10 files ================ 20:56:08 (1763344568) [ 921.363911] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 947.175949] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 948.404248] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 954.854870] Lustre: DEBUG MARKER: == replay-single test 5: |x| 220 open(O_CREAT) =========== 20:56:45 (1763344605) [ 958.987150] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 987.622268] Lustre: lustre-MDT0000-mdc-ffff975049931000: Connection to lustre-MDT0000 (at 192.168.204.135@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 987.632060] Lustre: Skipped 3 previous similar messages [ 987.635043] LustreError: MGC192.168.204.135@tcp: Connection to MGS (at 192.168.204.135@tcp) was lost; in progress operations using this service will fail [ 987.648089] LustreError: Skipped 2 previous similar messages [ 987.663511] Lustre: Evicted from MGS (at 192.168.204.135@tcp) after server handle changed from 0x8285adaf89671295 to 0x8285adaf8967478c [ 987.668294] Lustre: Skipped 2 previous similar messages [ 987.672920] Lustre: MGC192.168.204.135@tcp: Connection restored to 192.168.204.135@tcp (at 192.168.204.135@tcp) [ 987.679697] LustreError: 2361:0:(client.c:3418:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff97504978ea00 x1848999892153600/t64424509443(64424509443) o101->lustre-MDT0000-mdc-ffff975049931000@192.168.204.135@tcp:12/10 lens 592/608 e 0 to 0 dl 1763344655 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'bash.0' uid:0 gid:0 projid:0 [ 987.685772] Lustre: Skipped 7 previous similar messages [ 987.697900] LustreError: 2361:0:(client.c:3418:ptlrpc_replay_interpret()) Skipped 9 previous similar messages [ 995.200660] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 996.727894] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1019.277688] Lustre: DEBUG MARKER: == replay-single test 6a: mkdir + contained create ======= 20:57:49 (1763344669) [ 1023.131990] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1054.034599] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1055.478838] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1065.790811] Lustre: DEBUG MARKER: == replay-single test 6b: |X| rmdir ====================== 20:58:36 (1763344716) [ 1069.177495] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1099.870362] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1101.360187] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1108.486674] Lustre: DEBUG MARKER: == replay-single test 7: mkdir |X| contained create ====== 20:59:19 (1763344759) [ 1111.656318] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1131.999297] Lustre: 2365:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763344767/real 1763344767] req@ffff975049749c00 x1848999892634880/t0(0) o400->lustre-MDT0000-mdc-ffff975049931000@192.168.204.135@tcp:12/10 lens 224/224 e 0 to 1 dl 1763344783 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1132.027814] Lustre: 2365:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 16 previous similar messages [ 1139.944496] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1141.407237] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1148.409410] Lustre: DEBUG MARKER: == replay-single test 8: creat open |X| close ============ 20:59:59 (1763344799) [ 1151.697031] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1172.008231] LustreError: 2361:0:(client.c:3418:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff975046447b80 x1848999892645376/t81604378634(81604378634) o101->lustre-MDT0000-mdc-ffff975049931000@192.168.204.135@tcp:12/10 lens 664/608 e 0 to 0 dl 1763344839 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'multiop.0' uid:0 gid:0 projid:0 [ 1172.019298] LustreError: 2361:0:(client.c:3418:ptlrpc_replay_interpret()) Skipped 219 previous similar messages [ 1182.801761] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1184.694900] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1193.179378] Lustre: DEBUG MARKER: == replay-single test 9: |X| create (same inum/gen) ====== 21:00:43 (1763344843) [ 1196.695829] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1228.863836] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1230.877579] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1239.314095] Lustre: DEBUG MARKER: == replay-single test 10: create |X| rename unlink ======= 21:01:29 (1763344889) [ 1242.617489] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1264.104593] Lustre: lustre-MDT0000-mdc-ffff975049931000: Connection to lustre-MDT0000 (at 192.168.204.135@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1264.116737] Lustre: Skipped 5 previous similar messages [ 1264.122870] LustreError: MGC192.168.204.135@tcp: Connection to MGS (at 192.168.204.135@tcp) was lost; in progress operations using this service will fail [ 1264.128199] LustreError: Skipped 5 previous similar messages [ 1264.151092] Lustre: Evicted from MGS (at 192.168.204.135@tcp) after server handle changed from 0x8285adaf8967bec4 to 0x8285adaf8967c394 [ 1264.156436] Lustre: Skipped 5 previous similar messages [ 1264.161412] Lustre: MGC192.168.204.135@tcp: Connection restored to 192.168.204.135@tcp (at 192.168.204.135@tcp) [ 1264.165478] Lustre: Skipped 11 previous similar messages [ 1271.149469] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1272.655572] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1279.613585] Lustre: DEBUG MARKER: == replay-single test 11: create open write rename |X| create-old-name read ========================================================== 21:02:10 (1763344930) [ 1282.549954] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1301.849465] LustreError: 2361:0:(client.c:3418:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff975046441c00 x1848999892676096/t94489280522(94489280522) o101->lustre-MDT0000-mdc-ffff975049931000@192.168.204.135@tcp:12/10 lens 592/608 e 0 to 0 dl 1763344969 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'bash.0' uid:0 gid:0 projid:0 [ 1369.785551] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1371.632869] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1379.800938] Lustre: DEBUG MARKER: == replay-single test 12: open, unlink |X| close ========= 21:03:50 (1763345030) [ 1382.992686] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1404.787600] LustreError: 2361:0:(client.c:3418:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff975046443480 x1848999892676864/t94489280524(94489280524) o101->lustre-MDT0000-mdc-ffff975049931000@192.168.204.135@tcp:12/10 lens 576/608 e 0 to 0 dl 1763345072 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'grep.0' uid:0 gid:0 projid:0 [ 1404.802676] LustreError: 2361:0:(client.c:3418:ptlrpc_replay_interpret()) Skipped 1 previous similar message [ 1412.391213] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1413.946269] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1421.819357] Lustre: DEBUG MARKER: == replay-single test 13: open chmod 0 |x| write close === 21:04:32 (1763345072) [ 1425.840187] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1457.413340] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1458.565809] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1465.575811] Lustre: DEBUG MARKER: == replay-single test 14: open(O_CREAT), unlink |X| close ========================================================== 21:05:16 (1763345116) [ 1469.167963] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1490.198723] LustreError: 2361:0:(client.c:3418:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff975046443480 x1848999892676864/t94489280524(94489280524) o101->lustre-MDT0000-mdc-ffff975049931000@192.168.204.135@tcp:12/10 lens 576/608 e 0 to 0 dl 1763345158 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'grep.0' uid:0 gid:0 projid:0 [ 1490.231847] LustreError: 2361:0:(client.c:3418:ptlrpc_replay_interpret()) Skipped 3 previous similar messages [ 1499.411727] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1500.796664] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1507.486960] Lustre: DEBUG MARKER: == replay-single test 15: open(O_CREAT), unlink |X| touch new, close ========================================================== 21:05:58 (1763345158) [ 1511.107957] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1538.702341] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1540.283460] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1548.234388] Lustre: DEBUG MARKER: == replay-single test 16: |X| open(O_CREAT), unlink, touch new, unlink new ========================================================== 21:06:38 (1763345198) [ 1551.416656] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1578.187103] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1579.699559] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1587.653386] Lustre: DEBUG MARKER: == replay-single test 17: |X| open(O_CREAT), |replay| close ========================================================== 21:07:18 (1763345238) [ 1590.976762] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1618.789684] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1620.027866] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1626.862973] Lustre: DEBUG MARKER: == replay-single test 18: open(O_CREAT), unlink, touch new, close, touch, unlink ========================================================== 21:07:57 (1763345277) [ 1629.868799] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1651.270218] LustreError: 2361:0:(client.c:3418:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff975046443480 x1848999892676864/t94489280524(94489280524) o101->lustre-MDT0000-mdc-ffff975049931000@192.168.204.135@tcp:12/10 lens 576/608 e 0 to 0 dl 1763345319 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'grep.0' uid:0 gid:0 projid:0 [ 1651.295731] LustreError: 2361:0:(client.c:3418:ptlrpc_replay_interpret()) Skipped 7 previous similar messages [ 1657.105530] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1658.387256] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1664.188976] Lustre: DEBUG MARKER: == replay-single test 19: mcreate, open, write, rename === 21:08:35 (1763345315) [ 1666.852127] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1688.032923] Lustre: 2362:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763345323/real 1763345323] req@ffff975046441180 x1848999892768768/t0(0) o400->lustre-MDT0000-mdc-ffff975049931000@192.168.204.135@tcp:12/10 lens 224/224 e 0 to 1 dl 1763345339 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1688.057903] Lustre: 2362:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 37 previous similar messages [ 1696.280391] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1697.852133] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1706.249700] Lustre: DEBUG MARKER: == replay-single test 20a: |X| open(O_CREAT), unlink, replay, close (test mds_cleanup_orphans) ========================================================== 21:09:16 (1763345356) [ 1709.946338] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1741.678705] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1742.981435] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1750.209933] Lustre: DEBUG MARKER: == replay-single test 20b: write, unlink, eviction, replay (test mds_cleanup_orphans) ========================================================== 21:10:01 (1763345401) [ 1755.558658] LustreError: lustre-MDT0000-mdc-ffff975049931000: operation mds_statfs to node 192.168.204.135@tcp failed: rc = -107 [ 1755.563232] LustreError: Skipped 11 previous similar messages [ 1755.569504] LustreError: lustre-MDT0000-mdc-ffff975049931000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 1755.579672] LustreError: 53758:0:(file.c:249:ll_close_inode_openhandle()) lustre-clilmv-ffff975049931000: inode [0x200001b71:0x118:0x0] mdc close failed: rc = -108 [ 1755.579765] LustreError: 53702:0:(vvp_io.c:1896:vvp_io_init()) lustre: refresh file layout [0x200001b71:0x132:0x0] error -108. [ 1779.167305] Lustre: lustre-MDT0000-mdc-ffff975049931000: Connection to lustre-MDT0000 (at 192.168.204.135@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1779.176350] Lustre: Skipped 11 previous similar messages [ 1779.183513] LustreError: MGC192.168.204.135@tcp: Connection to MGS (at 192.168.204.135@tcp) was lost; in progress operations using this service will fail [ 1779.198435] LustreError: Skipped 10 previous similar messages [ 1779.211571] Lustre: Evicted from MGS (at 192.168.204.135@tcp) after server handle changed from 0x8285adaf8967f5eb to 0x8285adaf8967fabb [ 1779.222387] Lustre: Skipped 10 previous similar messages [ 1779.227933] Lustre: MGC192.168.204.135@tcp: Connection restored to 192.168.204.135@tcp (at 192.168.204.135@tcp) [ 1779.233875] Lustre: Skipped 22 previous similar messages [ 1785.219677] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1786.592628] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1801.485606] Lustre: DEBUG MARKER: before 6144, after 6144 [ 1806.862433] Lustre: DEBUG MARKER: == replay-single test 20c: check that client eviction does not affect file content ========================================================== 21:10:57 (1763345457) [ 1809.875936] LustreError: lustre-MDT0000-mdc-ffff975049931000: operation mds_statfs to node 192.168.204.135@tcp failed: rc = -107 [ 1809.902658] LustreError: lustre-MDT0000-mdc-ffff975049931000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 1817.289327] Lustre: DEBUG MARKER: == replay-single test 21: |X| open(O_CREAT), unlink touch new, replay, close (test mds_cleanup_orphans) ========================================================== 21:11:07 (1763345467) [ 1820.789170] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1850.366610] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1851.856774] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1859.753122] Lustre: DEBUG MARKER: == replay-single test 22: open(O_CREAT), |X| unlink, replay, close (test mds_cleanup_orphans) ========================================================== 21:11:50 (1763345510) [ 1863.755839] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1896.949158] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1898.646792] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1905.696515] Lustre: DEBUG MARKER: == replay-single test 23: open(O_CREAT), |X| unlink touch new, replay, close (test mds_cleanup_orphans) ========================================================== 21:12:36 (1763345556) [ 1909.063533] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1928.737875] LustreError: 2361:0:(client.c:3418:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff975046442d80 x1848999892825856/t150323855363(150323855363) o101->lustre-MDT0000-mdc-ffff975049931000@192.168.204.135@tcp:12/10 lens 592/608 e 0 to 0 dl 1763345596 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'multiop.0' uid:0 gid:0 projid:0 [ 1928.769538] LustreError: 2361:0:(client.c:3418:ptlrpc_replay_interpret()) Skipped 9 previous similar messages [ 1938.045941] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1939.497351] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1947.551978] Lustre: DEBUG MARKER: == replay-single test 24: open(O_CREAT), replay, unlink, close (test mds_cleanup_orphans) ========================================================== 21:13:18 (1763345598) [ 1951.124923] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 1982.760907] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1984.577955] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1993.304262] Lustre: DEBUG MARKER: == replay-single test 25: open(O_CREAT), unlink, replay, close (test mds_cleanup_orphans) ========================================================== 21:14:03 (1763345643) [ 1997.216587] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2038.389608] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2040.013089] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2049.347288] Lustre: DEBUG MARKER: == replay-single test 26: |X| open(O_CREAT), unlink two, close one, replay, close one (test mds_cleanup_orphans) ========================================================== 21:14:59 (1763345699) [ 2053.385677] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2083.701693] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2085.553403] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2093.462379] Lustre: DEBUG MARKER: == replay-single test 27: |X| open(O_CREAT), unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 21:15:44 (1763345744) [ 2096.633669] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2126.122837] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2127.654719] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2136.410824] Lustre: DEBUG MARKER: == replay-single test 28: open(O_CREAT), |X| unlink two, close one, replay, close one (test mds_cleanup_orphans) ========================================================== 21:16:26 (1763345786) [ 2140.289603] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2172.530170] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2173.918963] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2181.426789] Lustre: DEBUG MARKER: == replay-single test 29: open(O_CREAT), |X| unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 21:17:12 (1763345832) [ 2185.590308] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2216.724560] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2218.530802] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2227.372750] Lustre: DEBUG MARKER: == replay-single test 30: open(O_CREAT) two, unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 21:17:57 (1763345877) [ 2231.289803] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2258.510389] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2259.983419] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2266.701955] Lustre: DEBUG MARKER: == replay-single test 31: open(O_CREAT) two, unlink one, |X| unlink one, close two (test mds_cleanup_orphans) ========================================================== 21:18:37 (1763345917) [ 2270.713897] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2289.120260] Lustre: 2364:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763345925/real 1763345925] req@ffff9750586a9f80 x1848999892923264/t0(0) o400->MGC192.168.204.135@tcp@192.168.204.135@tcp:26/25 lens 224/224 e 0 to 1 dl 1763345941 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2289.178329] Lustre: 2364:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 48 previous similar messages [ 2302.870420] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2304.178836] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2311.294487] Lustre: DEBUG MARKER: == replay-single test 32: close() notices client eviction; close() after client eviction ========================================================== 21:19:22 (1763345962) [ 2313.744315] LustreError: lustre-MDT0000-mdc-ffff975049931000: operation mds_statfs to node 192.168.204.135@tcp failed: rc = -107 [ 2313.760255] LustreError: lustre-MDT0000-mdc-ffff975049931000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 2320.462074] Lustre: DEBUG MARKER: == replay-single test 33a: fid seq shouldn't be reused after abort recovery ========================================================== 21:19:31 (1763345971) [ 2323.041824] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2335.306224] LustreError: lustre-MDT0000-mdc-ffff975049931000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 2347.506767] Lustre: DEBUG MARKER: == replay-single test 33b: test fid seq allocation ======= 21:19:57 (1763345997) [ 2350.722178] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2360.883328] LustreError: lustre-MDT0000-mdc-ffff975049931000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 2374.182142] Lustre: DEBUG MARKER: == replay-single test 34: abort recovery before client does replay (test mds_cleanup_orphans) ========================================================== 21:20:24 (1763346024) [ 2377.723243] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2386.414069] LustreError: MGC192.168.204.135@tcp: Connection to MGS (at 192.168.204.135@tcp) was lost; in progress operations using this service will fail [ 2386.420838] LustreError: Skipped 13 previous similar messages [ 2386.434705] Lustre: lustre-MDT0000-mdc-ffff975049931000: Connection to lustre-MDT0000 (at 192.168.204.135@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 2386.452815] Lustre: Skipped 15 previous similar messages [ 2386.452832] Lustre: Evicted from MGS (at 192.168.204.135@tcp) after server handle changed from 0x8285adaf89684736 to 0x8285adaf89685107 [ 2386.463490] Lustre: Skipped 13 previous similar messages [ 2386.467931] Lustre: MGC192.168.204.135@tcp: Connection restored to 192.168.204.135@tcp (at 192.168.204.135@tcp) [ 2386.471616] Lustre: Skipped 29 previous similar messages [ 2386.565261] LustreError: lustre-MDT0000-mdc-ffff975049931000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 2401.887525] Lustre: DEBUG MARKER: == replay-single test 35: test recovery from llog for unlink op ========================================================== 21:20:52 (1763346052) [ 2417.206617] LustreError: lustre-MDT0000-mdc-ffff975049931000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 2429.128236] Lustre: DEBUG MARKER: SKIP: replay-single test_36 skipping ALWAYS excluded test 36 [ 2430.687588] Lustre: DEBUG MARKER: == replay-single test 37: abort recovery before client does replay (test mds_cleanup_orphans for directories) ========================================================== 21:21:21 (1763346081) [ 2434.600865] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2447.930319] LustreError: lustre-MDT0000-mdc-ffff975049931000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 2459.798578] Lustre: DEBUG MARKER: == replay-single test 38: test recovery from unlink llog (test llog_gen_rec) ========================================================== 21:21:50 (1763346110) [ 2491.212271] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2523.615300] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2525.732761] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2547.096392] Lustre: DEBUG MARKER: == replay-single test 39: test recovery from unlink llog (test llog_gen_rec) ========================================================== 21:23:17 (1763346197) [ 2572.278422] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2616.301182] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2618.216481] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2639.521491] Lustre: DEBUG MARKER: == replay-single test 41: read from a valid osc while other oscs are invalid ========================================================== 21:24:50 (1763346290) [ 2647.842219] Lustre: DEBUG MARKER: == replay-single test 42: recovery after ost failure ===== 21:24:58 (1763346298) [ 2671.364916] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-OST0000 [ 2766.769227] Lustre: DEBUG MARKER: == replay-single test 43: mds osc import failure during recovery; don't LBUG ========================================================== 21:26:57 (1763346417) [ 2771.265238] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 2802.805839] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2804.234395] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2822.592695] Lustre: DEBUG MARKER: == replay-single test 44a: race in target handle connect ========================================================== 21:27:53 (1763346473) [ 2904.822709] Lustre: DEBUG MARKER: == replay-single test 44b: race in target handle connect ========================================================== 21:29:15 (1763346555) [ 2927.104981] LustreError: 85591:0:(lmv_obd.c:1435:lmv_statfs()) lustre-MDT0000-mdc-ffff975049931000: can't stat MDS #0: rc = -114 [ 2950.632988] LustreError: 85614:0:(lmv_obd.c:1435:lmv_statfs()) lustre-MDT0000-mdc-ffff975049931000: can't stat MDS #0: rc = -114 [ 2972.536448] LustreError: 85636:0:(lmv_obd.c:1435:lmv_statfs()) lustre-MDT0000-mdc-ffff975049931000: can't stat MDS #0: rc = -114 [ 2994.698841] LustreError: 85658:0:(lmv_obd.c:1435:lmv_statfs()) lustre-MDT0000-mdc-ffff975049931000: can't stat MDS #0: rc = -114 [ 3017.207414] LustreError: 85681:0:(lmv_obd.c:1435:lmv_statfs()) lustre-MDT0000-mdc-ffff975049931000: can't stat MDS #0: rc = -110 [ 3040.771453] LustreError: 85703:0:(lmv_obd.c:1435:lmv_statfs()) lustre-MDT0000-mdc-ffff975049931000: can't stat MDS #0: rc = -114 [ 3062.561498] LustreError: 85726:0:(lmv_obd.c:1435:lmv_statfs()) lustre-MDT0000-mdc-ffff975049931000: can't stat MDS #0: rc = -114 [ 3107.514507] LustreError: 85770:0:(lmv_obd.c:1435:lmv_statfs()) lustre-MDT0000-mdc-ffff975049931000: can't stat MDS #0: rc = -114 [ 3107.520271] LustreError: 85770:0:(lmv_obd.c:1435:lmv_statfs()) Skipped 1 previous similar message [ 3131.565241] Lustre: lustre-MDT0000-mdc-ffff975049931000: Connection restored to 192.168.204.135@tcp (at 192.168.204.135@tcp) [ 3131.582190] Lustre: Skipped 21 previous similar messages [ 3136.218153] Lustre: DEBUG MARKER: == replay-single test 44c: race in target handle connect ========================================================== 21:33:06 (1763346786) [ 3139.987112] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3153.387671] LustreError: MGC192.168.204.135@tcp: Connection to MGS (at 192.168.204.135@tcp) was lost; in progress operations using this service will fail [ 3153.388287] Lustre: lustre-MDT0000-mdc-ffff975049931000: Connection to lustre-MDT0000 (at 192.168.204.135@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 3153.401844] LustreError: Skipped 5 previous similar messages [ 3153.408807] Lustre: Evicted from MGS (at 192.168.204.135@tcp) after server handle changed from 0x8285adaf896c7a3b to 0x8285adaf896c8b75 [ 3153.415576] Lustre: Skipped 17 previous similar messages [ 3153.447417] Lustre: Skipped 5 previous similar messages [ 3153.589818] LustreError: lustre-MDT0000-mdc-ffff975049931000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 3179.807463] Lustre: 2363:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763346815/real 1763346815] req@ffff975049748000 x1848999895701760/t0(0) o400->MGC192.168.204.135@tcp@192.168.204.135@tcp:26/25 lens 224/224 e 0 to 1 dl 1763346831 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3179.826936] Lustre: 2363:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 18 previous similar messages [ 3192.342771] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3193.777835] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3200.938906] Lustre: DEBUG MARKER: == replay-single test 45: Handle failed close ============ 21:34:11 (1763346851) [ 3201.140753] Lustre: setting import lustre-MDT0000_UUID INACTIVE by administrator request [ 3201.151968] LustreError: 88119:0:(file.c:249:ll_close_inode_openhandle()) lustre-clilmv-ffff975049931000: inode [0x20001a9e1:0x1:0x0] mdc close failed: rc = -108 [ 3201.174282] LustreError: lustre-MDT0000-mdc-ffff975049931000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 3208.042858] Lustre: DEBUG MARKER: == replay-single test 46: Don't leak file handle after open resend (3325) ========================================================== 21:34:18 (1763346858) [ 3258.601856] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3260.265684] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3270.420623] Lustre: DEBUG MARKER: == replay-single test 47: MDS->OSC failure during precreate cleanup (2824) ========================================================== 21:35:20 (1763346920) [ 3301.515545] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 3303.150831] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 3374.804318] Lustre: DEBUG MARKER: == replay-single test 48: MDS->OSC failure during precreate cleanup (2824) ========================================================== 21:37:05 (1763347025) [ 3378.013631] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3399.178889] LustreError: 2361:0:(client.c:3418:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff975048590a80 x1848999895768064/t236223201383(236223201383) o101->lustre-MDT0000-mdc-ffff975049931000@192.168.204.135@tcp:12/10 lens 592/608 e 0 to 0 dl 1763347067 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'createmany.0' uid:0 gid:0 projid:0 [ 3399.196710] LustreError: 2361:0:(client.c:3418:ptlrpc_replay_interpret()) Skipped 16 previous similar messages [ 3469.302028] Lustre: DEBUG MARKER: == replay-single test 50: Double OSC recovery, don't LASSERT (3812) ========================================================== 21:38:39 (1763347119) [ 3483.839834] Lustre: DEBUG MARKER: == replay-single test 52: time out lock replay (3764) ==== 21:38:54 (1763347134) [ 3526.250303] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3527.608954] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3535.362395] Lustre: DEBUG MARKER: == replay-single test 53a: |X| close request while two MDC requests in flight ========================================================== 21:39:46 (1763347186) [ 3541.801412] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3582.281886] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3583.796663] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3591.184091] Lustre: DEBUG MARKER: == replay-single test 53b: |X| open request while two MDC requests in flight ========================================================== 21:40:41 (1763347241) [ 3596.956066] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3623.183995] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3624.535077] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3631.525627] Lustre: DEBUG MARKER: == replay-single test 53c: |X| open request and close request while two MDC requests in flight ========================================================== 21:41:22 (1763347282) [ 3636.429599] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3666.100748] Lustre: DEBUG MARKER: == replay-single test 53d: close reply while two MDC requests in flight ========================================================== 21:41:56 (1763347316) [ 3696.729654] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3698.040777] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3705.449113] Lustre: DEBUG MARKER: == replay-single test 53e: |X| open reply while two MDC requests in flight ========================================================== 21:42:36 (1763347356) [ 3710.922362] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3733.048401] Lustre: lustre-MDT0000-mdc-ffff975049931000: Connection restored to 192.168.204.135@tcp (at 192.168.204.135@tcp) [ 3733.055196] Lustre: Skipped 22 previous similar messages [ 3736.983570] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3738.378968] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3745.502697] Lustre: DEBUG MARKER: == replay-single test 53f: |X| open reply and close reply while two MDC requests in flight ========================================================== 21:43:16 (1763347396) [ 3750.260774] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3762.655421] Lustre: lustre-MDT0000-mdc-ffff975049931000: Connection to lustre-MDT0000 (at 192.168.204.135@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 3762.664696] Lustre: Skipped 13 previous similar messages [ 3767.729841] LustreError: MGC192.168.204.135@tcp: Connection to MGS (at 192.168.204.135@tcp) was lost; in progress operations using this service will fail [ 3767.737637] LustreError: Skipped 9 previous similar messages [ 3767.747833] Lustre: Evicted from MGS (at 192.168.204.135@tcp) after server handle changed from 0x8285adaf896cd462 to 0x8285adaf896cd9be [ 3767.755794] Lustre: Skipped 9 previous similar messages [ 3779.562562] Lustre: DEBUG MARKER: == replay-single test 53g: |X| drop open reply and close request while close and open are both in flight ========================================================== 21:43:50 (1763347430) [ 3784.730625] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3796.450834] Lustre: 101792:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763347432/real 1763347432] req@ffff975046438380 x1848999895910656/t0(0) o36->lustre-MDT0000-mdc-ffff975049931000@192.168.204.135@tcp:12/10 lens 504/576 e 0 to 1 dl 1763347448 ref 2 fl Rpc:XQr/200/ffffffff rc 0/-1 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 3796.467131] Lustre: 101792:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 39 previous similar messages [ 3812.506777] Lustre: DEBUG MARKER: == replay-single test 53h: open request and close reply while two MDC requests in flight ========================================================== 21:44:23 (1763347463) [ 3818.405725] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3847.094605] Lustre: DEBUG MARKER: == replay-single test 55: let MDS_CHECK_RESENT return the original return code instead of 0 ========================================================== 21:44:58 (1763347498) [ 3868.914932] Lustre: DEBUG MARKER: == replay-single test 56: don't replay a symlink open request (3440) ========================================================== 21:45:19 (1763347519) [ 3872.109233] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3901.260358] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3902.569910] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3920.002767] Lustre: DEBUG MARKER: == replay-single test 57: test recovery from llog for setattr op ========================================================== 21:46:10 (1763347570) [ 3924.111251] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3948.542389] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3949.510852] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3961.399893] Lustre: DEBUG MARKER: == replay-single test 58a: test recovery from llog for setattr op (test llog_gen_rec) ========================================================== 21:46:52 (1763347612) [ 4001.101557] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4029.757180] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4031.201796] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4078.176970] Lustre: DEBUG MARKER: == replay-single test 58b: test replay of setxattr op ==== 21:48:48 (1763347728) [ 4078.640742] Lustre: Mounted lustre-client [ 4081.699400] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4083.702472] LustreError: lustre-MDT0000-mdc-ffff975049931000: operation mds_batch to node 192.168.204.135@tcp failed: rc = -107 [ 4110.325866] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4111.340310] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4113.766449] LustreError: 109746:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff975046685000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 4113.773214] LustreError: 109746:0:(lov_obd.c:783:lov_cleanup()) Skipped 1 previous similar message [ 4113.779310] LustreError: 109746:0:(obd_class.h:479:obd_check_dev()) Device 10 not setup [ 4113.783517] LustreError: 109746:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 4113.814467] Lustre: Unmounted lustre-client [ 4116.451129] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount FULL mgc.*.mgs_server_uuid [ 4117.773744] Lustre: DEBUG MARKER: mgc.*.mgs_server_uuid in FULL state after 0 sec [ 4122.197510] Lustre: DEBUG MARKER: == replay-single test 58c: resend/reconstruct setxattr op ========================================================== 21:49:33 (1763347773) [ 4127.549541] Lustre: Mounted lustre-client [ 4164.770307] LustreError: 110848:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff97504650d000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 4164.777022] LustreError: 110848:0:(lov_obd.c:783:lov_cleanup()) Skipped 1 previous similar message [ 4164.784845] LustreError: 110848:0:(obd_class.h:479:obd_check_dev()) Device 10 not setup [ 4164.789509] LustreError: 110848:0:(obd_class.h:479:obd_check_dev()) Skipped 5 previous similar messages [ 4164.817224] Lustre: Unmounted lustre-client [ 4169.826990] Lustre: DEBUG MARKER: SKIP: replay-single test_59 skipping ALWAYS excluded test 59 [ 4170.779599] Lustre: DEBUG MARKER: == replay-single test 60: test llog post recovery init vs llog unlink ========================================================== 21:50:21 (1763347821) [ 4178.352081] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4207.069132] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4208.238990] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4217.547850] Lustre: DEBUG MARKER: == replay-single test 61a: test race llog recovery vs llog cleanup ========================================================== 21:51:08 (1763347868) [ 4235.623166] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-OST0000 [ 4309.887739] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 4311.219264] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4349.891932] Lustre: DEBUG MARKER: == replay-single test 61b: test race mds llog sync vs llog cleanup ========================================================== 21:53:20 (1763348000) [ 4372.454784] Lustre: lustre-MDT0000-mdc-ffff975049931000: Connection to lustre-MDT0000 (at 192.168.204.135@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 4372.469035] Lustre: Skipped 12 previous similar messages [ 4372.476921] LustreError: MGC192.168.204.135@tcp: Connection to MGS (at 192.168.204.135@tcp) was lost; in progress operations using this service will fail [ 4372.492058] LustreError: Skipped 7 previous similar messages [ 4372.504900] Lustre: Evicted from MGS (at 192.168.204.135@tcp) after server handle changed from 0x8285adaf89712aec to 0x8285adaf89723826 [ 4372.512855] Lustre: Skipped 7 previous similar messages [ 4372.523287] Lustre: MGC192.168.204.135@tcp: Connection restored to 192.168.204.135@tcp (at 192.168.204.135@tcp) [ 4372.536180] Lustre: Skipped 20 previous similar messages [ 4408.290062] Lustre: 2364:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763348044/real 1763348044] req@ffff975050794a80 x1848999899524224/t0(0) o400->MGC192.168.204.135@tcp@192.168.204.135@tcp:26/25 lens 224/224 e 0 to 1 dl 1763348060 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4408.318946] Lustre: 2364:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 32 previous similar messages [ 4412.187245] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4413.477779] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4419.488831] Lustre: DEBUG MARKER: == replay-single test 61c: test race mds llog sync vs llog cleanup ========================================================== 21:54:30 (1763348070) [ 4457.977441] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 4459.450599] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4466.688830] Lustre: DEBUG MARKER: == replay-single test 61d: error in llog_setup should cleanup the llog context correctly ========================================================== 21:55:17 (1763348117) [ 4486.287834] Lustre: DEBUG MARKER: == replay-single test 62: don't mis-drop resent replay === 21:55:37 (1763348137) [ 4488.927605] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4527.071418] LustreError: 2361:0:(client.c:3367:ptlrpc_replay_interpret()) @@@ request replay timed out req@ffff975048d55880 x1848999899544064/t313532612612(313532612612) o101->lustre-MDT0000-mdc-ffff975049931000@192.168.204.135@tcp:12/10 lens 592/664 e 0 to 1 dl 1763348178 ref 2 fl Interpret:EXQU/604/ffffffff rc -110/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 4527.140483] LustreError: 2361:0:(client.c:3418:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff975048d55880 x1848999899544064/t313532612612(313532612612) o101->lustre-MDT0000-mdc-ffff975049931000@192.168.204.135@tcp:12/10 lens 592/608 e 0 to 0 dl 1763348195 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'createmany.0' uid:0 gid:0 projid:0 [ 4527.153068] LustreError: 2361:0:(client.c:3418:ptlrpc_replay_interpret()) Skipped 19 previous similar messages [ 4530.274759] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4531.411666] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4538.169078] Lustre: DEBUG MARKER: == replay-single test 65a: AT: verify early replies ====== 21:56:29 (1763348189) [ 4591.188960] Lustre: DEBUG MARKER: == replay-single test 65b: AT: verify early replies on packed reply / bulk ========================================================== 21:57:22 (1763348242) [ 4635.853721] Lustre: DEBUG MARKER: == replay-single test 66a: AT: verify MDT service time adjusts with no early replies ========================================================== 21:58:06 (1763348286) [ 4696.773640] Lustre: DEBUG MARKER: == replay-single test 66b: AT: verify net latency adjusts ========================================================== 21:59:07 (1763348347) [ 4722.668542] LustreError: 123279:0:(client.c:1679:after_reply()) cfs_fail_timeout id 50c sleeping for 10000ms [ 4732.679193] LustreError: 123279:0:(client.c:1679:after_reply()) cfs_fail_timeout id 50c awake [ 4732.704191] LustreError: 123279:0:(client.c:1679:after_reply()) cfs_fail_timeout id 50c sleeping for 10000ms [ 4742.735151] LustreError: 123279:0:(client.c:1679:after_reply()) cfs_fail_timeout id 50c awake [ 4742.757633] LustreError: 123279:0:(client.c:1679:after_reply()) cfs_fail_timeout id 50c sleeping for 10000ms [ 4752.860478] LustreError: 123279:0:(client.c:1679:after_reply()) cfs_fail_timeout id 50c awake [ 4752.874621] LustreError: 123279:0:(client.c:1679:after_reply()) cfs_fail_timeout id 50c sleeping for 10000ms [ 4762.903833] LustreError: 123279:0:(client.c:1679:after_reply()) cfs_fail_timeout id 50c awake [ 4762.919662] LustreError: 2361:0:(client.c:1679:after_reply()) cfs_fail_timeout id 50c sleeping for 10000ms [ 4772.943440] LustreError: 2361:0:(client.c:1679:after_reply()) cfs_fail_timeout id 50c awake [ 4772.956869] LustreError: 2363:0:(client.c:1679:after_reply()) cfs_fail_timeout id 50c sleeping for 10000ms [ 4782.959145] LustreError: 2363:0:(client.c:1679:after_reply()) cfs_fail_timeout id 50c awake [ 4797.920946] Lustre: DEBUG MARKER: == replay-single test 67a: AT: verify slow request processing doesn't induce reconnects ========================================================== 22:00:48 (1763348448) [ 4873.200301] Lustre: DEBUG MARKER: == replay-single test 67b: AT: verify instant slowdown doesn't induce reconnects ========================================================== 22:02:03 (1763348523) [ 4904.995460] Lustre: DEBUG MARKER: phase 2 [ 4911.561701] Lustre: DEBUG MARKER: == replay-single test 68: AT: verify slowing locks ======= 22:02:42 (1763348562) [ 4939.013947] LustreError: 108225:0:(ldlm_request.c:1402:ldlm_cli_cancel_req()) cfs_fail_timeout id 312 sleeping for 19000ms [ 4939.022286] LustreError: 108225:0:(ldlm_request.c:1402:ldlm_cli_cancel_req()) Skipped 1 previous similar message [ 4958.081048] LustreError: 108225:0:(ldlm_request.c:1402:ldlm_cli_cancel_req()) cfs_fail_timeout id 312 awake [ 4958.088491] LustreError: 108225:0:(ldlm_request.c:1402:ldlm_cli_cancel_req()) Skipped 1 previous similar message [ 4991.046778] Lustre: DEBUG MARKER: == replay-single test 70a: check multi client t-f ======== 22:04:01 (1763348641) [ 4992.253573] Lustre: DEBUG MARKER: SKIP: replay-single test_70a Need two or more clients, have 1 [ 4993.779046] Lustre: DEBUG MARKER: == replay-single test 70b: dbench 1mdts recovery; 1 clients ========================================================== 22:04:04 (1763348644) [ 4997.724173] Lustre: DEBUG MARKER: Started rundbench load pid=126570 ... [ 5001.701810] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5003.801829] Lustre: DEBUG MARKER: test_70b fail mds1 1 times [ 5005.297089] LustreError: lustre-MDT0000-mdc-ffff975049931000: operation mds_sync to node 192.168.204.135@tcp failed: rc = -19 [ 5005.314892] Lustre: lustre-MDT0000-mdc-ffff975049931000: Connection to lustre-MDT0000 (at 192.168.204.135@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 5005.321598] Lustre: Skipped 4 previous similar messages [ 5022.696843] LustreError: MGC192.168.204.135@tcp: Connection to MGS (at 192.168.204.135@tcp) was lost; in progress operations using this service will fail [ 5022.707678] LustreError: Skipped 3 previous similar messages [ 5022.720915] Lustre: Evicted from MGS (at 192.168.204.135@tcp) after server handle changed from 0x8285adaf897248db to 0x8285adaf8972ac94 [ 5022.732996] Lustre: Skipped 3 previous similar messages [ 5022.739299] Lustre: MGC192.168.204.135@tcp: Connection restored to 192.168.204.135@tcp (at 192.168.204.135@tcp) [ 5022.744930] Lustre: Skipped 7 previous similar messages [ 5022.755760] LustreError: 2361:0:(client.c:3418:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff975048d56a00 x1848999899747840/t317827580300(317827580300) o101->lustre-MDT0000-mdc-ffff975049931000@192.168.204.135@tcp:12/10 lens 576/608 e 0 to 0 dl 1763348690 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'dbench.0' uid:0 gid:0 projid:0 [ 5022.775679] LustreError: 2361:0:(client.c:3418:ptlrpc_replay_interpret()) Skipped 24 previous similar messages [ 5029.883033] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 5031.654095] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5037.964162] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5040.088575] Lustre: DEBUG MARKER: test_70b fail mds1 2 times [ 5041.678545] LustreError: lustre-MDT0000-mdc-ffff975049931000: operation mds_reint to node 192.168.204.135@tcp failed: rc = -19 [ 5058.556577] LustreError: 2361:0:(client.c:3418:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff975048d56a00 x1848999899747840/t317827580300(317827580300) o101->lustre-MDT0000-mdc-ffff975049931000@192.168.204.135@tcp:12/10 lens 576/608 e 0 to 0 dl 1763348726 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'dbench.0' uid:0 gid:0 projid:0 [ 5058.572967] LustreError: 2361:0:(client.c:3418:ptlrpc_replay_interpret()) Skipped 23 previous similar messages [ 5065.376844] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 5066.405305] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5071.937638] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5074.381111] Lustre: DEBUG MARKER: test_70b fail mds1 3 times [ 5076.028507] LustreError: lustre-MDT0000-mdc-ffff975049931000: operation ldlm_cancel to node 192.168.204.135@tcp failed: rc = -19 [ 5104.670306] LustreError: 2361:0:(client.c:3418:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff975048d56a00 x1848999899747840/t317827580300(317827580300) o101->lustre-MDT0000-mdc-ffff975049931000@192.168.204.135@tcp:12/10 lens 576/608 e 0 to 0 dl 1763348772 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'dbench.0' uid:0 gid:0 projid:0 [ 5104.685065] LustreError: 2361:0:(client.c:3418:ptlrpc_replay_interpret()) Skipped 36 previous similar messages [ 5109.634666] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 5111.135654] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5117.954639] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5120.495734] Lustre: DEBUG MARKER: test_70b fail mds1 4 times [ 5122.011186] LustreError: lustre-MDT0000-mdc-ffff975049931000: operation mds_readpage to node 192.168.204.135@tcp failed: rc = -19 [ 5122.022106] LustreError: Skipped 1 previous similar message [ 5146.318773] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 5147.769827] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5155.691831] Lustre: DEBUG MARKER: == replay-single test 70c: tar 1mdts recovery ============ 22:06:46 (1763348806) [ 5281.384057] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5292.763240] Lustre: DEBUG MARKER: test_70c fail mds1 1 times [ 5295.172254] LustreError: lustre-MDT0000-mdc-ffff975049931000: operation ldlm_enqueue to node 192.168.204.135@tcp failed: rc = -19 [ 5313.598405] LustreError: 2361:0:(client.c:3418:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9750460f2a00 x1848999904627968/t335007456719(335007456719) o101->lustre-MDT0000-mdc-ffff975049931000@192.168.204.135@tcp:12/10 lens 592/608 e 0 to 0 dl 1763348981 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'tar.0' uid:0 gid:0 projid:0 [ 5313.612858] LustreError: 2361:0:(client.c:3418:ptlrpc_replay_interpret()) Skipped 68 previous similar messages [ 5324.367592] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 5325.965669] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5453.206382] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5464.750480] Lustre: DEBUG MARKER: test_70c fail mds1 2 times [ 5467.347299] LustreError: lustre-MDT0000-mdc-ffff975049931000: operation ldlm_enqueue to node 192.168.204.135@tcp failed: rc = -19 [ 5487.638079] LustreError: 2361:0:(client.c:3418:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9750460bdc00 x1848999908670208/t339302423399(339302423399) o101->lustre-MDT0000-mdc-ffff975049931000@192.168.204.135@tcp:12/10 lens 584/608 e 0 to 0 dl 1763349155 ref 2 fl Interpret:RQU/604/0 rc 301/301 job:'tar.0' uid:0 gid:0 projid:0 [ 5487.648463] LustreError: 2361:0:(client.c:3418:ptlrpc_replay_interpret()) Skipped 85 previous similar messages [ 5497.295096] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 5499.392422] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5545.953192] Lustre: DEBUG MARKER: == replay-single test 70d: mkdir/rmdir striped dir 1mdts recovery ========================================================== 22:13:16 (1763349196) [ 5547.086778] Lustre: DEBUG MARKER: SKIP: replay-single test_70d needs >= 2 MDTs [ 5548.241869] Lustre: DEBUG MARKER: == replay-single test 70e: rename cross-MDT with random fails ========================================================== 22:13:19 (1763349199) [ 5549.338447] Lustre: DEBUG MARKER: SKIP: replay-single test_70e needs >= 2 MDTs [ 5552.096319] Lustre: DEBUG MARKER: == replay-single test 70f: OSS O_DIRECT recovery with 1 clients ========================================================== 22:13:23 (1763349203) [ 5559.305879] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-OST0000 [ 5561.848489] Lustre: DEBUG MARKER: test_70f failing OST 1 times [ 5574.623236] Lustre: 2362:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763349210/real 1763349210] req@ffff975050608380 x1848999910230016/t0(0) o4->lustre-OST0000-osc-ffff975049931000@192.168.204.135@tcp:6/4 lens 488/448 e 0 to 1 dl 1763349226 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'dd.0' uid:0 gid:0 projid:0 [ 5574.657794] Lustre: 2362:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 9 previous similar messages [ 5594.624913] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 5596.612992] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 5607.300850] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-OST0000 [ 5609.641214] Lustre: DEBUG MARKER: test_70f failing OST 2 times [ 5615.592850] Lustre: lustre-OST0000-osc-ffff975049931000: Connection to lustre-OST0000 (at 192.168.204.135@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 5615.603299] Lustre: Skipped 6 previous similar messages [ 5630.284962] Lustre: lustre-OST0000-osc-ffff975049931000: Connection restored to 192.168.204.135@tcp (at 192.168.204.135@tcp) [ 5630.290405] Lustre: Skipped 12 previous similar messages [ 5639.764055] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 5641.492640] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 5650.177547] Lustre: DEBUG MARKER: == replay-single test 71a: mkdir/rmdir striped dir with 2 mdts recovery ========================================================== 22:15:01 (1763349301) [ 5651.583652] Lustre: DEBUG MARKER: SKIP: replay-single test_71a needs >= 2 MDTs [ 5652.919633] Lustre: DEBUG MARKER: == replay-single test 73a: open(O_CREAT), unlink, replay, reconnect before open replay, close ========================================================== 22:15:03 (1763349303) [ 5655.877214] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5677.032647] LustreError: MGC192.168.204.135@tcp: Connection to MGS (at 192.168.204.135@tcp) was lost; in progress operations using this service will fail [ 5677.041689] LustreError: Skipped 5 previous similar messages [ 5677.051739] Lustre: Evicted from MGS (at 192.168.204.135@tcp) after server handle changed from 0x8285adaf897bc75c to 0x8285adaf897da6c7 [ 5677.055772] Lustre: Skipped 5 previous similar messages [ 5692.383514] LustreError: 2361:0:(client.c:3367:ptlrpc_replay_interpret()) @@@ request replay timed out req@ffff97505060c000 x1848999910441472/t343597386787(343597386787) o101->lustre-MDT0000-mdc-ffff975049931000@192.168.204.135@tcp:12/10 lens 592/664 e 0 to 1 dl 1763349344 ref 2 fl Interpret:EXPQU/604/ffffffff rc -110/-1 job:'multiop.0' uid:0 gid:0 projid:0 [ 5696.167830] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 5697.744629] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5704.036373] Lustre: DEBUG MARKER: == replay-single test 73b: open(O_CREAT), unlink, replay, reconnect at open_replay reply, close ========================================================== 22:15:54 (1763349354) [ 5706.806070] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5744.607215] LustreError: 2361:0:(client.c:3367:ptlrpc_replay_interpret()) @@@ request replay timed out req@ffff975050608380 x1848999910451840/t347892350979(347892350979) o101->lustre-MDT0000-mdc-ffff975049931000@192.168.204.135@tcp:12/10 lens 592/664 e 0 to 1 dl 1763349396 ref 2 fl Interpret:EXPQU/604/ffffffff rc -110/-1 job:'multiop.0' uid:0 gid:0 projid:0 [ 5744.687798] LustreError: 2361:0:(client.c:3418:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff975050608380 x1848999910451840/t347892350979(347892350979) o101->lustre-MDT0000-mdc-ffff975049931000@192.168.204.135@tcp:12/10 lens 592/608 e 0 to 0 dl 1763349412 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'multiop.0' uid:0 gid:0 projid:0 [ 5744.708563] LustreError: 2361:0:(client.c:3418:ptlrpc_replay_interpret()) Skipped 104 previous similar messages [ 5748.344103] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 5749.835622] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5757.212582] Lustre: DEBUG MARKER: == replay-single test 74: Ensure applications don't fail waiting for OST recovery ========================================================== 22:16:47 (1763349407) [ 5758.444339] LustreError: 140692:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff975049931000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 5758.451815] LustreError: 140692:0:(lov_obd.c:783:lov_cleanup()) Skipped 1 previous similar message [ 5758.470145] LustreError: 140692:0:(obd_class.h:479:obd_check_dev()) Device 5 not setup [ 5758.473035] LustreError: 140692:0:(obd_class.h:479:obd_check_dev()) Skipped 5 previous similar messages [ 5758.511382] Lustre: Unmounted lustre-client [ 5786.768318] Lustre: Mounted lustre-client [ 5808.023656] Lustre: DEBUG MARKER: == replay-single test 80a: DNE: create remote dir, drop update rep from MDT0, fail MDT0 ========================================================== 22:17:38 (1763349458) [ 5809.660450] Lustre: DEBUG MARKER: SKIP: replay-single test_80a needs >= 2 MDTs [ 5811.130218] Lustre: DEBUG MARKER: == replay-single test 80b: DNE: create remote dir, drop update rep from MDT0, fail MDT1 ========================================================== 22:17:41 (1763349461) [ 5812.388841] Lustre: DEBUG MARKER: SKIP: replay-single test_80b needs >= 2 MDTs [ 5813.672099] Lustre: DEBUG MARKER: == replay-single test 80c: DNE: create remote dir, drop update rep from MDT1, fail MDT[0,1] ========================================================== 22:17:44 (1763349464) [ 5814.899829] Lustre: DEBUG MARKER: SKIP: replay-single test_80c needs >= 2 MDTs [ 5816.209754] Lustre: DEBUG MARKER: == replay-single test 80d: DNE: create remote dir, drop update rep from MDT1, fail 2 MDTs ========================================================== 22:17:47 (1763349467) [ 5817.526932] Lustre: DEBUG MARKER: SKIP: replay-single test_80d needs >= 2 MDTs [ 5819.274211] Lustre: DEBUG MARKER: == replay-single test 80e: DNE: create remote dir, drop MDT1 rep, fail MDT0 ========================================================== 22:17:49 (1763349469) [ 5820.597179] Lustre: DEBUG MARKER: SKIP: replay-single test_80e needs >= 2 MDTs [ 5822.034703] Lustre: DEBUG MARKER: == replay-single test 80f: DNE: create remote dir, drop MDT1 rep, fail MDT1 ========================================================== 22:17:52 (1763349472) [ 5823.670772] Lustre: DEBUG MARKER: SKIP: replay-single test_80f needs >= 2 MDTs [ 5825.330374] Lustre: DEBUG MARKER: == replay-single test 80g: DNE: create remote dir, drop MDT1 rep, fail MDT0, then MDT1 ========================================================== 22:17:55 (1763349475) [ 5826.734893] Lustre: DEBUG MARKER: SKIP: replay-single test_80g needs >= 2 MDTs [ 5828.337425] Lustre: DEBUG MARKER: == replay-single test 80h: DNE: create remote dir, drop MDT1 rep, fail 2 MDTs ========================================================== 22:17:58 (1763349478) [ 5829.756056] Lustre: DEBUG MARKER: SKIP: replay-single test_80h needs >= 2 MDTs [ 5831.158316] Lustre: DEBUG MARKER: == replay-single test 81a: DNE: unlink remote dir, drop MDT0 update rep, fail MDT1 ========================================================== 22:18:01 (1763349481) [ 5832.374323] Lustre: DEBUG MARKER: SKIP: replay-single test_81a needs >= 2 MDTs [ 5833.928952] Lustre: DEBUG MARKER: == replay-single test 81b: DNE: unlink remote dir, drop MDT0 update reply, fail MDT0 ========================================================== 22:18:04 (1763349484) [ 5835.286556] Lustre: DEBUG MARKER: SKIP: replay-single test_81b needs >= 2 MDTs [ 5836.925628] Lustre: DEBUG MARKER: == replay-single test 81c: DNE: unlink remote dir, drop MDT0 update reply, fail MDT0,MDT1 ========================================================== 22:18:07 (1763349487) [ 5838.162506] Lustre: DEBUG MARKER: SKIP: replay-single test_81c needs >= 2 MDTs [ 5839.606733] Lustre: DEBUG MARKER: == replay-single test 81d: DNE: unlink remote dir, drop MDT0 update reply, fail 2 MDTs ========================================================== 22:18:10 (1763349490) [ 5840.953418] Lustre: DEBUG MARKER: SKIP: replay-single test_81d needs >= 2 MDTs [ 5842.310303] Lustre: DEBUG MARKER: == replay-single test 81e: DNE: unlink remote dir, drop MDT1 req reply, fail MDT0 ========================================================== 22:18:13 (1763349493) [ 5843.665366] Lustre: DEBUG MARKER: SKIP: replay-single test_81e needs >= 2 MDTs [ 5845.195447] Lustre: DEBUG MARKER: == replay-single test 81f: DNE: unlink remote dir, drop MDT1 req reply, fail MDT1 ========================================================== 22:18:15 (1763349495) [ 5846.658888] Lustre: DEBUG MARKER: SKIP: replay-single test_81f needs >= 2 MDTs [ 5848.127936] Lustre: DEBUG MARKER: == replay-single test 81g: DNE: unlink remote dir, drop req reply, fail M0, then M1 ========================================================== 22:18:18 (1763349498) [ 5849.612786] Lustre: DEBUG MARKER: SKIP: replay-single test_81g needs >= 2 MDTs [ 5851.338260] Lustre: DEBUG MARKER: == replay-single test 81h: DNE: unlink remote dir, drop request reply, fail 2 MDTs ========================================================== 22:18:21 (1763349501) [ 5852.896392] Lustre: DEBUG MARKER: SKIP: replay-single test_81h needs >= 2 MDTs [ 5854.883829] Lustre: DEBUG MARKER: == replay-single test 84a: stale open during export disconnect ========================================================== 22:18:25 (1763349505) [ 5858.543793] LustreError: lustre-MDT0000-mdc-ffff975060b45000: operation mds_statfs to node 192.168.204.135@tcp failed: rc = -107 [ 5858.575655] LustreError: lustre-MDT0000-mdc-ffff975060b45000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5865.664595] Lustre: DEBUG MARKER: == replay-single test 85a: check the cancellation of unused locks during recovery(IBITS) ========================================================== 22:18:36 (1763349516) [ 5906.887877] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 5907.984699] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5914.195699] Lustre: DEBUG MARKER: == replay-single test 85b: check the cancellation of unused locks during recovery(EXTENT) ========================================================== 22:19:25 (1763349565) [ 5952.761164] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 5954.106580] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 5961.963120] Lustre: DEBUG MARKER: == replay-single test 86: umount server after clear nid_stats should not hit LBUG ========================================================== 22:20:12 (1763349612) [ 5963.324820] LustreError: 150180:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff975060b45000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 5963.331819] LustreError: 150180:0:(lov_obd.c:783:lov_cleanup()) Skipped 1 previous similar message [ 5963.347312] LustreError: 150180:0:(obd_class.h:479:obd_check_dev()) Device 5 not setup [ 5963.353032] LustreError: 150180:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 5963.387616] Lustre: Unmounted lustre-client [ 5974.605477] Lustre: Mounted lustre-client [ 5979.768426] Lustre: DEBUG MARKER: == replay-single test 87a: write replay ================== 22:20:30 (1763349630) [ 5984.326753] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-OST0000 [ 6015.864889] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 6017.480620] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 6026.253376] Lustre: DEBUG MARKER: == replay-single test 87b: write replay with changed data (checksum resend) ========================================================== 22:21:16 (1763349676) [ 6030.622140] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-OST0000 [ 6058.836322] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 6060.633603] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 6068.446258] Lustre: DEBUG MARKER: == replay-single test 88: MDS should not assign same objid to different files ========================================================== 22:21:59 (1763349719) [ 6072.739396] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-OST0000 [ 6076.321544] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 6170.981323] Lustre: DEBUG MARKER: == replay-single test 89: no disk space leak on late ost connection ========================================================== 22:23:41 (1763349821) [ 6205.919369] Lustre: 2364:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763349841/real 1763349841] req@ffff975042b94380 x1848999910979072/t0(0) o400->lustre-MDT0000-mdc-ffff97504650d800@192.168.204.135@tcp:12/10 lens 224/224 e 0 to 1 dl 1763349857 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6205.959760] Lustre: 2364:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 14 previous similar messages [ 6211.434446] LustreError: 155691:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff97504650d800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 6211.445461] LustreError: 155691:0:(lov_obd.c:783:lov_cleanup()) Skipped 1 previous similar message [ 6211.455358] LustreError: 155691:0:(obd_class.h:479:obd_check_dev()) Device 5 not setup [ 6211.458288] LustreError: 155691:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 6211.526126] Lustre: Unmounted lustre-client [ 6221.849933] Lustre: Mounted lustre-client [ 6221.868123] LustreError: lustre-OST0000-osc-ffff9750504bb800: operation ost_connect to node 192.168.204.135@tcp failed: rc = -16 [ 6289.577917] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 60 sec [ 6303.632273] Lustre: DEBUG MARKER: free_before: 7518208 free_after: 7518208 [ 6310.367786] Lustre: DEBUG MARKER: == replay-single test 90: lfs find identifies the missing striped file segments ========================================================== 22:26:01 (1763349961) [ 6319.078486] Lustre: lustre-OST0000-osc-ffff9750504bb800: Connection to lustre-OST0000 (at 192.168.204.135@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 6319.085940] Lustre: Skipped 11 previous similar messages [ 6334.566504] Lustre: lustre-OST0000-osc-ffff9750504bb800: Connection restored to 192.168.204.135@tcp (at 192.168.204.135@tcp) [ 6334.572566] Lustre: Skipped 14 previous similar messages [ 6344.478683] Lustre: DEBUG MARKER: == replay-single test 93a: replay + reconnect ============ 22:26:35 (1763349995) [ 6412.059417] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 6413.328715] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 6420.996994] Lustre: DEBUG MARKER: == replay-single test 93b: replay + reconnect on mds ===== 22:27:51 (1763350071) [ 6442.975798] LustreError: MGC192.168.204.135@tcp: Connection to MGS (at 192.168.204.135@tcp) was lost; in progress operations using this service will fail [ 6442.983136] LustreError: Skipped 4 previous similar messages [ 6442.997823] Lustre: Evicted from MGS (at 192.168.204.135@tcp) after server handle changed from 0x8285adaf897e322d to 0x8285adaf897e3c21 [ 6443.007738] Lustre: Skipped 4 previous similar messages [ 6529.693867] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 6531.018826] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6540.400810] Lustre: DEBUG MARKER: == replay-single test complete, duration 6339 sec ======== 22:29:51 (1763350191) [ 6542.051820] Lustre: DEBUG MARKER: === replay-single: start cleanup 22:29:52 (1763350192) === [ 6552.695848] Lustre: DEBUG MARKER: === replay-single: finish cleanup 22:30:03 (1763350203) === [ 6584.047952] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 6585.895667] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6589.421065] LustreError: 162378:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff9750504bb800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 6589.433312] LustreError: 162378:0:(lov_obd.c:783:lov_cleanup()) Skipped 1 previous similar message [ 6589.463845] LustreError: 162378:0:(obd_class.h:479:obd_check_dev()) Device 5 not setup [ 6589.471117] LustreError: 162378:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 6589.547063] Lustre: Unmounted lustre-client [ 6605.895639] Key type lgssc unregistered [ 6606.176094] LNet: 162858:0:(lib-ptl.c:967:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 6606.181634] LNetError: 162858:0:(acceptor.c:264:lnet_acceptor_remove_socket()) Interface ens2 not found [ 6606.201372] LNet: Removed LNI 192.168.204.35@tcp [ 6607.268202] Key type .llcrypt unregistered [ 6607.269738] Key type ._llcrypt unregistered