[ 0.000000] Linux version 4.18.0rh8.10-debug (green@maintenance) (gcc version 8.5.0 20210514 (Red Hat 8.5.0-26) (GCC)) #2 SMP Mon Jul 14 01:24:22 EDT 2025 [ 0.000000] Command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers' [ 0.000000] x86/fpu: xstate_offset[2]: 576, xstate_sizes[2]: 256 [ 0.000000] x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'standard' format. [ 0.000000] signal: max sigframe size: 1776 [ 0.000000] BIOS-provided physical RAM map: [ 0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable [ 0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000000100000-0x00000000bffd9fff] usable [ 0.000000] BIOS-e820: [mem 0x00000000bffda000-0x00000000bfffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000100000000-0x0000000146dfffff] usable [ 0.000000] NX (Execute Disable) protection: active [ 0.000000] SMBIOS 2.8 present. [ 0.000000] DMI: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.17.0-10.fc44 06/10/2025 [ 0.000000] Hypervisor detected: KVM [ 0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00 [ 0.000000] kvm-clock: using sched offset of 571667238 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2399.998 MHz processor [ 0.000000] last_pfn = 0x146e00 max_arch_pfn = 0x400000000 [ 0.000000] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT [ 0.000000] last_pfn = 0xbffda max_arch_pfn = 0x400000000 [ 0.000000] found SMP MP-table at [mem 0x000f54d0-0x000f54df] [ 0.000000] RAMDISK: [mem 0xbcc64000-0xbffcffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F52F0 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE2464 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE2300 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 0022C0 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE2374 000090 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE2404 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE243C 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe2300-0xbffe2373] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe22ff] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe2374-0xbffe2403] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe2404-0xbffe243b] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe243c-0xbffe2463] [ 0.000000] No NUMA configuration found [ 0.000000] Faking a node at [mem 0x0000000000000000-0x0000000146dfffff] [ 0.000000] NODE_DATA(0) allocated [mem 0x1465a3000-0x1465cdfff] [ 0.000000] Reserving 256MB of memory at 2752MB for crashkernel (System RAM: 4205MB) [ 0.000000] Zone ranges: [ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.000000] DMA32 [mem 0x0000000001000000-0x00000000ffffffff] [ 0.000000] Normal [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Device empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff] [ 0.000000] node 0: [mem 0x0000000000100000-0x00000000bffd9fff] [ 0.000000] node 0: [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Zeroed struct page in unavailable ranges: 4744 pages [ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x0000000146dfffff] [ 0.000000] ACPI: PM-Timer IO Port: 0x608 [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) [ 0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) [ 0.000000] Using ACPI (MADT) for SMP configuration information [ 0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000] TSC deadline timer available [ 0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs [ 0.000000] kvm-guest: KVM setup pv remote TLB flush [ 0.000000] kvm-guest: setup PV sched yield [ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff] [ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff] [ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff] [ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff] [ 0.000000] PM: Registered nosave memory: [mem 0xbffda000-0xbfffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xc0000000-0xfeffbfff] [ 0.000000] PM: Registered nosave memory: [mem 0xfeffc000-0xfeffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xff000000-0xfffbffff] [ 0.000000] PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff] [ 0.000000] [mem 0xc0000000-0xfeffbfff] available for PCI devices [ 0.000000] Booting paravirtualized kernel on KVM [ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns [ 0.000000] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1 [ 0.000000] percpu: Embedded 63 pages/cpu s221184 r8192 d28672 u524288 [ 0.000000] kvm-guest: PV spinlocks enabled [ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1059618 [ 0.000000] Policy zone: Normal [ 0.000000] Kernel command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] Specific versions of hardware are certified with Red Hat Enterprise Linux 8. Please see the list of hardware certified with Red Hat Enterprise Linux 8 at https://catalog.redhat.com. [ 0.000000] audit: disabled (until reboot) [ 0.000000] software IO TLB: area num 4. [ 0.000000] Memory: 2829700K/4306400K available (18435K kernel code, 11221K rwdata, 7248K rodata, 2908K init, 18040K bss, 524592K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] ftrace: allocating 41240 entries in 162 pages [ 0.000000] ftrace: allocated 162 pages with 3 groups [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] rcu: RCU event tracing is enabled. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ 0.000000] rcu: RCU callback double-/use-after-free debug enabled. [ 0.000000] Rude variant of Tasks RCU enabled. [ 0.000000] Tracing variant of Tasks RCU enabled. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 0.000000] NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16 [ 0.000000] random: get_random_bytes called from start_kernel+0x622/0x9a8 with crng_init=0 [ 0.001000] Console: colour *CGA 80x25 [ 0.001000] printk: console [ttyS1] enabled [ 0.001000] ACPI: Core revision 20220331 [ 0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.001011] APIC: Switch to symmetric I/O mode setup [ 0.002495] x2apic enabled [ 0.003006] Switched APIC routing to physical x2apic. [ 0.004009] kvm-guest: setup PV IPIs [ 0.007404] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.008000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.008022] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.009010] pid_max: default: 32768 minimum: 301 [ 0.010147] LSM: Security Framework initializing [ 0.011041] Yama: becoming mindful. [ 0.012033] SELinux: Initializing. [ 0.013064] *** VALIDATE selinux *** [ 0.023228] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.027736] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.028150] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.030063] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.031128] *** VALIDATE tmpfs *** [ 0.033154] *** VALIDATE proc *** [ 0.034254] *** VALIDATE cgroup *** [ 0.035010] *** VALIDATE cgroup2 *** [ 0.037006] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.038150] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.039000] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.039000] Spectre V2 : User space: Vulnerable [ 0.039009] Speculative Store Bypass: Vulnerable [ 0.040057] debug: unmapping init [mem 0xffffffff91a59000-0xffffffff91a60fff] [ 0.042164] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.044043] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.045019] ... version: 2 [ 0.046010] ... bit width: 48 [ 0.047010] ... generic registers: 4 [ 0.048008] ... value mask: 0000ffffffffffff [ 0.049009] ... max period: 00007fffffffffff [ 0.050008] ... fixed-purpose events: 3 [ 0.051008] ... event mask: 000000070000000f [ 0.053227] rcu: Hierarchical SRCU implementation. [ 0.055597] smp: Bringing up secondary CPUs ... [ 0.056627] x86: Booting SMP configuration: [ 0.057015] .... node #0, CPUs: #1 #2 #3 [ 0.072020] smp: Brought up 1 node, 4 CPUs [ 0.074015] smpboot: Max logical packages: 1 [ 0.075016] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.118421] node 0 deferred pages initialised in 40ms [ 0.123257] devtmpfs: initialized [ 0.125405] x86/mm: Memory block size: 128MB [ 0.128234] gcov: version magic: 0x41383552 [ 0.133151] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.135087] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.139357] pinctrl core: initialized pinctrl subsystem [ 0.152389] [ 0.152865] ************************************************************* [ 0.156017] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.159011] ** ** [ 0.161009] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.165016] ** ** [ 0.168011] ** This means that this kernel is built to expose internal ** [ 0.169009] ** IOMMU data structures, which may compromise security on ** [ 0.172012] ** your system. ** [ 0.174008] ** ** [ 0.176009] ** If you see this message and you are not debugging the ** [ 0.178009] ** kernel, report this immediately to your vendor! ** [ 0.181011] ** ** [ 0.183008] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.185012] ************************************************************* [ 0.187822] NET: Registered protocol family 16 [ 0.189462] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.190048] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.192053] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.193118] cpuidle: using governor menu [ 0.194605] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.199256] PCI: Using configuration type 1 for base access [ 0.200284] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.210044] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.212012] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.215234] cryptd: max_cpu_qlen set to 1000 [ 0.216399] ACPI: Added _OSI(Module Device) [ 0.218011] ACPI: Added _OSI(Processor Device) [ 0.219010] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.221063] ACPI: Added _OSI(Processor Aggregator Device) [ 0.226920] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.233564] ACPI: Interpreter enabled [ 0.234077] ACPI: PM: (supports S0 S3 S4 S5) [ 0.235013] ACPI: Using IOAPIC for interrupt routing [ 0.237379] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.243407] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.255304] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.258053] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.261021] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.265581] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.271993] acpiphp: Slot [2] registered [ 0.273183] acpiphp: Slot [5] registered [ 0.275153] acpiphp: Slot [6] registered [ 0.277171] acpiphp: Slot [3] registered [ 0.278136] acpiphp: Slot [4] registered [ 0.280141] acpiphp: Slot [7] registered [ 0.281237] acpiphp: Slot [8] registered [ 0.283083] acpiphp: Slot [9] registered [ 0.285113] acpiphp: Slot [10] registered [ 0.286171] acpiphp: Slot [11] registered [ 0.288161] acpiphp: Slot [12] registered [ 0.291119] acpiphp: Slot [13] registered [ 0.292000] acpiphp: Slot [14] registered [ 0.292000] acpiphp: Slot [15] registered [ 0.293077] acpiphp: Slot [16] registered [ 0.294126] acpiphp: Slot [17] registered [ 0.296071] acpiphp: Slot [18] registered [ 0.298096] acpiphp: Slot [19] registered [ 0.299191] acpiphp: Slot [20] registered [ 0.301172] acpiphp: Slot [21] registered [ 0.303085] acpiphp: Slot [22] registered [ 0.305082] acpiphp: Slot [23] registered [ 0.306183] acpiphp: Slot [24] registered [ 0.308112] acpiphp: Slot [25] registered [ 0.310088] acpiphp: Slot [26] registered [ 0.311102] acpiphp: Slot [27] registered [ 0.313091] acpiphp: Slot [28] registered [ 0.314076] acpiphp: Slot [29] registered [ 0.316080] acpiphp: Slot [30] registered [ 0.317094] acpiphp: Slot [31] registered [ 0.319047] PCI host bridge to bus 0000:00 [ 0.320013] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.323015] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.325018] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.328027] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.331018] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.333208] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.335316] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.339151] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.342585] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.350013] pci 0000:00:01.1: reg 0x20: [io 0xc120-0xc12f] [ 0.356176] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.359062] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.361022] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.364015] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.367686] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.369856] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.372037] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.376238] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.379973] pci 0000:00:02.0: reg 0x10: [io 0xc100-0xc11f] [ 0.388016] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.393014] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.398233] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.406015] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.410799] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.424015] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.434967] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.442012] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.448000] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.461014] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.473332] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.475482] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.477393] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.480324] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.483173] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.488684] iommu: Default domain type: Passthrough [ 0.491543] SCSI subsystem initialized [ 0.493100] ACPI: bus type USB registered [ 0.495099] usbcore: registered new interface driver usbfs [ 0.497043] usbcore: registered new interface driver hub [ 0.500091] usbcore: registered new device driver usb [ 0.502135] pps_core: LinuxPPS API ver. 1 registered [ 0.504009] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.508095] PTP clock support registered [ 0.512042] EDAC MC: Ver: 3.0.0 [ 0.513137] PCI: Using ACPI for IRQ routing [ 0.516038] NetLabel: Initializing [ 0.517005] NetLabel: domain hash size = 128 [ 0.518007] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.520083] NetLabel: unlabeled traffic allowed by default [ 0.522273] vgaarb: loaded [ 0.523388] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.525011] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.531349] clocksource: Switched to clocksource kvm-clock [ 0.647084] VFS: Disk quotas dquot_6.6.0 [ 0.649380] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.651358] *** VALIDATE ramfs *** [ 0.652349] *** VALIDATE hugetlbfs *** [ 0.653659] pnp: PnP ACPI init [ 0.657910] pnp: PnP ACPI: found 6 devices [ 0.680398] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.686341] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.688019] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.689556] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.693322] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.695949] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.698187] NET: Registered protocol family 2 [ 0.703486] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.708321] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.711175] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.718589] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.721280] TCP: Hash tables configured (established 65536 bind 65536) [ 0.723659] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.728610] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.731089] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.733510] NET: Registered protocol family 1 [ 0.736395] RPC: Registered named UNIX socket transport module. [ 0.739034] RPC: Registered udp transport module. [ 0.740485] RPC: Registered tcp transport module. [ 0.741752] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.745696] NET: Registered protocol family 44 [ 0.747065] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.748605] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.753307] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.755249] PCI: CLS 0 bytes, default 64 [ 0.757234] Unpacking initramfs... [ 2.686805] debug: unmapping init [mem 0xffff88f7fcc64000-0xffff88f7fffcffff] [ 2.698172] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.701399] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.709267] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 3.510095] Initialise system trusted keyrings [ 3.514204] Key type blacklist registered [ 3.516329] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 3.528250] zbud: loaded [ 3.531106] *** VALIDATE nfs *** [ 3.532346] *** VALIDATE nfs4 *** [ 3.533761] pstore: using deflate compression [ 3.540402] Platform Keyring initialized [ 3.686281] NET: Registered protocol family 38 [ 3.688178] Key type asymmetric registered [ 3.689657] Asymmetric key parser 'x509' registered [ 3.692310] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 3.695946] io scheduler mq-deadline registered [ 3.698046] io scheduler kyber registered [ 3.700779] io scheduler bfq registered [ 3.702853] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 3.707260] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 3.714197] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 3.716604] ACPI: Power Button [PWRF] [ 3.727740] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 3.746196] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 3.766546] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 3.821956] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.862192] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.868355] Non-volatile memory driver v1.3 [ 3.870539] Linux agpgart interface v0.103 [ 3.917903] virtio_blk virtio1: [vda] 146208 512-byte logical blocks (74.9 MB/71.4 MiB) [ 3.920458] vda: detected capacity change from 0 to 74858496 [ 3.942114] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.947676] vdb: detected capacity change from 0 to 1073741824 [ 3.953108] libphy: Fixed MDIO Bus: probed [ 3.958479] usbcore: registered new interface driver usbserial_generic [ 3.962102] usbserial: USB Serial support registered for generic [ 3.966225] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.973493] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.976471] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.981726] mousedev: PS/2 mouse device common for all mice [ 3.984530] rtc_cmos 00:05: RTC can wake from S4 [ 3.988980] rtc_cmos 00:05: registered as rtc0 [ 3.990658] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.993481] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.994037] intel_pstate: CPU model not supported [ 4.002817] hid: raw HID events driver (C) Jiri Kosina [ 4.007148] usbcore: registered new interface driver usbhid [ 4.009338] usbhid: USB HID core driver [ 4.010670] drop_monitor: Initializing network drop monitor service [ 4.014815] Initializing XFRM netlink socket [ 4.017113] NET: Registered protocol family 10 [ 4.021266] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 4.027360] Segment Routing with IPv6 [ 4.030274] NET: Registered protocol family 17 [ 4.033083] mpls_gso: MPLS GSO support [ 4.039019] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 4.041218] RAS: Correctable Errors collector initialized. [ 4.049361] AVX version of gcm_enc/dec engaged. [ 4.051208] AES CTR mode by8 optimization enabled [ 4.150723] sched_clock: Marking stable (4150559270, 0)->(5372015289, -1221456019) [ 4.155177] registered taskstats version 1 [ 4.157106] Loading compiled-in X.509 certificates [ 4.160282] zswap: loaded using pool lzo/zbud [ 4.190992] Key type big_key registered [ 4.203878] Key type encrypted registered [ 4.205586] ima: No TPM chip found, activating TPM-bypass! [ 4.207802] ima: Allocated hash algorithm: sha1 [ 4.209509] ima: No architecture policies found [ 4.211320] evm: Initialising EVM extended attributes: [ 4.213159] evm: security.selinux [ 4.214315] evm: security.ima [ 4.215532] evm: security.capability [ 4.216788] evm: HMAC attrs: 0x1 [ 4.219247] rtc_cmos 00:05: setting system clock to 2026-08-24 05:13:23 UTC (1787548403) [ 4.225895] debug: unmapping init [mem 0xffffffff92a03000-0xffffffff92bfffff] [ 4.229261] debug: unmapping init [mem 0xffffffff91782000-0xffffffff91a58fff] [ 4.238235] Write protecting the kernel read-only data: 28672k [ 4.242714] debug: unmapping init [mem 0xffffffff8fe03000-0xffffffff8fffffff] [ 4.245943] debug: unmapping init [mem 0xffffffff90714000-0xffffffff907fffff] [ 4.293238] 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) [ 4.304981] systemd[1]: Detected virtualization kvm. [ 4.309306] systemd[1]: Detected architecture x86-64. [ 4.313391] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 4.344263] systemd[1]: No hostname configured. [ 4.345950] systemd[1]: Set hostname to . [ 4.351959] random: systemd: uninitialized urandom read (16 bytes read) [ 4.355412] systemd[1]: Initializing machine ID from random generator. [ 4.443113] random: ln: uninitialized urandom read (6 bytes read) [ 4.677632] random: systemd: uninitialized urandom read (16 bytes read) [ 4.683653] systemd[1]: Listening on udev Kernel Socket. [ OK ] Listening on udev Kernel Socket. [ 4.694878] systemd[1]: Reached target Swap. [ OK ] Reached target Swap. [ 4.700955] systemd[1]: Reached target Slices. [ OK ] Reached target Slices. [ OK ] Reached target Timers. [ OK ] Listening on Journal Socket. Starting Setup Virtual Console... [ OK ] Started Memstrack Anylazing Service. Starting Create list of required st…ce nodes for the current kernel... Starting Apply Kernel Variables... [ OK ] Reached target Initrd Root Device. [ OK ] Listening on udev Control Socket. [ OK ] Listening on Journal Socket (/dev/log). Starting Journal Service... [ OK ] Reached target Sockets. [ OK ] Reached target Local File Systems. Starting Create Volatile Files and Directories... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Paths. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Started Setup Virtual Console. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Apply Kernel Variables. [ OK ] Started Create Volatile Files and Directories. Starting Create Static Device Nodes in /dev... Starting dracut cmdline hook... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started Journal Service. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 5.834876] device-mapper: uevent: version 1.0.3 [ 5.839415] device-mapper: ioctl: 4.46.0-ioctl (2022-02-22) initialised: dm-devel@redhat.com [ OK ] Started dracut pre-udev hook. Starting udev Kernel Device Manager... [ OK ] Started udev Kernel Device Manager. Starting dracut pre-trigger hook... [ OK ] Started dracut pre-trigger hook. Starting udev Coldplug all Devices... Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting dracut initqueue hook... [ 7.025100] virtio_net virtio0 ens2: renamed from eth0 [ 7.511669] scsi host0: ata_piix [ 7.617856] scsi host1: ata_piix [ 7.624776] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc120 irq 14 [ 7.630442] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc128 irq 15 [ 10.707066] random: fast init done [ 11.733294] random: crng init done [ 11.734427] random: 7 urandom warning(s) missed due to ratelimiting [ 12.240538] dracut-initqueue[585]: RTNETLINK answers: File exists Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Mounting /sysroot... [ 13.790168] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped target Timers. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target 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 Hardware RNG Entropy Gatherer Daemon. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped target Basic System. [ OK ] Stopped target Paths. [ OK ] Stopped target System Initialization. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. [ OK ] Stopped target Swap. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped Apply Kernel Variables. Stopping udev Kernel Device Manager... [ OK ] Stopped target Local File Systems. [ OK ] Stopped target Sockets. [ OK ] Stopped target Slices. [ 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... [ 15.840352] printk: systemd: 26 output lines suppressed due to ratelimiting [ 16.472659] SELinux: Disabled at runtime. [ 16.559216] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 16.572893] systemd[1]: Detected virtualization kvm. [ 16.576404] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 17.775778] systemd[1]: initrd-switch-root.service: Succeeded. [ 17.786323] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 17.796669] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 17.804530] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 17.810818] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 17.832376] systemd[1]: Starting Journal Service... Starting Journal Service... [ 17.867375] systemd[1]: Listening on RPCbind Server Activation Socket. [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Created slice User and Session Slice. [ OK ] Listening on Process Core Dump Socket. [ OK ] Listening on udev Kernel Socket. [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Reached target rpc_pipefs.target. [ OK ] Created slice system-getty.slice. [ OK ] Created slice system-sshd\x2dkeygen.slice. Starting Remount Root and Kernel File Systems... [ OK ] Listening on initctl Compatibility Named Pipe. Starting Apply Kernel Variables... Activating swap /dev/disk/by-label/SWAP... [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Listening on udev Control Socket. Starting udev Coldplug all Devices... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Paths. [ 18.215387] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS Starting Create list of required st…ce nodes for the current kernel... [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd Root File System. [ OK ] Stopped target Initrd File Systems. Mounting Kernel Debug File System... [ OK ] Reached target Slices. Mounting POSIX Message Queue File System... [ OK ] Reached target Local Encrypted Volumes. Mounting Huge Pages File System... [ OK ] Reached target RPC Port Mapper. [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Started Journal Service. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Started Apply Kernel Variables. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Mounted Kernel Debug File System. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Mounted Huge Pages File System. [ OK ] Reached target Swap. Starting Configure read-only root support... Starting Create Static Device Nodes in /dev... Starting Flush Journal to Persistent Storage... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started udev Coldplug all Devices. [ OK ] Started Create Static Device Nodes in /dev. Starting udev Kernel Device Manager... [ OK ] Reached target Local File Systems (Pre). Mounting /home/green/git/lustre-release... Mounting /mnt... [ OK ] Mounted /mnt. [ 19.203679] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 19.981219] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 20.021228] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 20.776935] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 20.834025] EDAC sbridge: Ver: 1.1.2 [ 23.396443] Key type dns_resolver registered [ 23.883643] NFS: Registering the id_resolver key type [ 23.886370] Key type id_resolver registered [ 23.888528] 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 Load/Save Random Seed... Starting Create Volatile Files and Directories... [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Load/Save Random Seed. [ OK ] Started Create Volatile Files and Directories. Starting Update UTMP about System Boot/Shutdown... Starting RPC Bind... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Reached target Basic System. Starting Restore /run/initramfs on shutdown... [ OK ] Started daily update of the root trust anchor for DNSSEC. Starting Login Service... [ OK ] Started D-Bus System Message Bus. Starting Network Manager... [ OK ] Started irqbalance daemon. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Started dnf makecache --timer. [ OK ] Reached target Timers. [ OK ] Reached target sshd-keygen.target. [ 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 GSSAPI Proxy Daemon... Starting Dynamic System Tuning Daemon... Starting OpenSSH server 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 Getty on tty1. [ OK ] Started Serial Getty on ttyS1. [ OK ] Started Serial Getty on ttyS0. [ OK ] Reached target Login Prompts. [ OK ] Started Command Scheduler. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting System Logging Service... Starting Notify NFS peers of a restart... Starting Crash recovery kernel arming... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Starting Authorization Manager... Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg629-client login: [ 51.934560] hrtimer: interrupt took 4549702 ns [ 94.439246] libcfs: loading out-of-tree module taints kernel. [ 94.901280] Key type ._llcrypt registered [ 94.904292] Key type .llcrypt registered [ 96.632954] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [ 96.752222] alg: No test for adler32 (adler32-zlib) [ 99.131712] Lustre: Lustre: Build Version: 2.17.57_82_g53f9976 [ 102.267383] LNet: Added LNI 192.168.206.29@tcp [8/256/0/180] [ 104.047178] Key type lgssc registered [ 107.936677] Lustre: Echo OBD driver; http://www.lustre.org/ [ 244.659391] Lustre: Mounted lustre-client - version 2.17.57_82_g53f9976 [ 249.534631] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 261.145550] Lustre: DEBUG MARKER: oleg629-client.virtnet: executing check_logdir /tmp/testlogs/ [ 265.503706] Lustre: DEBUG MARKER: oleg629-client.virtnet: executing yml_node [ 270.020455] Lustre: DEBUG MARKER: Client: 2.17.57.82 [ 270.303384] Lustre: lustre-OST0000-osc-ffff88f8594f0800: disconnect after 23s idle [ 272.485690] Lustre: DEBUG MARKER: MDS: 2.17.57.82 [ 274.679530] Lustre: DEBUG MARKER: OSS: 2.17.57.82 [ 276.504668] Lustre: DEBUG MARKER: -----============= acceptance-small: recovery-small ============----- Mon Aug 24 01:17:54 EDT 2026 [ 291.561838] Lustre: DEBUG MARKER: excepting tests: 136 [ 293.162768] Lustre: DEBUG MARKER: === recovery-small: start setup 01:18:11 (1787548691) === [ 298.118222] Lustre: DEBUG MARKER: oleg629-client.virtnet: executing check_config_client /mnt/lustre [ 313.111715] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 323.661638] Lustre: DEBUG MARKER: === recovery-small: finish setup 01:18:41 (1787548721) === [ 325.514837] Lustre: DEBUG MARKER: == recovery-small test 1: create, chmod, stat: drop req, drop rep ========================================================== 01:18:43 (1787548723) [ 341.983286] Lustre: 10017:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787548725/real 1787548725] req@ffff88f851233b80 x1874380456995968/t0(0) o700->lustre-MDT0000-mdc-ffff88f8594f0800@192.168.206.129@tcp:30/10 lens 264/248 e 0 to 1 dl 1787548741 ref 2 fl Rpc:XQr/200/ffffffff rc 0/-1 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 342.035822] Lustre: lustre-MDT0000-mdc-ffff88f8594f0800: Connection to lustre-MDT0000 (at 192.168.206.129@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 342.086585] Lustre: lustre-MDT0000-mdc-ffff88f8594f0800: Connection restored to 192.168.206.129@tcp (at 192.168.206.129@tcp) [ 359.903145] Lustre: 10037:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787548743/real 1787548743] req@ffff88f843067800 x1874380456997888/t0(0) o36->lustre-MDT0000-mdc-ffff88f8594f0800@192.168.206.129@tcp:12/10 lens 520/576 e 0 to 1 dl 1787548759 ref 2 fl Rpc:XQr/200/ffffffff rc 0/-1 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 359.923551] Lustre: lustre-MDT0000-mdc-ffff88f8594f0800: Connection to lustre-MDT0000 (at 192.168.206.129@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 359.975298] Lustre: lustre-MDT0000-mdc-ffff88f8594f0800: Connection restored to 192.168.206.129@tcp (at 192.168.206.129@tcp) [ 378.335182] Lustre: 10064:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787548761/real 1787548761] req@ffff88f843067800 x1874380456999168/t0(0) o101->lustre-MDT0000-mdc-ffff88f8594f0800@192.168.206.129@tcp:12/10 lens 576/1152 e 0 to 1 dl 1787548777 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'tchmod.0' uid:0 gid:0 projid:0 [ 378.367751] Lustre: lustre-MDT0000-mdc-ffff88f8594f0800: Connection to lustre-MDT0000 (at 192.168.206.129@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 378.414919] Lustre: lustre-MDT0000-mdc-ffff88f8594f0800: Connection restored to 192.168.206.129@tcp (at 192.168.206.129@tcp) [ 397.281818] Lustre: 10084:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787548780/real 1787548780] req@ffff88f851299f80 x1874380457001344/t0(0) o36->lustre-MDT0000-mdc-ffff88f8594f0800@192.168.206.129@tcp:12/10 lens 488/512 e 0 to 1 dl 1787548796 ref 2 fl Rpc:XQr/200/ffffffff rc 0/-1 job:'tchmod.0' uid:0 gid:0 projid:4294967295 [ 397.308327] Lustre: lustre-MDT0000-mdc-ffff88f8594f0800: Connection to lustre-MDT0000 (at 192.168.206.129@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 397.370393] Lustre: lustre-MDT0000-mdc-ffff88f8594f0800: Connection restored to 192.168.206.129@tcp (at 192.168.206.129@tcp) [ 416.223427] Lustre: 10110:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787548799/real 1787548799] req@ffff88f843065880 x1874380457002624/t0(0) o34->lustre-MDT0000-mdc-ffff88f8594f0800@192.168.206.129@tcp:12/10 lens 472/728 e 0 to 1 dl 1787548815 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'statone.0' uid:0 gid:0 projid:0 [ 416.257077] Lustre: lustre-MDT0000-mdc-ffff88f8594f0800: Connection to lustre-MDT0000 (at 192.168.206.129@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 416.309248] Lustre: lustre-MDT0000-mdc-ffff88f8594f0800: Connection restored to 192.168.206.129@tcp (at 192.168.206.129@tcp) [ 435.167220] Lustre: 10131:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787548818/real 1787548818] req@ffff88f85129a300 x1874380457003904/t0(0) o34->lustre-MDT0000-mdc-ffff88f8594f0800@192.168.206.129@tcp:12/10 lens 472/728 e 0 to 1 dl 1787548834 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'statone.0' uid:0 gid:0 projid:0 [ 435.201909] Lustre: lustre-MDT0000-mdc-ffff88f8594f0800: Connection to lustre-MDT0000 (at 192.168.206.129@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 435.281974] Lustre: lustre-MDT0000-mdc-ffff88f8594f0800: Connection restored to 192.168.206.129@tcp (at 192.168.206.129@tcp) [ 443.185928] Lustre: DEBUG MARKER: == recovery-small test 4: open: drop req, drop rep ======= 01:20:40 (1787548840) [ 459.745952] Lustre: 10736:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787548843/real 1787548843] req@ffff88f843065880 x1874380457006208/t0(0) o101->lustre-MDT0000-mdc-ffff88f8594f0800@192.168.206.129@tcp:12/10 lens 576/1152 e 0 to 1 dl 1787548859 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'cat.0' uid:0 gid:0 projid:0 [ 459.771936] Lustre: lustre-MDT0000-mdc-ffff88f8594f0800: Connection to lustre-MDT0000 (at 192.168.206.129@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 459.812070] Lustre: lustre-MDT0000-mdc-ffff88f8594f0800: Connection restored to 192.168.206.129@tcp (at 192.168.206.129@tcp) [ 488.483387] Lustre: DEBUG MARKER: == recovery-small test 5: rename: drop req, drop rep ===== 01:21:25 (1787548885) [ 506.335324] Lustre: 11357:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787548889/real 1787548889] req@ffff88f851299500 x1874380457012608/t0(0) o101->lustre-MDT0000-mdc-ffff88f8594f0800@192.168.206.129@tcp:12/10 lens 576/1152 e 0 to 1 dl 1787548905 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'mv.0' uid:0 gid:0 projid:0 [ 506.355861] Lustre: 11357:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 506.367182] Lustre: lustre-MDT0000-mdc-ffff88f8594f0800: Connection to lustre-MDT0000 (at 192.168.206.129@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 506.376803] Lustre: Skipped 1 previous similar message [ 506.443094] Lustre: lustre-MDT0000-mdc-ffff88f8594f0800: Connection restored to 192.168.206.129@tcp (at 192.168.206.129@tcp) [ 506.450509] Lustre: Skipped 1 previous similar message [ 533.021373] Lustre: DEBUG MARKER: == recovery-small test 6: link, unlink: drop req, drop rep ========================================================== 01:22:10 (1787548930) [ 549.855759] Lustre: lustre-OST0000-osc-ffff88f8594f0800: disconnect after 20s idle [ 549.860789] Lustre: Skipped 1 previous similar message [ 586.207157] Lustre: 12037:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787548969/real 1787548969] req@ffff88f843065500 x1874380457025664/t0(0) o101->lustre-MDT0000-mdc-ffff88f8594f0800@192.168.206.129@tcp:12/10 lens 576/1152 e 0 to 1 dl 1787548985 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'unlink.0' uid:0 gid:0 projid:0 [ 586.234174] Lustre: 12037:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 586.240635] Lustre: lustre-MDT0000-mdc-ffff88f8594f0800: Connection to lustre-MDT0000 (at 192.168.206.129@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 586.257583] Lustre: Skipped 3 previous similar messages [ 586.319462] Lustre: lustre-MDT0000-mdc-ffff88f8594f0800: Connection restored to 192.168.206.129@tcp (at 192.168.206.129@tcp) [ 586.332773] Lustre: Skipped 3 previous similar messages [ 614.233929] Lustre: DEBUG MARKER: == recovery-small test 8: touch: drop rep (bug 1423) ===== 01:23:31 (1787549011) [ 639.069275] Lustre: DEBUG MARKER: == recovery-small test 9: pause bulk on OST (bug 1420) === 01:23:56 (1787549036) [ 654.830670] Lustre: DEBUG MARKER: == recovery-small test 10a: finish request on server after client eviction (bug 1521) ========================================================== 01:24:12 (1787549052) [ 655.281519] Lustre: *** cfs_fail_loc=305, val=0*** [ 658.597317] Lustre: *** cfs_fail_loc=305, val=0*** [ 671.711467] Lustre: lustre-OST0000-osc-ffff88f8594f0800: disconnect after 23s idle [ 671.956654] Lustre: *** cfs_fail_loc=305, val=0*** [ 673.984141] Lustre: *** cfs_fail_loc=305, val=0*** [ 688.311655] Lustre: *** cfs_fail_loc=305, val=0*** [ 690.357718] Lustre: *** cfs_fail_loc=305, val=0*** [ 704.697892] Lustre: *** cfs_fail_loc=305, val=0*** [ 706.709347] Lustre: *** cfs_fail_loc=305, val=0*** [ 720.090200] Lustre: *** cfs_fail_loc=305, val=0*** [ 722.069052] Lustre: *** cfs_fail_loc=305, val=0*** [ 736.489708] Lustre: *** cfs_fail_loc=305, val=0*** [ 738.449939] Lustre: *** cfs_fail_loc=305, val=0*** [ 752.792869] Lustre: *** cfs_fail_loc=305, val=0*** [ 754.840398] Lustre: *** cfs_fail_loc=305, val=0*** [ 768.579346] LustreError: lustre-MDT0000-mdc-ffff88f8594f0800: operation ldlm_enqueue to node 192.168.206.129@tcp failed: rc = -107 [ 768.595273] Lustre: lustre-MDT0000-mdc-ffff88f8594f0800: Connection to lustre-MDT0000 (at 192.168.206.129@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 768.611748] Lustre: Skipped 2 previous similar messages [ 768.624452] LustreError: lustre-MDT0000-mdc-ffff88f8594f0800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 768.636972] LustreError: 13969:0:(ldlm_resource.c:1207:ldlm_resource_complain()) lustre-MDT0000-mdc-ffff88f8594f0800: namespace resource [0x200000007:0x1:0x0].0x0 (ffff88f843aec900) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 768.667345] Lustre: lustre-MDT0000-mdc-ffff88f8594f0800: Connection restored to 192.168.206.129@tcp (at 192.168.206.129@tcp) [ 768.688195] Lustre: Skipped 2 previous similar messages [ 774.142772] Lustre: lustre-OST0001-osc-ffff88f8594f0800: Connection to lustre-OST0001 (at 192.168.206.129@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 774.197527] LustreError: lustre-OST0001-osc-ffff88f8594f0800: This client was evicted by lustre-OST0001; in progress operations using this service will fail. [ 774.212825] Lustre: lustre-OST0001-osc-ffff88f8594f0800: Connection restored to 192.168.206.129@tcp (at 192.168.206.129@tcp) [ 778.989943] Lustre: DEBUG MARKER: == recovery-small test 10b: re-send BL AST =============== 01:26:16 (1787549176) [ 794.591589] Lustre: lustre-OST0000-osc-ffff88f8594f0800: disconnect after 23s idle [ 804.932356] Lustre: DEBUG MARKER: == recovery-small test 10c: re-send BL AST vs reconnect race (LU-5569) ========================================================== 01:26:42 (1787549202) [ 815.084432] Lustre: DEBUG MARKER: == recovery-small test 10d: test failed blocking ast ===== 01:26:52 (1787549212) [ 818.674909] Lustre: Unmounted lustre-client [ 819.061601] Lustre: Mounted lustre-client - version 2.17.57_82_g53f9976 [ 820.573802] LustreError: lustre-OST0000-osc-ffff88f845066000: operation ost_statfs to node 192.168.206.129@tcp failed: rc = -107 [ 820.584852] LustreError: lustre-OST0000-osc-ffff88f845066000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 820.593450] Lustre: 2362:0:(llite_lib.c:4342:ll_dirty_page_discard_warn()) lustre: dirty page discard: 192.168.206.129@tcp:/lustre/fid: [0x200000403:0x1:0x0]/ may get corrupted (rc -108) [ 823.386238] Lustre: Unmounted lustre-client [ 829.351469] Lustre: DEBUG MARKER: == recovery-small test 10e: re-send BL AST vs reconnect race 2 ========================================================== 01:27:07 (1787549227) [ 831.065199] Lustre: DEBUG MARKER: SKIP: recovery-small test_10e need two clients [ 832.781493] Lustre: DEBUG MARKER: == recovery-small test 11: wake up a thread waiting for completion after eviction (b=2460) ========================================================== 01:27:10 (1787549230) [ 858.796656] Lustre: DEBUG MARKER: == recovery-small test 12: recover from timed out resend in ptlrpcd (b=2494) ========================================================== 01:27:36 (1787549256) [ 858.864871] Lustre: DEBUG MARKER: multiop /mnt/lustre/f12.recovery-small OS_c [ 876.511246] Lustre: 17644:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787549259/real 1787549259] req@ffff88f851299c00 x1874380457094144/t0(0) o35->lustre-MDT0000-mdc-ffff88f845066000@192.168.206.129@tcp:23/10 lens 392/624 e 0 to 1 dl 1787549275 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'multiop.0' uid:0 gid:0 projid:0 [ 876.536666] Lustre: 17644:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 903.000952] Lustre: DEBUG MARKER: == recovery-small test 13: mdc_readpage restart test (bug 1138) ========================================================== 01:28:20 (1787549300) [ 928.894736] Lustre: DEBUG MARKER: == recovery-small test 14: mdc_readpage resend test (bug 1138) ========================================================== 01:28:46 (1787549326) [ 938.592067] Lustre: DEBUG MARKER: == recovery-small test 15: failed open (-ENOMEM) ========= 01:28:56 (1787549336) [ 947.450387] Lustre: DEBUG MARKER: == recovery-small test 16: timeout bulk put, don't evict client (2732) ========================================================== 01:29:04 (1787549344) [ 994.405864] Lustre: DEBUG MARKER: == recovery-small test 17a: timeout bulk get, don't evict client (2732) ========================================================== 01:29:52 (1787549392) [ 1047.865780] Lustre: DEBUG MARKER: == recovery-small test 17b: timeout bulk get, dont evict client (3582) ========================================================== 01:30:45 (1787549445) [ 1049.404242] Lustre: DEBUG MARKER: SKIP: recovery-small test_17b Needs multiple clients [ 1051.252490] Lustre: DEBUG MARKER: == recovery-small test 18a: manual ost invalidate clears page cache immediately ========================================================== 01:30:49 (1787549449) [ 1052.289832] Lustre: setting import lustre-OST0001_UUID INACTIVE by administrator request [ 1052.365023] LustreError: lustre-OST0001-osc-ffff88f845066000: This client was evicted by lustre-OST0001; in progress operations using this service will fail. [ 1059.340089] Lustre: DEBUG MARKER: == recovery-small test 18b: eviction and reconnect clears page cache (2766) ========================================================== 01:30:56 (1787549456) [ 1062.929675] LustreError: lustre-OST0000-osc-ffff88f845066000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 1091.000686] Lustre: DEBUG MARKER: == recovery-small test 18c: Dropped connect reply after eviction handing (14755) ========================================================== 01:31:28 (1787549488) [ 1093.617322] LustreError: lustre-OST0000-osc-ffff88f845066000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 1113.165338] Lustre: DEBUG MARKER: == recovery-small test 19a: test expired_lock_main on mds (2867) ========================================================== 01:31:51 (1787549511) [ 1113.715648] Lustre: Mounted lustre-client - version 2.17.57_82_g53f9976 [ 1113.722462] Lustre: Skipped 1 previous similar message [ 1147.679120] Lustre: 2362:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787549530/real 1787549530] req@ffff88f843065c00 x1874380457151488/t0(0) o103->lustre-MDT0000-mdc-ffff88f845066000@192.168.206.129@tcp:17/18 lens 328/224 e 0 to 1 dl 1787549546 ref 1 fl Rpc:XQr/202/ffffffff rc 0/-1 job:'ldlm_bl.0' uid:0 gid:0 projid:4294967295 [ 1147.705163] Lustre: 2362:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 1217.565394] LustreError: lustre-MDT0000-mdc-ffff88f845066000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 1217.575209] LustreError: 23894:0:(file.c:251:ll_close_inode_openhandle()) lustre-clilmv-ffff88f845066000: inode [0x200000403:0x1:0x0] mdc close failed: rc = -108 [ 1217.589369] LustreError: 23894:0:(ldlm_resource.c:1207:ldlm_resource_complain()) lustre-MDT0000-mdc-ffff88f845066000: namespace resource [0x200000007:0x1:0x0].0x0 (ffff88f8591b8000) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 1217.589869] LustreError: 23893:0:(file.c:6167:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 1218.909977] Lustre: Unmounted lustre-client [ 1226.194411] Lustre: DEBUG MARKER: == recovery-small test 19b: test expired_lock_main on ost (2867) ========================================================== 01:33:44 (1787549624) [ 1226.519472] Lustre: Mounted lustre-client - version 2.17.57_82_g53f9976 [ 1293.279297] Lustre: lustre-OST0001-osc-ffff88f845066000: Connection to lustre-OST0001 (at 192.168.206.129@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1293.298843] Lustre: Skipped 18 previous similar messages [ 1293.327957] Lustre: lustre-OST0001-osc-ffff88f845066000: Connection restored to 192.168.206.129@tcp (at 192.168.206.129@tcp) [ 1293.341949] Lustre: Skipped 15 previous similar messages [ 1335.308155] LustreError: lustre-OST0001-osc-ffff88f845066000: This client was evicted by lustre-OST0001; in progress operations using this service will fail. [ 1335.358701] Lustre: Unmounted lustre-client [ 1342.818400] Lustre: DEBUG MARKER: == recovery-small test 19c: check reconnect and lock resend do not trigger expired_lock_main ========================================================== 01:35:40 (1787549740) [ 1343.511244] Lustre: Mounted lustre-client - version 2.17.57_82_g53f9976 [ 1349.125067] Lustre: Unmounted lustre-client [ 1361.055527] Lustre: DEBUG MARKER: == recovery-small test 20a: ldlm_handle_enqueue error (should return error) ========================================================== 01:35:59 (1787549759) [ 1362.304471] LustreError: lustre-OST0000-osc-ffff88f845066000: operation ldlm_enqueue to node 192.168.206.129@tcp failed: rc = -12 [ 1368.322842] Lustre: DEBUG MARKER: == recovery-small test 20b: ldlm_handle_enqueue error (should return error) ========================================================== 01:36:06 (1787549766) [ 1369.815182] LustreError: lustre-OST0000-osc-ffff88f845066000: operation ldlm_enqueue to node 192.168.206.129@tcp failed: rc = -12 [ 1375.313334] Lustre: DEBUG MARKER: == recovery-small test 21a: drop close request while close and open are both in flight ========================================================== 01:36:13 (1787549773) [ 1402.572692] Lustre: DEBUG MARKER: == recovery-small test 21b: drop open request while close and open are both in flight ========================================================== 01:36:40 (1787549800) [ 1545.233922] Lustre: DEBUG MARKER: == recovery-small test 21c: drop both request while close and open are both in flight ========================================================== 01:39:03 (1787549943) [ 1574.423389] Lustre: DEBUG MARKER: == recovery-small test 21d: drop close reply while close and open are both in flight ========================================================== 01:39:32 (1787549972) [ 1601.519408] Lustre: DEBUG MARKER: == recovery-small test 21e: drop open reply while close and open are both in flight ========================================================== 01:39:59 (1787549999) [ 1737.695151] Lustre: 29640:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787550001/real 1787550001] req@ffff88f851232680 x1874380457261824/t0(0) o36->lustre-MDT0000-mdc-ffff88f845066000@192.168.206.129@tcp:12/10 lens 488/512 e 0 to 1 dl 1787550136 ref 2 fl Rpc:XQr/200/ffffffff rc 0/-1 job:'touch.0' uid:0 gid:0 projid:4294967295 [ 1737.737060] Lustre: 29640:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 14 previous similar messages [ 1739.332773] Lustre: DEBUG MARKER: == recovery-small test 21f: drop both reply while close and open are both in flight ========================================================== 01:42:17 (1787550137) [ 1766.433350] Lustre: DEBUG MARKER: == recovery-small test 21g: drop open reply and close request while close and open are both in flight ========================================================== 01:42:44 (1787550164) [ 1792.157813] Lustre: DEBUG MARKER: == recovery-small test 21h: drop open request and close reply while close and open are both in flight ========================================================== 01:43:10 (1787550190) [ 1816.094986] Lustre: DEBUG MARKER: == recovery-small test 22: drop close request and do mknod ========================================================== 01:43:34 (1787550214) [ 1840.562453] Lustre: DEBUG MARKER: == recovery-small test 23: client hang when close a file after mds crash ========================================================== 01:43:57 (1787550237) [ 1870.303281] LustreError: MGC192.168.206.129@tcp: Connection to MGS (at 192.168.206.129@tcp) was lost; in progress operations using this service will fail [ 1870.344111] Lustre: Evicted from MGS (at 192.168.206.129@tcp) after server handle changed from 0x1555eafd93092cb to 0x1555eafd930b7c3 [ 1885.864667] Lustre: DEBUG MARKER: oleg629-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1887.275177] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1895.799890] Lustre: DEBUG MARKER: == recovery-small test 24a: fsync error (should return error) ========================================================== 01:44:53 (1787550293) [ 1897.485241] LustreError: lustre-OST0000-osc-ffff88f845066000: operation ost_write to node 192.168.206.129@tcp failed: rc = -107 [ 1897.505801] Lustre: lustre-OST0000-osc-ffff88f845066000: Connection to lustre-OST0000 (at 192.168.206.129@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1897.525819] Lustre: Skipped 13 previous similar messages [ 1897.549408] LustreError: lustre-OST0000-osc-ffff88f845066000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 1897.573713] Lustre: 2365:0:(llite_lib.c:4342:ll_dirty_page_discard_warn()) lustre: dirty page discard: 192.168.206.129@tcp:/lustre/fid: [0x200000404:0x30:0x0]// may get corrupted (rc -5) [ 1905.264391] Lustre: DEBUG MARKER: == recovery-small test 24b: test dirty page discard due to client eviction ========================================================== 01:45:02 (1787550302) [ 1907.644186] LustreError: lustre-OST0000-osc-ffff88f845066000: operation ost_sync to node 192.168.206.129@tcp failed: rc = -107 [ 1907.689747] LustreError: lustre-OST0000-osc-ffff88f845066000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 1907.738829] Lustre: lustre-OST0000-osc-ffff88f845066000: Connection restored to 192.168.206.129@tcp (at 192.168.206.129@tcp) [ 1907.752085] Lustre: Skipped 14 previous similar messages [ 1909.816698] Lustre: DEBUG MARKER: recovery-small test_24b: @@@@@@ IGNORE (bz5494): multiop didn't fail fsync: 5 or close: 0 [ 1914.474487] Lustre: DEBUG MARKER: recovery-small test_24b: @@@@@@ FAIL: no discarded dirty page found! [ 1936.740622] Lustre: DEBUG MARKER: == recovery-small test 26a: evict dead exports =========== 01:45:34 (1787550334) [ 1939.132857] Lustre: DEBUG MARKER: SKIP: recovery-small test_26a msg and ost1 are at the same node [ 1941.690971] Lustre: DEBUG MARKER: == recovery-small test 26b: evict dead exports =========== 01:45:39 (1787550339) [ 1944.437245] Lustre: DEBUG MARKER: SKIP: recovery-small test_26b msg and ost1 are at the same node [ 1946.326840] Lustre: DEBUG MARKER: == recovery-small test 27: fail LOV while using OSC's ==== 01:45:44 (1787550344) [ 1950.631747] LustreError: lustre-MDT0000-mdc-ffff88f845066000: operation ldlm_enqueue to node 192.168.206.129@tcp failed: rc = -19 [ 1971.679314] LustreError: MGC192.168.206.129@tcp: Connection to MGS (at 192.168.206.129@tcp) was lost; in progress operations using this service will fail [ 1980.851624] Lustre: Evicted from MGS (at 192.168.206.129@tcp) after server handle changed from 0x1555eafd930b7c3 to 0x1555eafd930d1e7 [ 2083.073456] LustreError: lustre-MDT0000-mdc-ffff88f845066000: operation ldlm_enqueue to node 192.168.206.129@tcp failed: rc = -19 [ 2102.751298] LustreError: MGC192.168.206.129@tcp: Connection to MGS (at 192.168.206.129@tcp) was lost; in progress operations using this service will fail [ 2102.786852] Lustre: Evicted from MGS (at 192.168.206.129@tcp) after server handle changed from 0x1555eafd930d1e7 to 0x1555eafd932d0fc [ 2128.757705] Lustre: DEBUG MARKER: == recovery-small test 28: handle error adding new clients (bug 6086) ========================================================== 01:48:46 (1787550526) [ 2129.132963] Lustre: *** cfs_fail_loc=305, val=0*** [ 2129.138086] Lustre: Skipped 4 previous similar messages [ 2169.315555] LustreError: MGC192.168.206.129@tcp: Connection to MGS (at 192.168.206.129@tcp) was lost; in progress operations using this service will fail [ 2179.577337] Lustre: Evicted from MGS (at 192.168.206.129@tcp) after server handle changed from 0x1555eafd932d0fc to 0x1555eafd932d4bb [ 2180.979259] Lustre: 15928:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.206.129@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 2201.222324] Lustre: DEBUG MARKER: oleg629-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2202.863426] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2211.753054] Lustre: DEBUG MARKER: == recovery-small test 29a: error adding new clients doesn't cause LBUG (bug 22273) ========================================================== 01:50:09 (1787550609) [ 2225.639617] LustreError: MGC192.168.206.129@tcp: Connection to MGS (at 192.168.206.129@tcp) was lost; in progress operations using this service will fail [ 2225.667751] Lustre: Evicted from MGS (at 192.168.206.129@tcp) after server handle changed from 0x1555eafd932d4bb to 0x1555eafd932d968 [ 2227.634803] LustreError: lustre-MDT0000-mdc-ffff88f845066000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 2251.168356] Lustre: DEBUG MARKER: == recovery-small test 29b: error adding new clients doesn't cause LBUG (bug 22273) ========================================================== 01:50:48 (1787550648) [ 2266.812798] LustreError: lustre-OST0000-osc-ffff88f845066000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 2288.599855] Lustre: DEBUG MARKER: == recovery-small test 50: failover MDS under load ======= 01:51:25 (1787550685) [ 2305.179773] LustreError: lustre-MDT0000-mdc-ffff88f845066000: operation ldlm_enqueue to node 192.168.206.129@tcp failed: rc = -19 [ 2305.207090] LustreError: Skipped 2 previous similar messages [ 2322.911382] LustreError: MGC192.168.206.129@tcp: Connection to MGS (at 192.168.206.129@tcp) was lost; in progress operations using this service will fail [ 2333.108425] Lustre: Evicted from MGS (at 192.168.206.129@tcp) after server handle changed from 0x1555eafd932d968 to 0x1555eafd93319c6 [ 2353.968418] Lustre: DEBUG MARKER: oleg629-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2355.934497] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2440.671167] Lustre: 2363:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787550823/real 1787550823] req@ffff88f850be4380 x1874380460826112/t0(0) o400->MGC192.168.206.129@tcp@192.168.206.129@tcp:26/25 lens 224/224 e 0 to 1 dl 1787550839 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2440.734434] Lustre: 2363:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 17 previous similar messages [ 2440.764431] LustreError: MGC192.168.206.129@tcp: Connection to MGS (at 192.168.206.129@tcp) was lost; in progress operations using this service will fail [ 2450.984362] Lustre: Evicted from MGS (at 192.168.206.129@tcp) after server handle changed from 0x1555eafd93319c6 to 0x1555eafd934cc75 [ 2471.976958] Lustre: DEBUG MARKER: oleg629-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2474.313077] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2539.860829] LustreError: lustre-MDT0000-mdc-ffff88f845066000: operation mds_reint to node 192.168.206.129@tcp failed: rc = -19 [ 2539.885958] LustreError: Skipped 1 previous similar message [ 2539.896968] Lustre: lustre-MDT0000-mdc-ffff88f845066000: Connection to lustre-MDT0000 (at 192.168.206.129@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 2539.928437] Lustre: Skipped 8 previous similar messages [ 2557.409838] LustreError: MGC192.168.206.129@tcp: Connection to MGS (at 192.168.206.129@tcp) was lost; in progress operations using this service will fail [ 2567.616234] Lustre: Evicted from MGS (at 192.168.206.129@tcp) after server handle changed from 0x1555eafd934cc75 to 0x1555eafd936af8a [ 2567.638522] Lustre: MGC192.168.206.129@tcp: Connection restored to 192.168.206.129@tcp (at 192.168.206.129@tcp) [ 2567.646849] Lustre: Skipped 12 previous similar messages [ 2591.116570] Lustre: DEBUG MARKER: oleg629-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2593.327413] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2622.334513] Lustre: DEBUG MARKER: == recovery-small test 51: failover MDS during recovery == 01:57:00 (1787551020) [ 2643.489144] LustreError: MGC192.168.206.129@tcp: Connection to MGS (at 192.168.206.129@tcp) was lost; in progress operations using this service will fail [ 2652.938100] Lustre: DEBUG MARKER: test_51: failover in 1 sec [ 2653.678819] Lustre: Evicted from MGS (at 192.168.206.129@tcp) after server handle changed from 0x1555eafd936af8a to 0x1555eafd937982e [ 2699.443263] Lustre: DEBUG MARKER: test_51: failover in 5 sec [ 2731.254959] Lustre: 15928:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.206.129@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 2750.496350] Lustre: DEBUG MARKER: test_51: failover in 10 sec [ 2779.551236] LustreError: MGC192.168.206.129@tcp: Connection to MGS (at 192.168.206.129@tcp) was lost; in progress operations using this service will fail [ 2779.585816] LustreError: Skipped 2 previous similar messages [ 2788.781576] Lustre: Evicted from MGS (at 192.168.206.129@tcp) after server handle changed from 0x1555eafd937f4cb to 0x1555eafd9385dfc [ 2788.797608] Lustre: Skipped 2 previous similar messages [ 2791.536317] Lustre: DEBUG MARKER: test_51: failover in 20 sec [ 2816.058205] LustreError: lustre-MDT0000-mdc-ffff88f845066000: operation ldlm_enqueue to node 192.168.206.129@tcp failed: rc = -19 [ 2816.066021] LustreError: Skipped 4 previous similar messages [ 2845.364971] Lustre: 15928:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.206.129@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 2858.017191] Lustre: DEBUG MARKER: test_51: failover in 25 sec [ 2916.759554] Lustre: DEBUG MARKER: test_51: failover in 30 sec [ 2971.827326] Lustre: 15928:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.206.129@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 3012.114794] Lustre: DEBUG MARKER: == recovery-small test 52: failover OST under load ======= 02:03:30 (1787551410) [ 3067.957606] Lustre: DEBUG MARKER: oleg629-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 3071.771462] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 3358.985145] LustreError: lustre-OST0000-osc-ffff88f845066000: operation ldlm_enqueue to node 192.168.206.129@tcp failed: rc = -19 [ 3359.003361] LustreError: Skipped 5 previous similar messages [ 3359.015105] Lustre: lustre-OST0000-osc-ffff88f845066000: Connection to lustre-OST0000 (at 192.168.206.129@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 3359.034072] Lustre: Skipped 7 previous similar messages [ 3383.872797] Lustre: lustre-OST0000-osc-ffff88f845066000: Connection restored to 192.168.206.129@tcp (at 192.168.206.129@tcp) [ 3383.887112] Lustre: Skipped 15 previous similar messages [ 3404.326542] Lustre: DEBUG MARKER: oleg629-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 3406.401943] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 3738.700189] Lustre: DEBUG MARKER: oleg629-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 3741.173293] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 3983.975661] Lustre: DEBUG MARKER: == recovery-small test 53a: touch: drop rep ============== 02:19:42 (1787552382) [ 4000.735335] Lustre: 50996:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787552384/real 1787552384] req@ffff88f844868700 x1874380482117632/t0(0) o101->lustre-MDT0000-mdc-ffff88f845066000@192.168.206.129@tcp:12/10 lens 576/1152 e 0 to 1 dl 1787552400 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'openfile.0' uid:0 gid:0 projid:0 [ 4000.767714] Lustre: 50996:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 7 previous similar messages [ 4000.773944] Lustre: lustre-MDT0000-mdc-ffff88f845066000: Connection to lustre-MDT0000 (at 192.168.206.129@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 4000.784224] Lustre: Skipped 1 previous similar message [ 4000.811696] Lustre: lustre-MDT0000-mdc-ffff88f845066000: Connection restored to 192.168.206.129@tcp (at 192.168.206.129@tcp) [ 4000.818544] Lustre: Skipped 1 previous similar message [ 4008.248607] Lustre: DEBUG MARKER: == recovery-small test 53b: touch: drop rep ============== 02:20:06 (1787552406) [ 4033.852384] Lustre: DEBUG MARKER: == recovery-small test 53c: touch: drop rep ============== 02:20:31 (1787552431) [ 4061.913708] Lustre: DEBUG MARKER: == recovery-small test 54: back in time ================== 02:20:59 (1787552459) [ 4062.520102] Lustre: Mounted lustre-client - version 2.17.57_82_g53f9976 [ 4094.431263] Lustre: 2363:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787552477/real 1787552477] req@ffff88f8448caa00 x1874380482134912/t0(0) o400->lustre-MDT0000-mdc-ffff88f845066000@192.168.206.129@tcp:12/10 lens 224/224 e 0 to 1 dl 1787552493 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4094.463103] Lustre: 2363:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 4094.470560] LustreError: MGC192.168.206.129@tcp: Connection to MGS (at 192.168.206.129@tcp) was lost; in progress operations using this service will fail [ 4094.485771] LustreError: Skipped 3 previous similar messages [ 4094.520893] Lustre: Evicted from MGS (at 192.168.206.129@tcp) after server handle changed from 0x1555eafd93a084d to 0x1555eafd94dcdcb [ 4094.533067] Lustre: Skipped 3 previous similar messages [ 4107.993588] Lustre: DEBUG MARKER: oleg629-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4109.500144] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4111.334401] Lustre: Unmounted lustre-client [ 4117.418774] Lustre: DEBUG MARKER: == recovery-small test 55: ost_brw_read/write drops timed-out read/write request ========================================================== 02:21:55 (1787552515) [ 4253.087155] Lustre: 2365:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787552636/real 1787552636] req@ffff88f843720e00 x1874380482168064/t0(0) o4->lustre-OST0000-osc-ffff88f845066000@192.168.206.129@tcp:6/4 lens 488/448 e 0 to 1 dl 1787552652 ref 2 fl Rpc:XQr/602/ffffffff rc 0/-1 job:'dd.0' uid:0 gid:0 projid:0 [ 4253.128361] Lustre: 2365:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 70 previous similar messages [ 4410.156075] Lustre: DEBUG MARKER: == recovery-small test 56: do not fail on getattr resend ========================================================== 02:26:47 (1787552807) [ 4460.170803] Lustre: DEBUG MARKER: == recovery-small test 57: read procfs entries causes kernel crash ========================================================== 02:27:37 (1787552857) [ 4463.920527] Lustre: Unmounted lustre-client [ 4490.499993] Lustre: Mounted lustre-client - version 2.17.57_82_g53f9976 [ 4498.494786] Lustre: DEBUG MARKER: == recovery-small test 58: Eviction in the middle of open RPC reply processing ========================================================== 02:28:16 (1787552896) [ 4498.956672] LustreError: 56924:0:(mdc_locks.c:1337:mdc_finish_intent_lock()) cfs_fail_timeout id 801 sleeping for 20000ms [ 4500.015420] LustreError: 56924:0:(mdc_locks.c:1337:mdc_finish_intent_lock()) cfs_fail_timeout interrupted [ 4500.269540] Lustre: *** cfs_fail_loc=305, val=0*** [ 4525.340330] Lustre: DEBUG MARKER: == recovery-small test 59: Read cancel race on client eviction ========================================================== 02:28:42 (1787552922) [ 4525.915978] Lustre: Mounted lustre-client - version 2.17.57_82_g53f9976 [ 4528.786336] Lustre: setting import lustre-MDT0000_UUID INACTIVE by administrator request [ 4539.096614] Lustre: Unmounted lustre-client [ 4546.803560] Lustre: DEBUG MARKER: == recovery-small test 60: Add Changelog entries during MDS failover ========================================================== 02:29:04 (1787552944) [ 4635.926299] LustreError: lustre-MDT0000-mdc-ffff88f8448a5000: operation mds_reint to node 192.168.206.129@tcp failed: rc = -19 [ 4635.940605] LustreError: Skipped 1 previous similar message [ 4635.948460] Lustre: lustre-MDT0000-mdc-ffff88f8448a5000: Connection to lustre-MDT0000 (at 192.168.206.129@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 4635.964993] Lustre: Skipped 23 previous similar messages [ 4654.047329] Lustre: 2364:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787553037/real 1787553037] req@ffff88f8476d0e00 x1874380484847744/t0(0) o400->MGC192.168.206.129@tcp@192.168.206.129@tcp:26/25 lens 224/224 e 0 to 1 dl 1787553053 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4654.092841] Lustre: 2364:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 81 previous similar messages [ 4654.100367] LustreError: MGC192.168.206.129@tcp: Connection to MGS (at 192.168.206.129@tcp) was lost; in progress operations using this service will fail [ 4664.294136] Lustre: Evicted from MGS (at 192.168.206.129@tcp) after server handle changed from 0x1555eafd94dea73 to 0x1555eafd950a7e6 [ 4664.310634] Lustre: MGC192.168.206.129@tcp: Connection restored to 192.168.206.129@tcp (at 192.168.206.129@tcp) [ 4664.323060] Lustre: Skipped 24 previous similar messages [ 4812.023240] Lustre: DEBUG MARKER: == recovery-small test 61: Verify to not reuse orphan objects - bug 17025 ========================================================== 02:33:30 (1787553210) [ 4817.350383] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4832.231643] LustreError: MGC192.168.206.129@tcp: Connection to MGS (at 192.168.206.129@tcp) was lost; in progress operations using this service will fail [ 4832.253370] Lustre: Evicted from MGS (at 192.168.206.129@tcp) after server handle changed from 0x1555eafd950a7e6 to 0x1555eafd95563fe [ 4832.310786] LustreError: lustre-MDT0000-mdc-ffff88f8448a5000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 4846.688985] Lustre: DEBUG MARKER: == recovery-small test 65: lock enqueue for destroyed export ========================================================== 02:34:04 (1787553244) [ 4847.134993] Lustre: Mounted lustre-client - version 2.17.57_82_g53f9976 [ 4854.439602] LustreError: lustre-OST0000-osc-ffff88f8448a5000: operation ldlm_enqueue to node 192.168.206.129@tcp failed: rc = -107 [ 4854.465433] LustreError: lustre-OST0000-osc-ffff88f8448a5000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 4866.217174] Lustre: Unmounted lustre-client [ 4872.091872] Lustre: DEBUG MARKER: == recovery-small test 66: lock enqueue re-send vs client eviction ========================================================== 02:34:30 (1787553270) [ 4878.520691] LustreError: lustre-MDT0000-mdc-ffff88f8448a5000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 4878.531645] LustreError: 61317:0:(file.c:6167:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -5 [ 4886.164363] Lustre: DEBUG MARKER: == recovery-small test 67: connect vs import invalidate race ========================================================== 02:34:43 (1787553283) [ 4886.513853] LustreError: 62021:0:(recover.c:329:ptlrpc_recover_import()) cfs_race id 531 sleeping [ 4890.572195] LustreError: lustre-MDT0000-mdc-ffff88f8448a5000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 4890.596660] LustreError: 62037:0:(import.c:293:ptlrpc_invalidate_import()) cfs_fail_race id 531 waking [ 4890.603149] LustreError: 62021:0:(recover.c:329:ptlrpc_recover_import()) cfs_fail_race id 531 awake: rc=914 [ 4890.614595] LustreError: 62021:0:(import.c:717:ptlrpc_connect_import_locked()) already connecting [ 4890.663273] LustreError: 62042:0:(file.c:6167:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 4891.735878] LustreError: 62049:0:(file.c:6167:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 4891.749128] LustreError: 62049:0:(file.c:6167:ll_inode_revalidate_fini()) Skipped 5 previous similar messages [ 4894.227844] LustreError: 62071:0:(file.c:6167:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 4894.245570] LustreError: 62071:0:(file.c:6167:ll_inode_revalidate_fini()) Skipped 13 previous similar messages [ 4899.025798] LustreError: 62116:0:(file.c:6167:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 4899.038813] LustreError: 62116:0:(file.c:6167:ll_inode_revalidate_fini()) Skipped 27 previous similar messages [ 4908.503196] Lustre: DEBUG MARKER: == recovery-small test 100: IR: Make sure normal recovery still works w/o IR ========================================================== 02:35:06 (1787553306) [ 4947.516198] Lustre: DEBUG MARKER: oleg629-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 4950.250133] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4963.128137] Lustre: DEBUG MARKER: == recovery-small test 101a: IR: Make sure IR works w/o normal recovery ========================================================== 02:36:00 (1787553360) [ 5001.317622] Lustre: DEBUG MARKER: oleg629-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 5002.941654] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 5012.962420] Lustre: DEBUG MARKER: == recovery-small test 101b: IR: Make sure IR works w/o normal recovery and proceed EAGAIN ========================================================== 02:36:51 (1787553411) [ 5074.239216] Lustre: DEBUG MARKER: oleg629-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 5075.646058] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 5083.608716] Lustre: DEBUG MARKER: == recovery-small test 102: IR: New client gets updated nidtbl after MGS restart ========================================================== 02:38:01 (1787553481) [ 5119.244173] Lustre: DEBUG MARKER: oleg629-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 5120.410426] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 5125.498748] Lustre: Unmounted lustre-client [ 5177.769267] Lustre: DEBUG MARKER: oleg629-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 5180.167888] Lustre: Mounted lustre-client - version 2.17.57_82_g53f9976 [ 5185.969587] Lustre: DEBUG MARKER: == recovery-small test 103: IR: MDS can start w/o MGS and get updated nidtbl later ========================================================== 02:39:43 (1787553583) [ 5188.414956] Lustre: DEBUG MARKER: SKIP: recovery-small test_103 needs separate mgs and mds [ 5189.900377] Lustre: DEBUG MARKER: == recovery-small test 104: IR: ost can disable IR voluntarily ========================================================== 02:39:47 (1787553587) [ 5216.932763] Lustre: DEBUG MARKER: == recovery-small test 105: IR: NON IR clients support === 02:40:15 (1787553615) [ 5218.310719] Lustre: DEBUG MARKER: SKIP: recovery-small test_105 Needs multiple clients [ 5220.205832] Lustre: DEBUG MARKER: == recovery-small test 106: lightweight connection support ========================================================== 02:40:17 (1787553617) [ 5221.708211] Lustre: *** cfs_fail_loc=805, val=0*** [ 5221.751590] Lustre: Mounted lustre-client - version 2.17.57_82_g53f9976 [ 5226.633956] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5248.479597] LustreError: MGC192.168.206.129@tcp: Connection to MGS (at 192.168.206.129@tcp) was lost; in progress operations using this service will fail [ 5248.499898] Lustre: lustre-MDT0000-mdc-ffff88f845061000: Connection to lustre-MDT0000 (at 192.168.206.129@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 5248.516745] Lustre: Evicted from MGS (at 192.168.206.129@tcp) after server handle changed from 0x1555eafd9556e1c to 0x1555eafd9557037 [ 5248.532303] Lustre: Skipped 12 previous similar messages [ 5249.837343] Lustre: 68680:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.206.129@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 5258.719326] Lustre: 2365:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787553641/real 1787553641] req@ffff88f847ffb480 x1874380486877440/t0(0) o400->lustre-MDT0000-mdc-ffff88f8431fc000@192.168.206.129@tcp:12/10 lens 224/224 e 0 to 1 dl 1787553657 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5258.782880] Lustre: 2365:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 6 previous similar messages [ 5267.616126] Lustre: Unmounted lustre-client [ 5275.529916] Lustre: DEBUG MARKER: == recovery-small test 107: drop reint reply, then restart MDT ========================================================== 02:41:13 (1787553673) [ 5301.809728] LustreError: 2361:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff88f844b91f80 x1874380486888448/t90194313220(90194313220) o101->lustre-MDT0000-mdc-ffff88f8431fc000@192.168.206.129@tcp:12/10 lens 664/608 e 0 to 0 dl 1787553717 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'multiop.0' uid:0 gid:0 projid:0 [ 5301.997957] Lustre: lustre-MDT0000-mdc-ffff88f8431fc000: Connection restored to 192.168.206.129@tcp (at 192.168.206.129@tcp) [ 5302.008729] Lustre: Skipped 15 previous similar messages [ 5310.154202] Lustre: DEBUG MARKER: oleg629-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5311.443405] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5320.365342] Lustre: DEBUG MARKER: == recovery-small test 108: client eviction don't crash == 02:41:57 (1787553717) [ 5321.728882] LustreError: lustre-OST0000-osc-ffff88f8431fc000: operation ost_write to node 192.168.206.129@tcp failed: rc = -107 [ 5321.752072] LustreError: Skipped 2 previous similar messages [ 5321.797538] LustreError: lustre-OST0000-osc-ffff88f8431fc000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 5321.829130] Lustre: 2365:0:(llite_lib.c:4342:ll_dirty_page_discard_warn()) lustre: dirty page discard: 192.168.206.129@tcp:/lustre/fid: [0x20000a042:0x6:0x0]// may get corrupted (rc -5) [ 5321.870824] LustreError: 73213:0:(ldlm_resource.c:1207:ldlm_resource_complain()) lustre-OST0000-osc-ffff88f8431fc000: namespace resource [0x240000400:0x3d22:0x0].0x0 (ffff88f844bf8f00) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 5330.343362] Lustre: DEBUG MARKER: == recovery-small test 110a: create remote directory: drop client req ========================================================== 02:42:07 (1787553727) [ 5332.451743] Lustre: DEBUG MARKER: SKIP: recovery-small test_110a needs >= 2 MDTs [ 5334.587900] Lustre: DEBUG MARKER: == recovery-small test 110b: create remote directory: drop Master rep ========================================================== 02:42:12 (1787553732) [ 5336.428952] Lustre: DEBUG MARKER: SKIP: recovery-small test_110b needs >= 2 MDTs [ 5338.303037] Lustre: DEBUG MARKER: == recovery-small test 110c: create remote directory: drop update rep on slave MDT ========================================================== 02:42:16 (1787553736) [ 5339.892297] Lustre: DEBUG MARKER: SKIP: recovery-small test_110c needs >= 2 MDTs [ 5342.094925] Lustre: DEBUG MARKER: == recovery-small test 110d: remove remote directory: drop client req ========================================================== 02:42:19 (1787553739) [ 5343.522572] Lustre: DEBUG MARKER: SKIP: recovery-small test_110d needs >= 2 MDTs [ 5345.070640] Lustre: DEBUG MARKER: == recovery-small test 110e: remove remote directory: drop master rep ========================================================== 02:42:23 (1787553743) [ 5346.575771] Lustre: DEBUG MARKER: SKIP: recovery-small test_110e needs >= 2 MDTs [ 5347.993142] Lustre: DEBUG MARKER: == recovery-small test 110f: remove remote directory: drop slave rep ========================================================== 02:42:26 (1787553746) [ 5349.428603] Lustre: DEBUG MARKER: SKIP: recovery-small test_110f needs >= 2 MDTs [ 5351.173958] Lustre: DEBUG MARKER: == recovery-small test 110g: drop reply during migration ========================================================== 02:42:29 (1787553749) [ 5352.635937] Lustre: DEBUG MARKER: SKIP: recovery-small test_110g needs >= 2 MDTs [ 5354.388981] Lustre: DEBUG MARKER: == recovery-small test 110h: drop update reply during cross-MDT file rename ========================================================== 02:42:32 (1787553752) [ 5355.795445] Lustre: DEBUG MARKER: SKIP: recovery-small test_110h needs >= 2 MDTs [ 5357.863153] Lustre: DEBUG MARKER: == recovery-small test 110i: drop update reply during cross-MDT dir rename ========================================================== 02:42:35 (1787553755) [ 5359.178692] Lustre: DEBUG MARKER: SKIP: recovery-small test_110i needs >= 2 MDTs [ 5361.266467] Lustre: DEBUG MARKER: == recovery-small test 110j: drop update reply during cross-MDT ln ========================================================== 02:42:39 (1787553759) [ 5362.782661] Lustre: DEBUG MARKER: SKIP: recovery-small test_110j needs >= 2 MDTs [ 5364.792178] Lustre: DEBUG MARKER: == recovery-small test 110k: FID_QUERY failed during recovery ========================================================== 02:42:42 (1787553762) [ 5366.298439] Lustre: DEBUG MARKER: SKIP: recovery-small test_110k needs >= 2 MDTS [ 5368.391770] Lustre: DEBUG MARKER: == recovery-small test 110m: update resent vs original RPC race ========================================================== 02:42:46 (1787553766) [ 5371.087185] Lustre: DEBUG MARKER: SKIP: recovery-small test_110m needs at least 2 MDTs [ 5372.757639] Lustre: DEBUG MARKER: == recovery-small test 111: mdd setup fail should not cause umount oops ========================================================== 02:42:50 (1787553770) [ 5399.450603] Lustre: DEBUG MARKER: == recovery-small test 112a: bulk resend while orignal request is in progress ========================================================== 02:43:17 (1787553797) [ 5427.656246] Lustre: DEBUG MARKER: == recovery-small test 115a: read: late REQ MDunlink and no bulk ========================================================== 02:43:45 (1787553825) [ 5428.011923] Lustre: *** cfs_fail_loc=51b, val=3*** [ 5437.026169] Lustre: DEBUG MARKER: == recovery-small test 115b: write: late REQ MDunlink and no bulk ========================================================== 02:43:55 (1787553835) [ 5437.300397] Lustre: *** cfs_fail_loc=51b, val=4*** [ 5446.109724] Lustre: DEBUG MARKER: == recovery-small test 115c: read: late Reply MDunlink and no bulk ========================================================== 02:44:04 (1787553844) [ 5446.348224] Lustre: *** cfs_fail_loc=50f, val=3*** [ 5453.131551] Lustre: DEBUG MARKER: == recovery-small test 115d: write: late Reply MDunlink and no bulk ========================================================== 02:44:11 (1787553851) [ 5453.360866] Lustre: *** cfs_fail_loc=50f, val=4*** [ 5460.672765] Lustre: DEBUG MARKER: == recovery-small test 115e: read: late Bulk MDunlink and no reply ========================================================== 02:44:18 (1787553858) [ 5460.892569] Lustre: *** cfs_fail_loc=510, val=3*** [ 5468.299818] Lustre: DEBUG MARKER: == recovery-small test 115f: read: late REQ MDunlink and no reply ========================================================== 02:44:26 (1787553866) [ 5468.628202] Lustre: *** cfs_fail_loc=51b, val=3*** [ 5478.951655] Lustre: DEBUG MARKER: == recovery-small test 115g: read: late REQ MDunlink and Reply MDunlink ========================================================== 02:44:36 (1787553876) [ 5479.448365] Lustre: *** cfs_fail_loc=51c, val=3*** [ 5544.176373] Lustre: DEBUG MARKER: == recovery-small test 120: flock race: completion vs. evict ========================================================== 02:45:42 (1787553942) [ 5544.670944] LustreError: 83418:0:(ldlm_flock.c:803:ldlm_flock_completion_ast()) cfs_fail_timeout id 320 sleeping for 4000ms [ 5547.613712] LustreError: lustre-MDT0000-mdc-ffff88f8431fc000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5547.632764] LustreError: 83433:0:(file.c:251:ll_close_inode_openhandle()) lustre-clilmv-ffff88f8431fc000: inode [0x20000a042:0x8:0x0] mdc close failed: rc = -108 [ 5547.683675] LustreError: 83433:0:(ldlm_resource.c:1207:ldlm_resource_complain()) lustre-MDT0000-mdc-ffff88f8431fc000: namespace resource [0x20000a042:0x11:0x0].0xc (ffff88f84759cd00) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 5547.706665] LustreError: 83438:0:(file.c:6167:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 5547.717793] LustreError: 83438:0:(file.c:6167:ll_inode_revalidate_fini()) Skipped 13 previous similar messages [ 5548.767258] LustreError: 83418:0:(ldlm_flock.c:803:ldlm_flock_completion_ast()) cfs_fail_timeout id 320 awake [ 5550.884859] LustreError: 83448:0:(ldlm_flock.c:803:ldlm_flock_completion_ast()) cfs_fail_timeout id 320 sleeping for 4000ms [ 5553.789587] LustreError: lustre-MDT0000-mdc-ffff88f8431fc000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5553.812728] LustreError: 83462:0:(ldlm_resource.c:1207:ldlm_resource_complain()) lustre-MDT0000-mdc-ffff88f8431fc000: namespace resource [0x20000a042:0x11:0x0].0xc (ffff88f84759cb00) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 5553.834449] LustreError: 83462:0:(ldlm_resource.c:1207:ldlm_resource_complain()) Skipped 1 previous similar message [ 5554.975130] LustreError: 83448:0:(ldlm_flock.c:803:ldlm_flock_completion_ast()) cfs_fail_timeout id 320 awake [ 5561.891393] LustreError: lustre-MDT0000-mdc-ffff88f8431fc000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5562.259744] LustreError: 83504:0:(ldlm_flock.c:808:ldlm_flock_completion_ast()) cfs_fail_timeout id 321 sleeping for 4000ms [ 5565.179951] LustreError: lustre-MDT0000-mdc-ffff88f8431fc000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5565.266962] LustreError: 83525:0:(file.c:6167:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 5566.335265] LustreError: 83504:0:(ldlm_flock.c:808:ldlm_flock_completion_ast()) cfs_fail_timeout id 321 awake [ 5566.347819] LustreError: 83504:0:(file.c:251:ll_close_inode_openhandle()) lustre-clilmv-ffff88f8431fc000: inode [0x20000a042:0x11:0x0] mdc close failed: rc = -108 [ 5566.370091] LustreError: 83504:0:(file.c:251:ll_close_inode_openhandle()) Skipped 1 previous similar message [ 5567.558505] LustreError: 83543:0:(file.c:6167:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 5567.580870] LustreError: 83543:0:(file.c:6167:ll_inode_revalidate_fini()) Skipped 12 previous similar messages [ 5572.543468] LustreError: 83581:0:(ldlm_flock.c:808:ldlm_flock_completion_ast()) cfs_fail_timeout id 321 sleeping for 4000ms [ 5575.379611] LustreError: lustre-MDT0000-mdc-ffff88f8431fc000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5575.391350] LustreError: 83595:0:(ldlm_resource.c:1207:ldlm_resource_complain()) lustre-MDT0000-mdc-ffff88f8431fc000: namespace resource [0x200000007:0x1:0x0].0x0 (ffff88f84750e600) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 5575.413975] LustreError: 83595:0:(ldlm_resource.c:1207:ldlm_resource_complain()) Skipped 1 previous similar message [ 5576.623139] LustreError: 83581:0:(ldlm_flock.c:808:ldlm_flock_completion_ast()) cfs_fail_timeout id 321 awake [ 5583.282957] LustreError: lustre-MDT0000-mdc-ffff88f8431fc000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5583.626978] LustreError: 83637:0:(ldlm_flock.c:857:ldlm_flock_completion_ast()) cfs_fail_timeout id 322 sleeping for 4000ms [ 5586.414230] LustreError: lustre-MDT0000-mdc-ffff88f8431fc000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5586.426951] LustreError: 83652:0:(ldlm_resource.c:1207:ldlm_resource_complain()) lustre-MDT0000-mdc-ffff88f8431fc000: namespace resource [0x20000a042:0x11:0x0].0xc (ffff88f84759ce00) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 5586.463294] LustreError: 83652:0:(ldlm_resource.c:1207:ldlm_resource_complain()) Skipped 2 previous similar messages [ 5587.711124] LustreError: 83637:0:(ldlm_flock.c:857:ldlm_flock_completion_ast()) cfs_fail_timeout id 322 awake [ 5590.487589] LustreError: lustre-MDT0000-mdc-ffff88f8431fc000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5590.563807] LustreError: 83684:0:(file.c:6167:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 5590.574433] LustreError: 83684:0:(file.c:6167:ll_inode_revalidate_fini()) Skipped 13 previous similar messages [ 5591.883798] LustreError: 83665:0:(file.c:251:ll_close_inode_openhandle()) lustre-clilmv-ffff88f8431fc000: inode [0x20000a042:0x11:0x0] mdc close failed: rc = -108 [ 5599.477519] LustreError: 83736:0:(ldlm_flock.c:803:ldlm_flock_completion_ast()) cfs_fail_timeout id 320 sleeping for 4000ms [ 5599.484142] LustreError: 83736:0:(ldlm_flock.c:803:ldlm_flock_completion_ast()) Skipped 1 previous similar message [ 5602.881646] LustreError: lustre-MDT0000-mdc-ffff88f8431fc000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5602.977454] LustreError: 83759:0:(file.c:6167:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 5602.994304] LustreError: 83759:0:(file.c:6167:ll_inode_revalidate_fini()) Skipped 26 previous similar messages [ 5603.487758] LustreError: 83736:0:(ldlm_flock.c:803:ldlm_flock_completion_ast()) cfs_fail_timeout id 320 awake [ 5603.494765] LustreError: 83736:0:(ldlm_flock.c:803:ldlm_flock_completion_ast()) Skipped 1 previous similar message [ 5603.502484] LustreError: 83736:0:(file.c:251:ll_close_inode_openhandle()) lustre-clilmv-ffff88f8431fc000: inode [0x20000a042:0x11:0x0] mdc close failed: rc = -108 [ 5613.492699] Lustre: DEBUG MARKER: == recovery-small test 113: ldlm enqueue dropped reply should not cause deadlocks ========================================================== 02:46:51 (1787554011) [ 5633.618766] LustreError: 68677:0:(ldlm_lockd.c:2890:ldlm_bl_thread_blwi()) cfs_fail_timeout id 31f sleeping for 4000ms [ 5633.627336] LustreError: 68677:0:(ldlm_lockd.c:2890:ldlm_bl_thread_blwi()) Skipped 1 previous similar message [ 5637.688317] LustreError: 68677:0:(ldlm_lockd.c:2890:ldlm_bl_thread_blwi()) cfs_fail_timeout id 31f awake [ 5637.716659] LustreError: 68677:0:(ldlm_lockd.c:2890:ldlm_bl_thread_blwi()) Skipped 1 previous similar message [ 5645.198974] Lustre: DEBUG MARKER: == recovery-small test 130a: enqueue resend on not existing file ========================================================== 02:47:22 (1787554042) [ 5696.323548] Lustre: DEBUG MARKER: == recovery-small test 130b: enqueue resend on a stale inode ========================================================== 02:48:14 (1787554094) [ 5759.118103] Lustre: DEBUG MARKER: == recovery-small test 130c: layout intent resend on a stale inode ========================================================== 02:49:17 (1787554157) [ 5790.995824] Lustre: DEBUG MARKER: == recovery-small test 132: long punch =================== 02:49:49 (1787554189) [ 5791.412186] Lustre: Mounted lustre-client - version 2.17.57_82_g53f9976 [ 5914.685228] Lustre: Unmounted lustre-client [ 5920.658611] Lustre: DEBUG MARKER: == recovery-small test 131: IO vs evict results to IO under staled lock ========================================================== 02:51:58 (1787554318) [ 5921.214199] LustreError: 88064:0:(osc_request.c:2990:osc_build_rpc()) cfs_fail_timeout id 414 sleeping for 10000ms [ 5923.451769] LustreError: lustre-OST0000-osc-ffff88f8431fc000: operation ost_statfs to node 192.168.206.129@tcp failed: rc = -107 [ 5923.462622] LustreError: Skipped 9 previous similar messages [ 5923.470682] Lustre: lustre-OST0000-osc-ffff88f8431fc000: Connection to lustre-OST0000 (at 192.168.206.129@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 5923.491733] Lustre: Skipped 17 previous similar messages [ 5923.509199] LustreError: lustre-OST0000-osc-ffff88f8431fc000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 5923.531261] LustreError: 88152:0:(ldlm_resource.c:1207:ldlm_resource_complain()) lustre-OST0000-osc-ffff88f8431fc000: namespace resource [0x240000400:0x3d4d:0x0].0x0 (ffff88f84759c000) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 5923.549405] LustreError: 88152:0:(ldlm_resource.c:1207:ldlm_resource_complain()) Skipped 1 previous similar message [ 5923.735075] LustreError: 88064:0:(osc_request.c:2990:osc_build_rpc()) cfs_fail_timeout interrupted [ 5923.748600] Lustre: 2363:0:(llite_lib.c:4342:ll_dirty_page_discard_warn()) lustre: dirty page discard: 192.168.206.129@tcp:/lustre/fid: [0x20000bf89:0x9:0x0]// may get corrupted (rc -108) [ 5923.765359] Lustre: lustre-OST0000-osc-ffff88f8431fc000: Connection restored to 192.168.206.129@tcp (at 192.168.206.129@tcp) [ 5923.770122] Lustre: Skipped 15 previous similar messages [ 5929.348187] Lustre: DEBUG MARKER: == recovery-small test 133: don't fail on flock resend === 02:52:07 (1787554327) [ 5986.271164] Lustre: 88731:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787554330/real 1787554330] req@ffff88f844d59f80 x1874380487054336/t0(0) o101->lustre-MDT0000-mdc-ffff88f8431fc000@192.168.206.129@tcp:12/10 lens 328/344 e 0 to 1 dl 1787554385 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'multiop.0' uid:0 gid:0 projid:0 [ 5986.305172] Lustre: 88731:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 17 previous similar messages [ 5992.261128] Lustre: DEBUG MARKER: == recovery-small test 134: race between failover and search for reply data free slot ========================================================== 02:53:10 (1787554390) [ 5993.500987] Lustre: DEBUG MARKER: SKIP: recovery-small test_134 Need 2+ clients, have 1 [ 5994.842579] Lustre: DEBUG MARKER: == recovery-small test 135: DOM: open/create resend to return size ========================================================== 02:53:13 (1787554393) [ 6056.991713] Lustre: DEBUG MARKER: SKIP: recovery-small test_136 skipping excluded test 136 [ 6059.030224] Lustre: DEBUG MARKER: == recovery-small test 137: late resend must be skipped if already applied ========================================================== 02:54:16 (1787554456) [ 6116.371839] Lustre: DEBUG MARKER: == recovery-small test 138: Umount MDT during recovery === 02:55:14 (1787554514) [ 6118.297793] Lustre: DEBUG MARKER: SKIP: recovery-small test_138 needs >= 2 MDTs [ 6119.773453] Lustre: DEBUG MARKER: == recovery-small test 139: corrupted catid won't cause crash ========================================================== 02:55:17 (1787554517) [ 6121.002970] Lustre: DEBUG MARKER: SKIP: recovery-small test_139 needs >= 2 MDTs [ 6122.312923] Lustre: DEBUG MARKER: == recovery-small test 140a: local mount is flagged properly ========================================================== 02:55:20 (1787554520) [ 6153.754630] Lustre: DEBUG MARKER: == recovery-small test 140b: local mount is excluded from recovery ========================================================== 02:55:51 (1787554551) [ 6165.014184] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 6192.136509] LustreError: MGC192.168.206.129@tcp: Connection to MGS (at 192.168.206.129@tcp) was lost; in progress operations using this service will fail [ 6192.162355] LustreError: Skipped 2 previous similar messages [ 6192.205846] Lustre: Evicted from MGS (at 192.168.206.129@tcp) after server handle changed from 0x1555eafd9557c8c to 0x1555eafd95594b8 [ 6192.223947] Lustre: Skipped 2 previous similar messages [ 6193.647129] Lustre: 68680:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.206.129@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 6212.257728] Lustre: DEBUG MARKER: oleg629-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6213.824100] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6222.754201] Lustre: DEBUG MARKER: == recovery-small test 141: do not lose locks on MGS restart ========================================================== 02:57:00 (1787554620) [ 6224.645392] Lustre: DEBUG MARKER: SKIP: recovery-small test_141 cannot run in local mode or from build tree [ 6226.115781] Lustre: DEBUG MARKER: == recovery-small test 142: orphan name stub can be cleaned up in startup ========================================================== 02:57:04 (1787554624) [ 6240.241560] LustreError: MGC192.168.206.129@tcp: Connection to MGS (at 192.168.206.129@tcp) was lost; in progress operations using this service will fail [ 6240.275773] Lustre: Evicted from MGS (at 192.168.206.129@tcp) after server handle changed from 0x1555eafd95594b8 to 0x1555eafd9559973 [ 6248.972352] Lustre: DEBUG MARKER: == recovery-small test 143: orphan cleanup thread shouldn't be blocked even delete failed ========================================================== 02:57:26 (1787554646) [ 6299.225463] Lustre: DEBUG MARKER: == recovery-small test 144a: MDT failover should stop precreation threads ========================================================== 02:58:16 (1787554696) [ 6358.545349] Lustre: DEBUG MARKER: oleg629-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 6360.935144] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 6443.999348] LustreError: MGC192.168.206.129@tcp: Connection to MGS (at 192.168.206.129@tcp) was lost; in progress operations using this service will fail [ 6444.019027] LustreError: Skipped 1 previous similar message [ 6453.937299] Lustre: Evicted from MGS (at 192.168.206.129@tcp) after server handle changed from 0x1555eafd9559cfa to 0x1555eafd955ad9a [ 6453.948592] Lustre: Skipped 1 previous similar message [ 6457.699149] Lustre: DEBUG MARKER: oleg629-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6459.299128] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6495.581690] Lustre: DEBUG MARKER: oleg629-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6497.359466] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6633.616529] Lustre: DEBUG MARKER: == recovery-small test 144b: orphan cleanup shouldn't be blocked for no objects+failover situation ========================================================== 03:03:51 (1787555031) [ 6642.285935] LustreError: lustre-OST0000-osc-ffff88f8431fc000: operation ost_setattr to node 192.168.206.129@tcp failed: rc = -19 [ 6642.297347] LustreError: Skipped 303 previous similar messages [ 6642.304765] Lustre: lustre-OST0000-osc-ffff88f8431fc000: Connection to lustre-OST0000 (at 192.168.206.129@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 6642.325229] Lustre: Skipped 9 previous similar messages [ 6696.218300] Lustre: DEBUG MARKER: oleg629-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 6700.302281] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 6955.128705] Lustre: DEBUG MARKER: == recovery-small test 144c: reconnection during orphan cleanup shouldn't lose LAST_ID synchronization ========================================================== 03:09:13 (1787555353) [ 7090.670411] LustreError: MGC192.168.206.129@tcp: Connection to MGS (at 192.168.206.129@tcp) was lost; in progress operations using this service will fail [ 7090.683017] LustreError: Skipped 1 previous similar message [ 7090.704681] Lustre: Evicted from MGS (at 192.168.206.129@tcp) after server handle changed from 0x1555eafd955b136 to 0x1555eafd96551cb [ 7090.714046] Lustre: Skipped 1 previous similar message [ 7090.731530] Lustre: MGC192.168.206.129@tcp: Connection restored to 192.168.206.129@tcp (at 192.168.206.129@tcp) [ 7090.737220] Lustre: Skipped 13 previous similar messages [ 7122.765906] Lustre: DEBUG MARKER: == recovery-small test 145: connect mdtlovs and process update logs after recovery expire ========================================================== 03:12:00 (1787555520) [ 7124.234345] Lustre: DEBUG MARKER: SKIP: recovery-small test_145 needs >= 3 MDTs [ 7126.621315] Lustre: DEBUG MARKER: == recovery-small test 146: test eviction is counted properly ========================================================== 03:12:04 (1787555524) [ 7129.075835] LustreError: lustre-MDT0000-mdc-ffff88f8431fc000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 7138.624337] Lustre: DEBUG MARKER: == recovery-small test 147: Check client reconnect ======= 03:12:16 (1787555536) [ 7306.473766] LustreError: lustre-OST0000-osc-ffff88f8431fc000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 7308.521366] Lustre: DEBUG MARKER: == recovery-small test 148: data corruption through resend ========================================================== 03:15:06 (1787555706) [ 7334.367151] Lustre: 2362:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787555713/real 1787555713] req@ffff88f85875dc00 x1874380504792320/t0(0) o4->lustre-OST0000-osc-ffff88f8431fc000@192.168.206.129@tcp:6/4 lens 4584/448 e 0 to 1 dl 1787555733 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'dd.0' uid:0 gid:0 projid:0 [ 7334.394654] Lustre: 2362:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 24 previous similar messages [ 7334.405288] Lustre: lustre-OST0000-osc-ffff88f8431fc000: Connection to lustre-OST0000 (at 192.168.206.129@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 7334.434526] Lustre: Skipped 3 previous similar messages [ 7351.163311] Lustre: DEBUG MARKER: == recovery-small test 149: skip orphan removal at umount ========================================================== 03:15:49 (1787555749) [ 7352.581950] Lustre: DEBUG MARKER: SKIP: recovery-small test_149 needs >= 2 MDTs [ 7354.230582] Lustre: DEBUG MARKER: == recovery-small test 150: statfs when MDT0 offline with lazystatfs option ========================================================== 03:15:52 (1787555752) [ 7355.670258] Lustre: DEBUG MARKER: SKIP: recovery-small test_150 needs >= 2 MDTs [ 7357.512964] Lustre: DEBUG MARKER: == recovery-small test 152: QoS object allocation could be awakened in case of OST failover ========================================================== 03:15:55 (1787555755) [ 7393.739414] Lustre: DEBUG MARKER: == recovery-small test 153: evict vs reconnect race ====== 03:16:31 (1787555791) [ 7429.614975] LustreError: MGC192.168.206.129@tcp: Connection to MGS (at 192.168.206.129@tcp) was lost; in progress operations using this service will fail [ 7429.646554] Lustre: Evicted from MGS (at 192.168.206.129@tcp) after server handle changed from 0x1555eafd96551cb to 0x1555eafd96579a2 [ 7429.656403] Lustre: Skipped 1 previous similar message [ 7445.073484] Lustre: DEBUG MARKER: == recovery-small test 154a: corruption update llog can be skipped ========================================================== 03:17:23 (1787555843) [ 7446.412749] Lustre: DEBUG MARKER: SKIP: recovery-small test_154a needs >= 2 MDTs [ 7448.003841] Lustre: DEBUG MARKER: == recovery-small test 154b: restore update llog after failed recovery ========================================================== 03:17:26 (1787555846) [ 7449.376650] Lustre: DEBUG MARKER: SKIP: recovery-small test_154b needs >= 2 MDTs [ 7450.917735] Lustre: DEBUG MARKER: == recovery-small test 155: failover after client remount ========================================================== 03:17:28 (1787555848) [ 7460.108331] Lustre: Unmounted lustre-client [ 7461.316970] Lustre: Mounted lustre-client - version 2.17.57_82_g53f9976 [ 7464.299529] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 7486.943642] Lustre: 2365:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787555870/real 1787555870] req@ffff88f870528700 x1874380504979712/t0(0) o400->MGC192.168.206.129@tcp@192.168.206.129@tcp:26/25 lens 224/224 e 0 to 1 dl 1787555886 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 7492.589656] Lustre: DEBUG MARKER: recovery-small test_155: @@@@@@ FAIL: ls1 != ls2 [ 7507.531538] Lustre: DEBUG MARKER: == recovery-small test 156: tot_granted miscount after client eviction ========================================================== 03:18:25 (1787555905) [ 7514.810354] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-OST0000 [ 7539.175850] LustreError: 2361:0:(client.c:3533:ptlrpc_replay_req()) cfs_fail_timeout id 536 sleeping for 45000ms [ 7584.239424] LustreError: 2361:0:(client.c:3533:ptlrpc_replay_req()) cfs_fail_timeout id 536 awake [ 7584.266831] LustreError: lustre-OST0000-osc-ffff88f860647000: operation ost_write to node 192.168.206.129@tcp failed: rc = -107 [ 7584.282085] LustreError: Skipped 33 previous similar messages [ 7584.311713] LustreError: lustre-OST0000-osc-ffff88f860647000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 7590.896479] Lustre: DEBUG MARKER: oleg629-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 7592.455908] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 7604.563962] Lustre: DEBUG MARKER: == recovery-small test 157: eviction during mmaped i/o === 03:20:02 (1787556002) [ 7605.196835] LustreError: 109712:0:(vvp_io.c:1490:vvp_io_fault_start()) cfs_fail_timeout id 1432 sleeping for 3000ms [ 7608.233837] LustreError: 109712:0:(vvp_io.c:1490:vvp_io_fault_start()) cfs_fail_timeout id 1432 awake [ 7608.267463] LustreError: lustre-OST0000-osc-ffff88f860647000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 7613.995708] Lustre: DEBUG MARKER: == recovery-small test 158a: connect without access right ========================================================== 03:20:12 (1787556012) [ 7615.155894] Lustre: DEBUG MARKER: SKIP: recovery-small test_158a needs >= 2 MDTS [ 7617.141211] Lustre: DEBUG MARKER: == recovery-small test 160: MDT destroys are blocked by grouplocks ========================================================== 03:20:14 (1787556014) [ 7620.360424] LustreError: lustre-MDT0000-mdc-ffff88f860647000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 7667.601948] Lustre: DEBUG MARKER: == recovery-small test 161: evict osp by ping evictor ==== 03:21:05 (1787556065) [ 7668.953812] Lustre: DEBUG MARKER: SKIP: recovery-small test_161 needs >= 2 MDTs [ 7670.628983] Lustre: DEBUG MARKER: == recovery-small test 162: File attributes should be persisted after MDS failover ========================================================== 03:21:08 (1787556068) [ 7687.762463] LustreError: 2361:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff88f84f6f4700 x1874380505075072/t133143986232(133143986232) o101->lustre-MDT0000-mdc-ffff88f860647000@192.168.206.129@tcp:12/10 lens 576/608 e 0 to 0 dl 1787556146 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'chattr.0' uid:0 gid:0 projid:0 [ 7702.289321] Lustre: DEBUG MARKER: == recovery-small test 163: changelog check for fail write and processing records ========================================================== 03:21:39 (1787556099) [ 7721.525224] Lustre: DEBUG MARKER: == recovery-small test 170: Reconnect after REPLAY_LOCKS hangs (LU-18154) ========================================================== 03:21:59 (1787556119) [ 7725.935171] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-OST0000 [ 7736.799206] Lustre: 2363:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787556076/real 1787556076] req@ffff88f84f6f6a00 x1874380505080960/t0(0) o400->lustre-MDT0000-mdc-ffff88f860647000@192.168.206.129@tcp:12/10 lens 224/224 e 0 to 1 dl 1787556136 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 7736.827188] Lustre: 2363:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 7759.852094] Lustre: *** cfs_fail_loc=537, val=0*** [ 7759.856293] LustreError: 2361:0:(import.c:717:ptlrpc_connect_import_locked()) already connecting [ 7761.494907] Lustre: DEBUG MARKER: oleg629-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 60 0 [ 7763.031155] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 7768.889627] Lustre: DEBUG MARKER: == recovery-small test complete, duration 7490 sec ======= 03:22:46 (1787556166) [ 7770.369608] Lustre: DEBUG MARKER: === recovery-small: start cleanup 03:22:48 (1787556168) === [ 8041.526568] Lustre: DEBUG MARKER: === recovery-small: finish cleanup 03:27:19 (1787556439) === [ 8062.431401] Lustre: 2364:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787556445/real 1787556445] req@ffff88f844bfc380 x1874380508861824/t0(0) o400->MGC192.168.206.129@tcp@192.168.206.129@tcp:26/25 lens 224/224 e 0 to 1 dl 1787556461 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 8062.478318] Lustre: 2364:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 8062.488657] LustreError: MGC192.168.206.129@tcp: Connection to MGS (at 192.168.206.129@tcp) was lost; in progress operations using this service will fail [ 8062.504164] LustreError: Skipped 2 previous similar messages [ 8072.676176] Lustre: lustre-MDT0000-mdc-ffff88f860647000: Connection to lustre-MDT0000 (at 192.168.206.129@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 8072.685529] Lustre: Evicted from MGS (at 192.168.206.129@tcp) after server handle changed from 0x1555eafd9659ab8 to 0x1555eafd96ebb29 [ 8072.697556] Lustre: Skipped 7 previous similar messages [ 8072.716847] Lustre: Skipped 2 previous similar messages [ 8072.725385] Lustre: MGC192.168.206.129@tcp: Connection restored to 192.168.206.129@tcp (at 192.168.206.129@tcp) [ 8072.736380] Lustre: Skipped 11 previous similar messages [ 8086.861304] Lustre: DEBUG MARKER: oleg629-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 8088.428147] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8093.920906] Lustre: Unmounted lustre-client [ 8119.202866] Key type lgssc unregistered [ 8119.598424] LNet: 116363:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 8119.615843] LNetError: 116363:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 8119.637801] LNet: Removed LNI 192.168.206.29@tcp [ 8120.938160] Key type .llcrypt unregistered [ 8120.940078] Key type ._llcrypt unregistered