[ 0.000000] Linux version 4.18.0rh8.10-debug (green@maintenance) (gcc version 8.5.0 20210514 (Red Hat 8.5.0-26) (GCC)) #2 SMP Mon Jul 14 01:24:22 EDT 2025 [ 0.000000] Command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers' [ 0.000000] x86/fpu: xstate_offset[2]: 576, xstate_sizes[2]: 256 [ 0.000000] x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'standard' format. [ 0.000000] signal: max sigframe size: 1776 [ 0.000000] BIOS-provided physical RAM map: [ 0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable [ 0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000000100000-0x00000000bffd9fff] usable [ 0.000000] BIOS-e820: [mem 0x00000000bffda000-0x00000000bfffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000100000000-0x0000000146dfffff] usable [ 0.000000] NX (Execute Disable) protection: active [ 0.000000] SMBIOS 2.8 present. [ 0.000000] DMI: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.17.0-8.fc42 06/10/2025 [ 0.000000] Hypervisor detected: KVM [ 0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00 [ 0.000000] kvm-clock: using sched offset of 801486270 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2399.998 MHz processor [ 0.000000] last_pfn = 0x146e00 max_arch_pfn = 0x400000000 [ 0.000000] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT [ 0.000000] last_pfn = 0xbffda max_arch_pfn = 0x400000000 [ 0.000000] found SMP MP-table at [mem 0x000f54d0-0x000f54df] [ 0.000000] RAMDISK: [mem 0xbcc64000-0xbffcffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F52F0 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE2421 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE22BD 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 00227D (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE2331 000090 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE23C1 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE23F9 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe22bd-0xbffe2330] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe22bc] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe2331-0xbffe23c0] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe23c1-0xbffe23f8] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe23f9-0xbffe2420] [ 0.000000] No NUMA configuration found [ 0.000000] Faking a node at [mem 0x0000000000000000-0x0000000146dfffff] [ 0.000000] NODE_DATA(0) allocated [mem 0x1465a3000-0x1465cdfff] [ 0.000000] Reserving 256MB of memory at 2752MB for crashkernel (System RAM: 4205MB) [ 0.000000] Zone ranges: [ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.000000] DMA32 [mem 0x0000000001000000-0x00000000ffffffff] [ 0.000000] Normal [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Device empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff] [ 0.000000] node 0: [mem 0x0000000000100000-0x00000000bffd9fff] [ 0.000000] node 0: [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Zeroed struct page in unavailable ranges: 4744 pages [ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x0000000146dfffff] [ 0.000000] ACPI: PM-Timer IO Port: 0x608 [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) [ 0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) [ 0.000000] Using ACPI (MADT) for SMP configuration information [ 0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000] TSC deadline timer available [ 0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs [ 0.000000] kvm-guest: KVM setup pv remote TLB flush [ 0.000000] kvm-guest: setup PV sched yield [ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff] [ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff] [ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff] [ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff] [ 0.000000] PM: Registered nosave memory: [mem 0xbffda000-0xbfffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xc0000000-0xfeffbfff] [ 0.000000] PM: Registered nosave memory: [mem 0xfeffc000-0xfeffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xff000000-0xfffbffff] [ 0.000000] PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff] [ 0.000000] [mem 0xc0000000-0xfeffbfff] available for PCI devices [ 0.000000] Booting paravirtualized kernel on KVM [ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns [ 0.000000] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1 [ 0.000000] percpu: Embedded 63 pages/cpu s221184 r8192 d28672 u524288 [ 0.000000] kvm-guest: PV spinlocks enabled [ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1059618 [ 0.000000] Policy zone: Normal [ 0.000000] Kernel command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] Specific versions of hardware are certified with Red Hat Enterprise Linux 8. Please see the list of hardware certified with Red Hat Enterprise Linux 8 at https://catalog.redhat.com. [ 0.000000] audit: disabled (until reboot) [ 0.000000] software IO TLB: area num 4. [ 0.000000] Memory: 2895288K/4306400K available (18435K kernel code, 11221K rwdata, 7248K rodata, 2908K init, 18040K bss, 524588K 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.001014] APIC: Switch to symmetric I/O mode setup [ 0.002316] x2apic enabled [ 0.003008] Switched APIC routing to physical x2apic. [ 0.004017] kvm-guest: setup PV IPIs [ 0.007857] ..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.008027] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.009015] pid_max: default: 32768 minimum: 301 [ 0.010141] LSM: Security Framework initializing [ 0.011047] Yama: becoming mindful. [ 0.012035] SELinux: Initializing. [ 0.013060] *** VALIDATE selinux *** [ 0.021633] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.026410] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.027216] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.028124] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.029232] *** VALIDATE tmpfs *** [ 0.031478] *** VALIDATE proc *** [ 0.033149] *** VALIDATE cgroup *** [ 0.034014] *** VALIDATE cgroup2 *** [ 0.036084] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.037178] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.038014] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.039031] Spectre V2 : User space: Vulnerable [ 0.041006] Speculative Store Bypass: Vulnerable [ 0.044541] debug: unmapping init [mem 0xffffffffaaa59000-0xffffffffaaa60fff] [ 0.046337] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.047862] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.048023] ... version: 2 [ 0.049013] ... bit width: 48 [ 0.050012] ... generic registers: 4 [ 0.051011] ... value mask: 0000ffffffffffff [ 0.052013] ... max period: 00007fffffffffff [ 0.053010] ... fixed-purpose events: 3 [ 0.054009] ... event mask: 000000070000000f [ 0.055287] rcu: Hierarchical SRCU implementation. [ 0.057666] smp: Bringing up secondary CPUs ... [ 0.058729] x86: Booting SMP configuration: [ 0.059026] .... node #0, CPUs: #1 #2 #3 [ 0.067107] smp: Brought up 1 node, 4 CPUs [ 0.069013] smpboot: Max logical packages: 1 [ 0.070015] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.117584] node 0 deferred pages initialised in 46ms [ 0.122101] devtmpfs: initialized [ 0.123352] x86/mm: Memory block size: 128MB [ 0.127232] gcov: version magic: 0x41383552 [ 0.130336] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.134149] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.137344] pinctrl core: initialized pinctrl subsystem [ 0.139251] [ 0.139855] ************************************************************* [ 0.142013] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.145013] ** ** [ 0.148011] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.150011] ** ** [ 0.153013] ** This means that this kernel is built to expose internal ** [ 0.156012] ** IOMMU data structures, which may compromise security on ** [ 0.159015] ** your system. ** [ 0.162016] ** ** [ 0.164014] ** If you see this message and you are not debugging the ** [ 0.167014] ** kernel, report this immediately to your vendor! ** [ 0.170012] ** ** [ 0.172014] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.175012] ************************************************************* [ 0.177966] NET: Registered protocol family 16 [ 0.180529] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.183164] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.186115] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.191107] cpuidle: using governor menu [ 0.193902] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.196613] PCI: Using configuration type 1 for base access [ 0.199221] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.208064] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.209018] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.211128] cryptd: max_cpu_qlen set to 1000 [ 0.213450] ACPI: Added _OSI(Module Device) [ 0.214000] ACPI: Added _OSI(Processor Device) [ 0.215012] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.216010] ACPI: Added _OSI(Processor Aggregator Device) [ 0.222771] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.230031] ACPI: Interpreter enabled [ 0.231055] ACPI: PM: (supports S0 S3 S4 S5) [ 0.233014] ACPI: Using IOAPIC for interrupt routing [ 0.235273] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.236471] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.248507] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.250042] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.253022] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.257090] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.263893] acpiphp: Slot [2] registered [ 0.265248] acpiphp: Slot [5] registered [ 0.267174] acpiphp: Slot [6] registered [ 0.269144] acpiphp: Slot [3] registered [ 0.271135] acpiphp: Slot [4] registered [ 0.272228] acpiphp: Slot [7] registered [ 0.274274] acpiphp: Slot [8] registered [ 0.276131] acpiphp: Slot [9] registered [ 0.278117] acpiphp: Slot [10] registered [ 0.279261] acpiphp: Slot [11] registered [ 0.281106] acpiphp: Slot [12] registered [ 0.283135] acpiphp: Slot [13] registered [ 0.284141] acpiphp: Slot [14] registered [ 0.286187] acpiphp: Slot [15] registered [ 0.288108] acpiphp: Slot [16] registered [ 0.290107] acpiphp: Slot [17] registered [ 0.292119] acpiphp: Slot [18] registered [ 0.293258] acpiphp: Slot [19] registered [ 0.295085] acpiphp: Slot [20] registered [ 0.296085] acpiphp: Slot [21] registered [ 0.298110] acpiphp: Slot [22] registered [ 0.300197] acpiphp: Slot [23] registered [ 0.302143] acpiphp: Slot [24] registered [ 0.303183] acpiphp: Slot [25] registered [ 0.305117] acpiphp: Slot [26] registered [ 0.307090] acpiphp: Slot [27] registered [ 0.308098] acpiphp: Slot [28] registered [ 0.310127] acpiphp: Slot [29] registered [ 0.312188] acpiphp: Slot [30] registered [ 0.314112] acpiphp: Slot [31] registered [ 0.315240] PCI host bridge to bus 0000:00 [ 0.317021] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.320046] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.323026] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.326028] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.328194] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.332026] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.334185] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.337312] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.341528] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.350013] pci 0000:00:01.1: reg 0x20: [io 0xc120-0xc12f] [ 0.354051] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.357019] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.360015] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.362017] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.365405] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.367862] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.371044] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.374975] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.379053] pci 0000:00:02.0: reg 0x10: [io 0xc100-0xc11f] [ 0.390060] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.396016] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.403058] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.416019] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.429024] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.454014] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.464000] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.470020] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.480017] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.510021] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.527431] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.531406] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.537145] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.540690] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.545384] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.554063] iommu: Default domain type: Passthrough [ 0.555000] SCSI subsystem initialized [ 0.556149] ACPI: bus type USB registered [ 0.558127] usbcore: registered new interface driver usbfs [ 0.560076] usbcore: registered new interface driver hub [ 0.563116] usbcore: registered new device driver usb [ 0.565285] pps_core: LinuxPPS API ver. 1 registered [ 0.568010] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.571059] PTP clock support registered [ 0.575082] EDAC MC: Ver: 3.0.0 [ 0.576078] PCI: Using ACPI for IRQ routing [ 0.577000] NetLabel: Initializing [ 0.579013] NetLabel: domain hash size = 128 [ 0.580014] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.583112] NetLabel: unlabeled traffic allowed by default [ 0.585365] vgaarb: loaded [ 0.589456] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.593017] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.600286] clocksource: Switched to clocksource kvm-clock [ 0.744274] VFS: Disk quotas dquot_6.6.0 [ 0.745769] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.748145] *** VALIDATE ramfs *** [ 0.749399] *** VALIDATE hugetlbfs *** [ 0.751149] pnp: PnP ACPI init [ 0.753678] pnp: PnP ACPI: found 6 devices [ 0.771195] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.774449] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.776579] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.778711] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.781220] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.783529] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.786524] NET: Registered protocol family 2 [ 0.789101] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.794488] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.797960] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.803491] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.807066] TCP: Hash tables configured (established 65536 bind 65536) [ 0.809882] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.812769] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.815588] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.818731] NET: Registered protocol family 1 [ 0.821915] RPC: Registered named UNIX socket transport module. [ 0.824272] RPC: Registered udp transport module. [ 0.826149] RPC: Registered tcp transport module. [ 0.827621] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.830194] NET: Registered protocol family 44 [ 0.831717] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.834097] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.835779] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.838089] PCI: CLS 0 bytes, default 64 [ 0.839643] Unpacking initramfs... [ 2.800824] debug: unmapping init [mem 0xffff9a3dbcc64000-0xffff9a3dbffcffff] [ 2.804948] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.807069] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.810023] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 3.426704] Initialise system trusted keyrings [ 3.428677] Key type blacklist registered [ 3.430945] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 3.441769] zbud: loaded [ 3.445478] *** VALIDATE nfs *** [ 3.446921] *** VALIDATE nfs4 *** [ 3.448926] pstore: using deflate compression [ 3.453565] Platform Keyring initialized [ 3.569394] NET: Registered protocol family 38 [ 3.570814] Key type asymmetric registered [ 3.571958] Asymmetric key parser 'x509' registered [ 3.573657] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 3.576809] io scheduler mq-deadline registered [ 3.578555] io scheduler kyber registered [ 3.580173] io scheduler bfq registered [ 3.582725] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 3.585452] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 3.588439] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 3.592384] ACPI: Power Button [PWRF] [ 3.598911] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 3.604655] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 3.617079] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 3.646952] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.692947] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.697579] Non-volatile memory driver v1.3 [ 3.698928] Linux agpgart interface v0.103 [ 3.733757] virtio_blk virtio1: [vda] 134040 512-byte logical blocks (68.6 MB/65.4 MiB) [ 3.736672] vda: detected capacity change from 0 to 68628480 [ 3.754464] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.757897] vdb: detected capacity change from 0 to 1073741824 [ 3.767363] libphy: Fixed MDIO Bus: probed [ 3.782224] usbcore: registered new interface driver usbserial_generic [ 3.784394] usbserial: USB Serial support registered for generic [ 3.786647] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.790806] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.792761] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.795285] mousedev: PS/2 mouse device common for all mice [ 3.800162] rtc_cmos 00:05: RTC can wake from S4 [ 3.803433] rtc_cmos 00:05: registered as rtc0 [ 3.805415] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.807679] intel_pstate: CPU model not supported [ 3.808110] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.813536] hid: raw HID events driver (C) Jiri Kosina [ 3.815727] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.817099] usbcore: registered new interface driver usbhid [ 3.817104] usbhid: USB HID core driver [ 3.817231] drop_monitor: Initializing network drop monitor service [ 3.817616] Initializing XFRM netlink socket [ 3.821174] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.822652] NET: Registered protocol family 10 [ 3.824224] Segment Routing with IPv6 [ 3.836434] NET: Registered protocol family 17 [ 3.839578] mpls_gso: MPLS GSO support [ 3.844556] RAS: Correctable Errors collector initialized. [ 3.846082] AVX version of gcm_enc/dec engaged. [ 3.847085] AES CTR mode by8 optimization enabled [ 3.931279] sched_clock: Marking stable (3931174305, 0)->(5019253513, -1088079208) [ 3.935701] registered taskstats version 1 [ 3.938476] Loading compiled-in X.509 certificates [ 3.940726] zswap: loaded using pool lzo/zbud [ 3.980477] Key type big_key registered [ 3.999596] Key type encrypted registered [ 4.001855] ima: No TPM chip found, activating TPM-bypass! [ 4.004372] ima: Allocated hash algorithm: sha1 [ 4.006558] ima: No architecture policies found [ 4.008106] evm: Initialising EVM extended attributes: [ 4.010377] evm: security.selinux [ 4.012072] evm: security.ima [ 4.013434] evm: security.capability [ 4.014864] evm: HMAC attrs: 0x1 [ 4.017995] rtc_cmos 00:05: setting system clock to 2026-01-22 09:15:10 UTC (1769073310) [ 4.027341] debug: unmapping init [mem 0xffffffffaba03000-0xffffffffabbfffff] [ 4.031433] debug: unmapping init [mem 0xffffffffaa782000-0xffffffffaaa58fff] [ 4.041142] Write protecting the kernel read-only data: 28672k [ 4.045523] debug: unmapping init [mem 0xffffffffa8e03000-0xffffffffa8ffffff] [ 4.049175] debug: unmapping init [mem 0xffffffffa9714000-0xffffffffa97fffff] [ 4.088700] 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.098206] systemd[1]: Detected virtualization kvm. [ 4.100162] systemd[1]: Detected architecture x86-64. [ 4.102723] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 4.131958] systemd[1]: No hostname configured. [ 4.133713] systemd[1]: Set hostname to . [ 4.136213] random: systemd: uninitialized urandom read (16 bytes read) [ 4.138952] systemd[1]: Initializing machine ID from random generator. [ 4.277728] random: ln: uninitialized urandom read (6 bytes read) [ 4.445417] random: systemd: uninitialized urandom read (16 bytes read) [ 4.448452] systemd[1]: Listening on udev Control Socket. [ OK ] Listening on udev Control Socket. [ 4.460293] systemd[1]: Started Dispatch Password Requests to Console Directory Watch. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ 4.473308] systemd[1]: Reached target Local Encrypted Volumes. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. [ OK ] Reached target Local File Systems. [ OK ] Listening on Journal Socket. Starting Create Volatile Files and Directories... [ OK ] Started Memstrack Anylazing Service. [ OK ] Listening on Journal Socket (/dev/log). Starting Journal Service... [ OK ] Reached target Slices. Starting Create list of required st…ce nodes for the current kernel... Starting Apply Kernel Variables... [ OK ] Reached target Swap. [ OK ] Reached target Timers. [ OK ] Reached target Initrd Root Device. Starting Setup Virtual Console... [ OK ] Listening on udev Kernel Socket. [ OK ] Reached target Sockets. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Apply Kernel Variables. [ OK ] Started Setup Virtual Console. Starting dracut cmdline hook... Starting Create Static Device Nodes in /dev... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started Journal Service. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 5.483356] device-mapper: uevent: version 1.0.3 [ 5.485839] 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.542142] random: fast init done [ 7.765488] virtio_net virtio0 ens2: renamed from eth0 [ 8.577328] scsi host0: ata_piix [ 8.656766] scsi host1: ata_piix [ 8.659709] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc120 irq 14 [ 8.668789] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc128 irq 15 [ 14.074522] random: crng init done [ 14.076726] random: 7 urandom warning(s) missed due to ratelimiting [ 16.990826] dracut-initqueue[584]: 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... [ 19.244299] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped dracut pre-pivot and cleanup hook. [ 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. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped target Timers. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Sockets. [ OK ] Stopped target Paths. [ OK ] Stopped target Slices. [ OK ] Stopped target System Initialization. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped target Swap. Stopping udev Kernel Device Manager... [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Closed udev Kernel Socket. [ OK ] Closed udev Control Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 22.138741] printk: systemd: 26 output lines suppressed due to ratelimiting [ 22.632375] SELinux: Disabled at runtime. [ 22.704805] 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) [ 22.715879] systemd[1]: Detected virtualization kvm. [ 22.718460] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 24.450814] systemd[1]: initrd-switch-root.service: Succeeded. [ 24.454198] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 24.460964] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 24.465718] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 24.469463] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 24.526275] systemd[1]: Starting Journal Service... Starting Journal Service... [ 24.726443] systemd[1]: Started Forward Password Requests to Wall Directory Watch. [ OK ] Started Forward Password Requests to Wall Directory Watch. Starting Remount Root and Kernel File Systems... Starting Create list of required st…ce nodes for the current kernel... [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Listening on Process Core Dump Socket. Mounting Huge Pages File System... Activating swap /dev/disk/by-label/SWAP... Mounting Kernel Debug File System... Mounting POSIX Message Queue File System... [ OK ] Listening on udev Control Socket. [ OK ] Listening on ini[ 25.721816] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS tctl Compatibility Named Pipe. [ OK ] Created slice User and Session Slice. [ OK ] Listening on udev Kernel Socket. Starting udev Coldplug all Devices... Starting Apply Kernel Variables... [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd File Systems. [ OK ] Stopped target Initrd Root File System. [ OK ] Reached target rpc_pipefs.target. [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Reached target RPC Port Mapper. [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. [ OK ] Reached target Slices. [ OK ] Created slice system-getty.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 Create list of required sta…vice nodes for the current kernel. [ OK ] Mounted Huge Pages File System. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Mounted Kernel Debug File System. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Started Apply Kernel Variables. [ OK ] Reached target Swap. Starting Create Static Device Nodes in /dev... Starting Configure read-only root support... Starting Flush Journal to Persistent Storage... [ OK ] Started udev Coldplug all Devices. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started Flush Journal to Persistent Storage. Starting udev Kernel Device Manager... [ OK ] Reached target Local File Systems (Pre). Mounting /home/green/git/lustre-release... Mounting /mnt... [ OK ] Mounted /mnt. [ 27.546609] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 30.029980] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 30.234528] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 31.198436] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 31.282452] EDAC sbridge: Ver: 1.1.2 [* ] A start job is running for Configur…only root support (10s / no limit)[ 35.258089] Key type dns_resolver registered [** ] A start job is running for Configur…only root support (11s / no limit)[ 35.624788] NFS: Registering the id_resolver key type [ 35.627188] Key type id_resolver registered [ 35.629021] Key type id_legacy registered [*** ] A start job is running for Configur…only root support (11s / no limit) [ *** ] A start job is running for Configur…only root support (12s / no limit) [ OK ] Started Configure read-only root support. [ OK ] Reached target Local File Systems. Starting Mark the need to relabel after reboot... Starting Rebuild Dynamic Linker Cache... Starting Create Volatile Files and Directories... Starting Load/Save Random Seed... [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Load/Save Random Seed. [ OK ] Started Create Volatile Files and Directories. Starting 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 ] Started Daily Cleanup of Temporary Directories. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Started dnf makecache --timer. [ OK ] Reached target Timers. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting Restore /run/initramfs on shutdown... [ OK ] Started irqbalance daemon. [ OK ] Reached target sshd-keygen.target. Starting Login Service... [ OK ] Started D-Bus System Message Bus. Starting Network Manager... [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Login Service. [ OK ] Started Network Manager. Starting Network Manager Wait Online... [ OK ] Reached target Network. Starting Dynamic System Tuning Daemon... Starting GSSAPI Proxy Daemon... Starting OpenSSH server daemon... [ OK ] Started GSSAPI Proxy Daemon. Starting Hostname Service... [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... [ OK ] Started Permit User Sessions. [ OK ] Started Command Scheduler. [ OK ] Started Serial Getty on ttyS1. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Getty on tty1. [ OK ] Reached target Login Prompts. [ OK ] Started OpenSSH server daemon. [ 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. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg256-client login: [ 122.510163] hrtimer: interrupt took 4153833 ns [ 123.104862] libcfs: loading out-of-tree module taints kernel. [ 123.622191] Key type ._llcrypt registered [ 123.657852] Key type .llcrypt registered [ 124.305341] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [ 124.316740] alg: No test for adler32 (adler32-zlib) [ 125.966168] Lustre: Lustre: Build Version: 2.17.50_3_g69d656b [ 127.172239] LNet: Added LNI 192.168.202.56@tcp [8/256/0/180] [ 129.008753] Key type lgssc registered [ 131.249811] Lustre: Echo OBD driver; http://www.lustre.org/ [ 285.117996] Lustre: Mounted lustre-client [ 291.145652] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 310.753264] Lustre: lustre-OST0000-osc-ffff9a3e0b67e800: disconnect after 23s idle [ 315.212441] Lustre: DEBUG MARKER: oleg256-client.virtnet: executing check_logdir /tmp/testlogs/ [ 320.529784] Lustre: DEBUG MARKER: oleg256-client.virtnet: executing yml_node [ 327.517443] Lustre: DEBUG MARKER: Client: 2.17.50.3 [ 330.828877] Lustre: DEBUG MARKER: MDS: 2.17.50.3 [ 334.105812] Lustre: DEBUG MARKER: OSS: 2.17.50.3 [ 336.718711] Lustre: DEBUG MARKER: -----============= acceptance-small: recovery-small ============----- Thu Jan 22 04:20:40 EST 2026 [ 359.513995] Lustre: DEBUG MARKER: excepting tests: 136 [ 361.851554] Lustre: DEBUG MARKER: === recovery-small: start setup 04:21:06 (1769073666) === [ 366.052371] Lustre: DEBUG MARKER: oleg256-client.virtnet: executing check_config_client /mnt/lustre [ 387.360430] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 402.441490] Lustre: DEBUG MARKER: === recovery-small: finish setup 04:21:47 (1769073707) === [ 404.648285] Lustre: DEBUG MARKER: == recovery-small test 1: create, chmod, stat: drop req, drop rep ========================================================== 04:21:49 (1769073709) [ 422.368343] Lustre: 9984:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1769073712/real 1769073712] req@ffff9a3e08e29c00 x1855007944094720/t0(0) o700->lustre-MDT0000-mdc-ffff9a3e0b67e800@192.168.202.156@tcp:30/10 lens 264/248 e 0 to 1 dl 1769073728 ref 2 fl Rpc:XQr/200/ffffffff rc 0/-1 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 422.424716] Lustre: lustre-MDT0000-mdc-ffff9a3e0b67e800: Connection to lustre-MDT0000 (at 192.168.202.156@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 422.482455] Lustre: lustre-MDT0000-mdc-ffff9a3e0b67e800: Connection restored to 192.168.202.156@tcp (at 192.168.202.156@tcp) [ 440.802505] Lustre: 10005:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1769073731/real 1769073731] req@ffff9a3e08e2a680 x1855007944096512/t0(0) o36->lustre-MDT0000-mdc-ffff9a3e0b67e800@192.168.202.156@tcp:12/10 lens 520/576 e 0 to 1 dl 1769073747 ref 2 fl Rpc:XQr/200/ffffffff rc 0/-1 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 440.829151] Lustre: lustre-MDT0000-mdc-ffff9a3e0b67e800: Connection to lustre-MDT0000 (at 192.168.202.156@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 440.883132] Lustre: lustre-MDT0000-mdc-ffff9a3e0b67e800: Connection restored to 192.168.202.156@tcp (at 192.168.202.156@tcp) [ 459.744386] Lustre: 10032:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1769073750/real 1769073750] req@ffff9a3e0c4bce00 x1855007944097792/t0(0) o101->lustre-MDT0000-mdc-ffff9a3e0b67e800@192.168.202.156@tcp:12/10 lens 576/1152 e 0 to 1 dl 1769073766 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'tchmod.0' uid:0 gid:0 projid:0 [ 459.793428] Lustre: lustre-MDT0000-mdc-ffff9a3e0b67e800: Connection to lustre-MDT0000 (at 192.168.202.156@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 459.872145] Lustre: lustre-MDT0000-mdc-ffff9a3e0b67e800: Connection restored to 192.168.202.156@tcp (at 192.168.202.156@tcp) [ 478.693089] Lustre: 10053:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1769073769/real 1769073769] req@ffff9a3e08e5df80 x1855007944099968/t0(0) o36->lustre-MDT0000-mdc-ffff9a3e0b67e800@192.168.202.156@tcp:12/10 lens 488/512 e 0 to 1 dl 1769073785 ref 2 fl Rpc:XQr/200/ffffffff rc 0/-1 job:'tchmod.0' uid:0 gid:0 projid:4294967295 [ 478.724300] Lustre: lustre-MDT0000-mdc-ffff9a3e0b67e800: Connection to lustre-MDT0000 (at 192.168.202.156@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 478.793045] Lustre: lustre-MDT0000-mdc-ffff9a3e0b67e800: Connection restored to 192.168.202.156@tcp (at 192.168.202.156@tcp) [ 500.707424] Lustre: 10096:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1769073791/real 1769073791] req@ffff9a3e0c4bca80 x1855007944101632/t0(0) o34->lustre-MDT0000-mdc-ffff9a3e0b67e800@192.168.202.156@tcp:12/10 lens 472/728 e 0 to 1 dl 1769073807 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'statone.0' uid:0 gid:0 projid:0 [ 500.737342] Lustre: lustre-MDT0000-mdc-ffff9a3e0b67e800: Connection to lustre-MDT0000 (at 192.168.202.156@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 500.794886] Lustre: lustre-MDT0000-mdc-ffff9a3e0b67e800: Connection restored to 192.168.202.156@tcp (at 192.168.202.156@tcp) [ 511.078493] Lustre: DEBUG MARKER: == recovery-small test 4: open: drop req, drop rep ======= 04:23:35 (1769073815) [ 529.376168] Lustre: 10700:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1769073819/real 1769073819] req@ffff9a3e08e5ca80 x1855007944104192/t0(0) o101->lustre-MDT0000-mdc-ffff9a3e0b67e800@192.168.202.156@tcp:12/10 lens 576/1152 e 0 to 1 dl 1769073835 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'cat.0' uid:0 gid:0 projid:0 [ 529.437560] Lustre: lustre-MDT0000-mdc-ffff9a3e0b67e800: Connection to lustre-MDT0000 (at 192.168.202.156@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 529.488316] Lustre: lustre-MDT0000-mdc-ffff9a3e0b67e800: Connection restored to 192.168.202.156@tcp (at 192.168.202.156@tcp) [ 547.808681] Lustre: 10721:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1769073838/real 1769073838] req@ffff9a3e08e29880 x1855007944107392/t0(0) o35->lustre-MDT0000-mdc-ffff9a3e0b67e800@192.168.202.156@tcp:23/10 lens 392/624 e 0 to 1 dl 1769073854 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'cat.0' uid:0 gid:0 projid:0 [ 547.849561] Lustre: lustre-MDT0000-mdc-ffff9a3e0b67e800: Connection to lustre-MDT0000 (at 192.168.202.156@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 547.904456] Lustre: lustre-MDT0000-mdc-ffff9a3e0b67e800: Connection restored to 192.168.202.156@tcp (at 192.168.202.156@tcp) [ 557.077652] Lustre: DEBUG MARKER: == recovery-small test 5: rename: drop req, drop rep ===== 04:24:21 (1769073861) [ 593.888756] Lustre: 11343:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1769073884/real 1769073884] req@ffff9a3e0c4bea00 x1855007944113920/t0(0) o36->lustre-MDT0000-mdc-ffff9a3e0b67e800@192.168.202.156@tcp:13/10 lens 552/624 e 0 to 1 dl 1769073900 ref 2 fl Rpc:XQr/200/ffffffff rc 0/-1 job:'mv.0' uid:0 gid:0 projid:4294967295 [ 593.923220] Lustre: 11343:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 593.935967] Lustre: lustre-MDT0000-mdc-ffff9a3e0b67e800: Connection to lustre-MDT0000 (at 192.168.202.156@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 593.958098] Lustre: Skipped 1 previous similar message [ 594.008992] Lustre: lustre-MDT0000-mdc-ffff9a3e0b67e800: Connection restored to 192.168.202.156@tcp (at 192.168.202.156@tcp) [ 594.019701] Lustre: Skipped 1 previous similar message [ 603.502494] Lustre: DEBUG MARKER: == recovery-small test 6: link, unlink: drop req, drop rep ========================================================== 04:25:08 (1769073908) [ 619.492488] Lustre: lustre-OST0001-osc-ffff9a3e0b67e800: disconnect after 23s idle [ 619.509138] Lustre: Skipped 1 previous similar message [ 660.960254] Lustre: 12002:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1769073951/real 1769073951] req@ffff9a3e08e5d180 x1855007944123904/t0(0) o101->lustre-MDT0000-mdc-ffff9a3e0b67e800@192.168.202.156@tcp:12/10 lens 576/1152 e 0 to 1 dl 1769073967 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'unlink.0' uid:0 gid:0 projid:0 [ 660.997399] Lustre: 12002:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 661.023403] Lustre: lustre-MDT0000-mdc-ffff9a3e0b67e800: Connection to lustre-MDT0000 (at 192.168.202.156@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 661.047610] Lustre: Skipped 2 previous similar messages [ 661.092100] Lustre: lustre-MDT0000-mdc-ffff9a3e0b67e800: Connection restored to 192.168.202.156@tcp (at 192.168.202.156@tcp) [ 661.110683] Lustre: Skipped 2 previous similar messages [ 689.965989] Lustre: DEBUG MARKER: == recovery-small test 8: touch: drop rep (bug 1423) ===== 04:26:34 (1769073994) [ 716.839759] Lustre: DEBUG MARKER: == recovery-small test 9: pause bulk on OST (bug 1420) === 04:27:01 (1769074021) [ 732.251235] Lustre: DEBUG MARKER: == recovery-small test 10a: finish request on server after client eviction (bug 1521) ========================================================== 04:27:17 (1769074037) [ 733.146374] Lustre: *** cfs_fail_loc=305, val=0*** [ 749.807440] Lustre: *** cfs_fail_loc=305, val=0*** [ 752.610653] Lustre: lustre-OST0001-osc-ffff9a3e0b67e800: disconnect after 24s idle [ 766.216088] Lustre: *** cfs_fail_loc=305, val=0*** [ 782.561793] Lustre: *** cfs_fail_loc=305, val=0*** [ 797.930623] Lustre: *** cfs_fail_loc=305, val=0*** [ 814.360890] Lustre: *** cfs_fail_loc=305, val=0*** [ 830.708126] Lustre: *** cfs_fail_loc=305, val=0*** [ 846.522871] LustreError: lustre-MDT0000-mdc-ffff9a3e0b67e800: operation ldlm_enqueue to node 192.168.202.156@tcp failed: rc = -107 [ 846.529492] Lustre: lustre-MDT0000-mdc-ffff9a3e0b67e800: Connection to lustre-MDT0000 (at 192.168.202.156@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 846.542315] Lustre: Skipped 2 previous similar messages [ 846.556685] LustreError: lustre-MDT0000-mdc-ffff9a3e0b67e800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 846.587963] Lustre: lustre-MDT0000-mdc-ffff9a3e0b67e800: Connection restored to 192.168.202.156@tcp (at 192.168.202.156@tcp) [ 846.605676] Lustre: Skipped 2 previous similar messages [ 856.740359] Lustre: DEBUG MARKER: == recovery-small test 10b: re-send BL AST =============== 04:29:21 (1769074161) [ 870.370351] Lustre: lustre-OST0001-osc-ffff9a3e0b67e800: disconnect after 23s idle [ 884.243062] Lustre: DEBUG MARKER: == recovery-small test 10c: re-send BL AST vs reconnect race (LU-5569) ========================================================== 04:29:48 (1769074188) [ 884.996494] Lustre: *** cfs_fail_loc=305, val=0*** [ 885.005996] Lustre: Skipped 1 previous similar message [ 895.250667] Lustre: DEBUG MARKER: == recovery-small test 10d: test failed blocking ast ===== 04:29:59 (1769074199) [ 898.843612] LustreError: 15868:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff9a3e0b67e800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 898.862951] LustreError: 15868:0:(obd_class.h:479:obd_check_dev()) Device 5 not setup [ 898.901860] Lustre: Unmounted lustre-client [ 899.320736] Lustre: Mounted lustre-client [ 899.906956] Lustre: Mounted lustre-client [ 901.324148] LustreError: lustre-OST0000-osc-ffff9a3e09bc4000: operation ldlm_enqueue to node 192.168.202.156@tcp failed: rc = -107 [ 901.348827] LustreError: lustre-OST0000-osc-ffff9a3e09bc4000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 901.402643] Lustre: 2378:0:(llite_lib.c:4226:ll_dirty_page_discard_warn()) lustre: dirty page discard: 192.168.202.156@tcp:/lustre/fid: [0x200000403:0x1:0x0]/ may get corrupted (rc -108) [ 904.074349] LustreError: 16063:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff9a3e0c9fe000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 904.101896] LustreError: 16063:0:(lov_obd.c:783:lov_cleanup()) Skipped 1 previous similar message [ 904.132807] LustreError: 16063:0:(obd_class.h:479:obd_check_dev()) Device 10 not setup [ 904.145095] LustreError: 16063:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 904.199236] Lustre: Unmounted lustre-client [ 910.830362] Lustre: DEBUG MARKER: == recovery-small test 10e: re-send BL AST vs reconnect race 2 ========================================================== 04:30:15 (1769074215) [ 912.444001] Lustre: DEBUG MARKER: SKIP: recovery-small test_10e need two clients [ 913.898743] Lustre: DEBUG MARKER: == recovery-small test 11: wake up a thread waiting for completion after eviction (b=2460) ========================================================== 04:30:19 (1769074219) [ 941.029223] Lustre: DEBUG MARKER: == recovery-small test 12: recover from timed out resend in ptlrpcd (b=2494) ========================================================== 04:30:45 (1769074245) [ 941.279283] Lustre: DEBUG MARKER: multiop /mnt/lustre/f12.recovery-small OS_c [ 958.944831] Lustre: 17626:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1769074249/real 1769074249] req@ffff9a3e0c4bdc00 x1855007944193664/t0(0) o35->lustre-MDT0000-mdc-ffff9a3e09bc4000@192.168.202.156@tcp:23/10 lens 392/624 e 0 to 1 dl 1769074265 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'multiop.0' uid:0 gid:0 projid:0 [ 959.019751] Lustre: 17626:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 985.997447] Lustre: DEBUG MARKER: == recovery-small test 13: mdc_readpage restart test (bug 1138) ========================================================== 04:31:31 (1769074291) [ 1013.975718] Lustre: DEBUG MARKER: == recovery-small test 14: mdc_readpage resend test (bug 1138) ========================================================== 04:31:58 (1769074318) [ 1024.038874] Lustre: DEBUG MARKER: == recovery-small test 15: failed open (-ENOMEM) ========= 04:32:08 (1769074328) [ 1033.798761] Lustre: DEBUG MARKER: == recovery-small test 16: timeout bulk put, don't evict client (2732) ========================================================== 04:32:18 (1769074338) [ 1081.169275] Lustre: DEBUG MARKER: == recovery-small test 17a: timeout bulk get, don't evict client (2732) ========================================================== 04:33:06 (1769074386) [ 1136.529060] Lustre: DEBUG MARKER: == recovery-small test 17b: timeout bulk get, dont evict client (3582) ========================================================== 04:34:01 (1769074441) [ 1138.428612] Lustre: DEBUG MARKER: SKIP: recovery-small test_17b Needs multiple clients [ 1140.717388] Lustre: DEBUG MARKER: == recovery-small test 18a: manual ost invalidate clears page cache immediately ========================================================== 04:34:05 (1769074445) [ 1141.834423] Lustre: setting import lustre-OST0001_UUID INACTIVE by administrator request [ 1141.913487] Lustre: lustre-OST0001-osc-ffff9a3e09bc4000: Connection to lustre-OST0001 (at 192.168.202.156@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1141.926672] Lustre: Skipped 5 previous similar messages [ 1141.962891] LustreError: lustre-OST0001-osc-ffff9a3e09bc4000: This client was evicted by lustre-OST0001; in progress operations using this service will fail. [ 1141.983719] Lustre: lustre-OST0001-osc-ffff9a3e09bc4000: Connection restored to 192.168.202.156@tcp (at 192.168.202.156@tcp) [ 1141.998084] Lustre: Skipped 4 previous similar messages [ 1150.745840] Lustre: DEBUG MARKER: == recovery-small test 18b: eviction and reconnect clears page cache (2766) ========================================================== 04:34:15 (1769074455) [ 1154.559912] LustreError: lustre-OST0000-osc-ffff9a3e09bc4000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 1186.356589] Lustre: DEBUG MARKER: == recovery-small test 18c: Dropped connect reply after eviction handing (14755) ========================================================== 04:34:50 (1769074490) [ 1199.595308] Lustre: Evicted from lustre-OST0000_UUID (at 192.168.202.156@tcp) after server handle changed from 0x66da280ed2fb563a to 0x66da280ed2fb576e [ 1199.600512] LustreError: lustre-OST0000-osc-ffff9a3e09bc4000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 1209.395951] Lustre: DEBUG MARKER: == recovery-small test 19a: test expired_lock_main on mds (2867) ========================================================== 04:35:14 (1769074514) [ 1210.078590] Lustre: Mounted lustre-client [ 1226.720455] Lustre: 2377:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1769074517/real 1769074517] req@ffff9a3e0c4bf100 x1855007944252416/t0(0) o103->lustre-MDT0000-mdc-ffff9a3e09bc4000@192.168.202.156@tcp:17/18 lens 328/224 e 0 to 1 dl 1769074533 ref 1 fl Rpc:XQr/200/ffffffff rc 0/-1 job:'ldlm_bl.0' uid:0 gid:0 projid:4294967295 [ 1226.752221] Lustre: 2377:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 1316.876161] LustreError: lustre-MDT0000-mdc-ffff9a3e09bc4000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 1316.890189] LustreError: 23875:0:(file.c:249:ll_close_inode_openhandle()) lustre-clilmv-ffff9a3e09bc4000: inode [0x200000403:0x1:0x0] mdc close failed: rc = -108 [ 1318.691870] LustreError: 23891:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff9a3e0b77e800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 1318.706410] LustreError: 23891:0:(lov_obd.c:783:lov_cleanup()) Skipped 1 previous similar message [ 1318.717803] LustreError: 23891:0:(obd_class.h:479:obd_check_dev()) Device 10 not setup [ 1318.734454] LustreError: 23891:0:(obd_class.h:479:obd_check_dev()) Skipped 5 previous similar messages [ 1318.762876] Lustre: Unmounted lustre-client [ 1326.736919] Lustre: DEBUG MARKER: == recovery-small test 19b: test expired_lock_main on ost (2867) ========================================================== 04:37:11 (1769074631) [ 1327.351423] Lustre: Mounted lustre-client [ 1436.180182] LustreError: lustre-OST0000-osc-ffff9a3e09bc4000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 1438.021391] LustreError: 24680:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff9a3e0903b800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 1438.026603] LustreError: 24680:0:(lov_obd.c:783:lov_cleanup()) Skipped 1 previous similar message [ 1438.031530] LustreError: 24680:0:(obd_class.h:479:obd_check_dev()) Device 10 not setup [ 1438.034592] LustreError: 24680:0:(obd_class.h:479:obd_check_dev()) Skipped 5 previous similar messages [ 1438.057650] Lustre: Unmounted lustre-client [ 1446.173647] Lustre: DEBUG MARKER: == recovery-small test 19c: check reconnect and lock resend do not trigger expired_lock_main ========================================================== 04:39:11 (1769074751) [ 1446.874428] Lustre: Mounted lustre-client [ 1452.220989] LustreError: 25349:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff9a3e0bbff000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 1452.231552] LustreError: 25349:0:(lov_obd.c:783:lov_cleanup()) Skipped 1 previous similar message [ 1452.243754] LustreError: 25349:0:(obd_class.h:479:obd_check_dev()) Device 10 not setup [ 1452.249493] LustreError: 25349:0:(obd_class.h:479:obd_check_dev()) Skipped 5 previous similar messages [ 1452.292459] Lustre: Unmounted lustre-client [ 1464.438065] Lustre: DEBUG MARKER: == recovery-small test 20a: ldlm_handle_enqueue error (should return error) ========================================================== 04:39:29 (1769074769) [ 1466.836381] LustreError: lustre-OST0000-osc-ffff9a3e09bc4000: operation ldlm_enqueue to node 192.168.202.156@tcp failed: rc = -12 [ 1473.088659] Lustre: DEBUG MARKER: == recovery-small test 20b: ldlm_handle_enqueue error (should return error) ========================================================== 04:39:38 (1769074778) [ 1474.637215] LustreError: lustre-OST0000-osc-ffff9a3e09bc4000: operation ldlm_enqueue to node 192.168.202.156@tcp failed: rc = -12 [ 1482.511593] Lustre: DEBUG MARKER: == recovery-small test 21a: drop close request while close and open are both in flight ========================================================== 04:39:47 (1769074787) [ 1512.340807] Lustre: DEBUG MARKER: == recovery-small test 21b: drop open request while close and open are both in flight ========================================================== 04:40:17 (1769074817) [ 1658.175464] Lustre: DEBUG MARKER: == recovery-small test 21c: drop both request while close and open are both in flight ========================================================== 04:42:43 (1769074963) [ 1680.352299] Lustre: lustre-MDT0000-mdc-ffff9a3e09bc4000: Connection to lustre-MDT0000 (at 192.168.202.156@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1680.367632] Lustre: Skipped 18 previous similar messages [ 1680.407193] Lustre: lustre-MDT0000-mdc-ffff9a3e09bc4000: Connection restored to 192.168.202.156@tcp (at 192.168.202.156@tcp) [ 1680.418653] Lustre: Skipped 15 previous similar messages [ 1689.282953] Lustre: DEBUG MARKER: == recovery-small test 21d: drop close reply while close and open are both in flight ========================================================== 04:43:14 (1769074994) [ 1719.423607] Lustre: DEBUG MARKER: == recovery-small test 21e: drop open reply while close and open are both in flight ========================================================== 04:43:44 (1769075024) [ 1858.528172] Lustre: 29649:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1769075027/real 1769075027] req@ffff9a3e0c4bd880 x1855007944362880/t0(0) o36->lustre-MDT0000-mdc-ffff9a3e09bc4000@192.168.202.156@tcp:12/10 lens 488/512 e 0 to 1 dl 1769075165 ref 2 fl Rpc:XQr/200/ffffffff rc 0/-1 job:'touch.0' uid:0 gid:0 projid:4294967295 [ 1858.571626] Lustre: 29649:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 15 previous similar messages [ 1861.108385] Lustre: DEBUG MARKER: == recovery-small test 21f: drop both reply while close and open are both in flight ========================================================== 04:46:05 (1769075165) [ 1890.777155] Lustre: DEBUG MARKER: == recovery-small test 21g: drop open reply and close request while close and open are both in flight ========================================================== 04:46:35 (1769075195) [ 1917.748942] Lustre: DEBUG MARKER: == recovery-small test 21h: drop open request and close reply while close and open are both in flight ========================================================== 04:47:02 (1769075222) [ 1943.680457] Lustre: DEBUG MARKER: == recovery-small test 22: drop close request and do mknod ========================================================== 04:47:28 (1769075248) [ 1968.792784] Lustre: DEBUG MARKER: == recovery-small test 23: client hang when close a file after mds crash ========================================================== 04:47:54 (1769075274) [ 1997.794063] LustreError: MGC192.168.202.156@tcp: Connection to MGS (at 192.168.202.156@tcp) was lost; in progress operations using this service will fail [ 2008.118193] Lustre: Evicted from MGS (at 192.168.202.156@tcp) after server handle changed from 0x66da280ed2fb4d1f to 0x66da280ed2fb71e6 [ 2021.131917] Lustre: DEBUG MARKER: oleg256-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2023.189608] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2031.446540] Lustre: DEBUG MARKER: == recovery-small test 24a: fsync error (should return error) ========================================================== 04:48:56 (1769075336) [ 2033.930153] LustreError: lustre-OST0000-osc-ffff9a3e09bc4000: operation ost_write to node 192.168.202.156@tcp failed: rc = -107 [ 2033.964824] LustreError: lustre-OST0000-osc-ffff9a3e09bc4000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 2033.989528] Lustre: 2377:0:(llite_lib.c:4226:ll_dirty_page_discard_warn()) lustre: dirty page discard: 192.168.202.156@tcp:/lustre/fid: [0x200000404:0x30:0x0]// may get corrupted (rc -5) [ 2043.981557] Lustre: DEBUG MARKER: == recovery-small test 24b: test dirty page discard due to client eviction ========================================================== 04:49:08 (1769075348) [ 2046.238369] LustreError: lustre-OST0000-osc-ffff9a3e09bc4000: operation ost_sync to node 192.168.202.156@tcp failed: rc = -107 [ 2046.268707] LustreError: lustre-OST0000-osc-ffff9a3e09bc4000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 2046.310944] Lustre: 2375:0:(llite_lib.c:4226:ll_dirty_page_discard_warn()) lustre: dirty page discard: 192.168.202.156@tcp:/lustre/fid: [0x200000404:0x35:0x0]// may get corrupted (rc -108) [ 2054.399618] Lustre: DEBUG MARKER: == recovery-small test 26a: evict dead exports =========== 04:49:19 (1769075359) [ 2056.471527] Lustre: DEBUG MARKER: SKIP: recovery-small test_26a msg and ost1 are at the same node [ 2058.034508] Lustre: DEBUG MARKER: == recovery-small test 26b: evict dead exports =========== 04:49:23 (1769075363) [ 2060.343438] Lustre: DEBUG MARKER: SKIP: recovery-small test_26b msg and ost1 are at the same node [ 2062.844397] Lustre: DEBUG MARKER: == recovery-small test 27: fail LOV while using OSC's ==== 04:49:27 (1769075367) [ 2067.435582] LustreError: lustre-MDT0000-mdc-ffff9a3e09bc4000: operation ldlm_enqueue to node 192.168.202.156@tcp failed: rc = -19 [ 2087.931225] LustreError: MGC192.168.202.156@tcp: Connection to MGS (at 192.168.202.156@tcp) was lost; in progress operations using this service will fail [ 2087.963427] Lustre: Evicted from MGS (at 192.168.202.156@tcp) after server handle changed from 0x66da280ed2fb71e6 to 0x66da280ed2fb8c34 [ 2199.333045] LustreError: lustre-MDT0000-mdc-ffff9a3e09bc4000: operation mds_close to node 192.168.202.156@tcp failed: rc = -19 [ 2217.505600] LustreError: MGC192.168.202.156@tcp: Connection to MGS (at 192.168.202.156@tcp) was lost; in progress operations using this service will fail [ 2227.752826] Lustre: Evicted from MGS (at 192.168.202.156@tcp) after server handle changed from 0x66da280ed2fb8c34 to 0x66da280ed2fd5509 [ 2243.617352] Lustre: DEBUG MARKER: == recovery-small test 28: handle error adding new clients (bug 6086) ========================================================== 04:52:28 (1769075548) [ 2244.186773] Lustre: *** cfs_fail_loc=305, val=0*** [ 2244.188698] Lustre: Skipped 2 previous similar messages [ 2287.087670] LustreError: MGC192.168.202.156@tcp: Connection to MGS (at 192.168.202.156@tcp) was lost; in progress operations using this service will fail [ 2287.125589] Lustre: Evicted from MGS (at 192.168.202.156@tcp) after server handle changed from 0x66da280ed2fd5509 to 0x66da280ed2fd5755 [ 2287.141405] Lustre: MGC192.168.202.156@tcp: Connection restored to 192.168.202.156@tcp (at 192.168.202.156@tcp) [ 2287.148270] Lustre: Skipped 13 previous similar messages [ 2297.329177] Lustre: lustre-MDT0000-mdc-ffff9a3e09bc4000: Connection to lustre-MDT0000 (at 192.168.202.156@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 2297.347306] Lustre: Skipped 11 previous similar messages [ 2310.849548] Lustre: DEBUG MARKER: oleg256-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2312.924218] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2325.838652] Lustre: DEBUG MARKER: == recovery-small test 29a: error adding new clients doesn't cause LBUG (bug 22273) ========================================================== 04:53:49 (1769075629) [ 2343.413133] LustreError: MGC192.168.202.156@tcp: Connection to MGS (at 192.168.202.156@tcp) was lost; in progress operations using this service will fail [ 2343.448677] Lustre: Evicted from MGS (at 192.168.202.156@tcp) after server handle changed from 0x66da280ed2fd5755 to 0x66da280ed2fd5d36 [ 2343.557938] LustreError: lustre-MDT0000-mdc-ffff9a3e09bc4000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 2368.280572] Lustre: DEBUG MARKER: == recovery-small test 29b: error adding new clients doesn't cause LBUG (bug 22273) ========================================================== 04:54:33 (1769075673) [ 2381.375464] LustreError: lustre-OST0000-osc-ffff9a3e09bc4000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 2399.491658] Lustre: DEBUG MARKER: == recovery-small test 50: failover MDS under load ======= 04:55:04 (1769075704) [ 2413.442214] LustreError: lustre-MDT0000-mdc-ffff9a3e09bc4000: operation ldlm_enqueue to node 192.168.202.156@tcp failed: rc = -19 [ 2413.446290] LustreError: Skipped 1 previous similar message [ 2431.460392] LustreError: MGC192.168.202.156@tcp: Connection to MGS (at 192.168.202.156@tcp) was lost; in progress operations using this service will fail [ 2440.628762] Lustre: Evicted from MGS (at 192.168.202.156@tcp) after server handle changed from 0x66da280ed2fd5d36 to 0x66da280ed2fdaf92 [ 2456.045937] Lustre: DEBUG MARKER: oleg256-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2458.873444] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2547.209673] LustreError: MGC192.168.202.156@tcp: Connection to MGS (at 192.168.202.156@tcp) was lost; in progress operations using this service will fail [ 2547.250732] Lustre: Evicted from MGS (at 192.168.202.156@tcp) after server handle changed from 0x66da280ed2fdaf92 to 0x66da280ed2ff4155 [ 2572.370659] Lustre: DEBUG MARKER: oleg256-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2574.920718] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2641.236869] LustreError: lustre-MDT0000-mdc-ffff9a3e09bc4000: operation ldlm_enqueue to node 192.168.202.156@tcp failed: rc = -19 [ 2641.261570] LustreError: Skipped 3 previous similar messages [ 2658.720959] Lustre: 2376:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1769075949/real 1769075949] req@ffff9a3e07480380 x1855007949172608/t0(0) o400->MGC192.168.202.156@tcp@192.168.202.156@tcp:26/25 lens 224/224 e 0 to 1 dl 1769075965 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2658.744061] Lustre: 2376:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 14 previous similar messages [ 2658.752660] LustreError: MGC192.168.202.156@tcp: Connection to MGS (at 192.168.202.156@tcp) was lost; in progress operations using this service will fail [ 2668.984452] Lustre: Evicted from MGS (at 192.168.202.156@tcp) after server handle changed from 0x66da280ed2ff4155 to 0x66da280ed300f4f2 [ 2688.208349] Lustre: DEBUG MARKER: oleg256-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2690.775543] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2721.058819] Lustre: DEBUG MARKER: == recovery-small test 51: failover MDS during recovery == 05:00:25 (1769076025) [ 2744.800551] LustreError: MGC192.168.202.156@tcp: Connection to MGS (at 192.168.202.156@tcp) was lost; in progress operations using this service will fail [ 2755.071390] Lustre: Evicted from MGS (at 192.168.202.156@tcp) after server handle changed from 0x66da280ed300f4f2 to 0x66da280ed301c707 [ 2764.604916] Lustre: DEBUG MARKER: test_51: failover in 1 sec [ 2800.231815] Lustre: DEBUG MARKER: test_51: failover in 5 sec [ 2850.147535] Lustre: DEBUG MARKER: test_51: failover in 10 sec [ 2885.113511] LustreError: MGC192.168.202.156@tcp: Connection to MGS (at 192.168.202.156@tcp) was lost; in progress operations using this service will fail [ 2885.116880] LustreError: Skipped 2 previous similar messages [ 2885.134186] Lustre: Evicted from MGS (at 192.168.202.156@tcp) after server handle changed from 0x66da280ed301f17e to 0x66da280ed3024f25 [ 2885.138896] Lustre: Skipped 2 previous similar messages [ 2904.107621] Lustre: DEBUG MARKER: test_51: failover in 20 sec [ 2904.739373] Lustre: lustre-MDT0000-mdc-ffff9a3e09bc4000: Connection restored to 192.168.202.156@tcp (at 192.168.202.156@tcp) [ 2904.764077] Lustre: Skipped 17 previous similar messages [ 2927.704170] LustreError: lustre-MDT0000-mdc-ffff9a3e09bc4000: operation mds_close to node 192.168.202.156@tcp failed: rc = -19 [ 2927.712807] LustreError: Skipped 6 previous similar messages [ 2927.718176] Lustre: lustre-MDT0000-mdc-ffff9a3e09bc4000: Connection to lustre-MDT0000 (at 192.168.202.156@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 2927.726756] Lustre: Skipped 9 previous similar messages [ 2963.484102] Lustre: DEBUG MARKER: test_51: failover in 25 sec [ 3020.889824] Lustre: DEBUG MARKER: test_51: failover in 30 sec [ 3109.070698] Lustre: DEBUG MARKER: == recovery-small test 52: failover OST under load ======= 05:06:54 (1769076414) [ 3163.881447] Lustre: DEBUG MARKER: oleg256-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 3166.039135] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 3455.295419] LustreError: lustre-OST0000-osc-ffff9a3e09bc4000: operation ost_write to node 192.168.202.156@tcp failed: rc = -19 [ 3455.305047] LustreError: Skipped 7 previous similar messages [ 3495.933216] Lustre: DEBUG MARKER: oleg256-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 3498.557963] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 3785.536518] Lustre: lustre-OST0000-osc-ffff9a3e09bc4000: Connection to lustre-OST0000 (at 192.168.202.156@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 3785.563967] Lustre: Skipped 4 previous similar messages [ 3824.668546] Lustre: DEBUG MARKER: oleg256-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 3828.073937] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4081.978542] Lustre: DEBUG MARKER: == recovery-small test 53a: touch: drop rep ============== 05:23:06 (1769077386) [ 4100.066804] Lustre: 50277:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1769077390/real 1769077390] req@ffff9a3e07ef0000 x1855007970064512/t0(0) o101->lustre-MDT0000-mdc-ffff9a3e09bc4000@192.168.202.156@tcp:12/10 lens 576/1152 e 0 to 1 dl 1769077406 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'openfile.0' uid:0 gid:0 projid:0 [ 4100.110480] Lustre: 50277:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 6 previous similar messages [ 4100.185119] Lustre: lustre-MDT0000-mdc-ffff9a3e09bc4000: Connection restored to 192.168.202.156@tcp (at 192.168.202.156@tcp) [ 4100.190959] Lustre: Skipped 7 previous similar messages [ 4108.408507] Lustre: DEBUG MARKER: == recovery-small test 53b: touch: drop rep ============== 05:23:33 (1769077413) [ 4136.154533] Lustre: DEBUG MARKER: == recovery-small test 53c: touch: drop rep ============== 05:24:00 (1769077440) [ 4162.451686] Lustre: DEBUG MARKER: == recovery-small test 54: back in time ================== 05:24:27 (1769077467) [ 4163.210734] Lustre: Mounted lustre-client [ 4195.296407] Lustre: 2376:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1769077485/real 1769077485] req@ffff9a3e0784d180 x1855007970081152/t0(0) o400->lustre-MDT0000-mdc-ffff9a3e09bc4000@192.168.202.156@tcp:12/10 lens 224/224 e 0 to 1 dl 1769077501 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4195.340980] Lustre: 2376:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 4195.388820] LustreError: MGC192.168.202.156@tcp: Connection to MGS (at 192.168.202.156@tcp) was lost; in progress operations using this service will fail [ 4195.415935] LustreError: Skipped 3 previous similar messages [ 4205.045426] Lustre: Evicted from MGS (at 192.168.202.156@tcp) after server handle changed from 0x66da280ed304067a to 0x66da280ed31969b5 [ 4205.063081] Lustre: Skipped 3 previous similar messages [ 4208.933024] Lustre: DEBUG MARKER: oleg256-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4210.798683] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4212.898373] LustreError: 53038:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff9a3e0b77b800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 4212.917985] LustreError: 53038:0:(lov_obd.c:783:lov_cleanup()) Skipped 1 previous similar message [ 4212.934578] LustreError: 53038:0:(obd_class.h:479:obd_check_dev()) Device 10 not setup [ 4212.940438] LustreError: 53038:0:(obd_class.h:479:obd_check_dev()) Skipped 5 previous similar messages [ 4212.996592] Lustre: Unmounted lustre-client [ 4218.486222] Lustre: DEBUG MARKER: == recovery-small test 55: ost_brw_read/write drops timed-out read/write request ========================================================== 05:25:23 (1769077523) [ 4354.528278] Lustre: 2377:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1769077645/real 1769077645] req@ffff9a3e07ef0000 x1855007970112640/t0(0) o4->lustre-OST0000-osc-ffff9a3e09bc4000@192.168.202.156@tcp:6/4 lens 488/448 e 0 to 1 dl 1769077661 ref 2 fl Rpc:XQr/602/ffffffff rc 0/-1 job:'dd.0' uid:0 gid:0 projid:0 [ 4354.571269] Lustre: 2377:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 75 previous similar messages [ 4387.296338] Lustre: lustre-OST0000-osc-ffff9a3e09bc4000: Connection to lustre-OST0000 (at 192.168.202.156@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 4387.303770] Lustre: Skipped 14 previous similar messages [ 4511.848452] Lustre: DEBUG MARKER: == recovery-small test 56: do not fail on getattr resend ========================================================== 05:30:17 (1769077817) [ 4563.651518] Lustre: DEBUG MARKER: == recovery-small test 57: read procfs entries causes kernel crash ========================================================== 05:31:07 (1769077867) [ 4566.486362] LustreError: 55187:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff9a3e09bc4000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 4566.491031] LustreError: 55187:0:(lov_obd.c:783:lov_cleanup()) Skipped 1 previous similar message [ 4566.500429] LustreError: 55187:0:(obd_class.h:479:obd_check_dev()) Device 5 not setup [ 4566.503510] LustreError: 55187:0:(obd_class.h:479:obd_check_dev()) Skipped 5 previous similar messages [ 4566.534852] Lustre: Unmounted lustre-client [ 4595.714673] Lustre: Mounted lustre-client [ 4602.655708] Lustre: DEBUG MARKER: == recovery-small test 58: Eviction in the middle of open RPC reply processing ========================================================== 05:31:47 (1769077907) [ 4602.924357] LustreError: 56174:0:(mdc_locks.c:1335:mdc_finish_intent_lock()) cfs_fail_timeout id 801 sleeping for 20000ms [ 4603.973219] LustreError: 56174:0:(mdc_locks.c:1335:mdc_finish_intent_lock()) cfs_fail_timeout interrupted [ 4604.145725] Lustre: *** cfs_fail_loc=305, val=0*** [ 4629.214599] Lustre: DEBUG MARKER: == recovery-small test 59: Read cancel race on client eviction ========================================================== 05:32:14 (1769077934) [ 4629.697678] Lustre: Mounted lustre-client [ 4633.002622] Lustre: setting import lustre-MDT0000_UUID INACTIVE by administrator request [ 4643.326566] LustreError: 56852:0:(obd_class.h:479:obd_check_dev()) Device 10 not setup [ 4643.345964] LustreError: 56852:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 4643.408576] Lustre: Unmounted lustre-client [ 4651.602587] Lustre: DEBUG MARKER: == recovery-small test 60: Add Changelog entries during MDS failover ========================================================== 05:32:36 (1769077956) [ 4724.514636] LustreError: lustre-MDT0000-mdc-ffff9a3e08114800: operation mds_reint to node 192.168.202.156@tcp failed: rc = -19 [ 4724.528758] LustreError: Skipped 2 previous similar messages [ 4742.628706] Lustre: 2378:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1769078033/real 1769078033] req@ffff9a3e098ead80 x1855007972791168/t0(0) o400->MGC192.168.202.156@tcp@192.168.202.156@tcp:26/25 lens 224/224 e 0 to 1 dl 1769078049 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4742.684382] Lustre: 2378:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 74 previous similar messages [ 4742.696163] LustreError: MGC192.168.202.156@tcp: Connection to MGS (at 192.168.202.156@tcp) was lost; in progress operations using this service will fail [ 4752.877428] Lustre: Evicted from MGS (at 192.168.202.156@tcp) after server handle changed from 0x66da280ed3198473 to 0x66da280ed31c3d8d [ 4752.892714] Lustre: MGC192.168.202.156@tcp: Connection restored to 192.168.202.156@tcp (at 192.168.202.156@tcp) [ 4752.902710] Lustre: Skipped 23 previous similar messages [ 4890.270886] Lustre: DEBUG MARKER: == recovery-small test 61: Verify to not reuse orphan objects - bug 17025 ========================================================== 05:36:35 (1769078195) [ 4894.950367] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4905.467661] LustreError: MGC192.168.202.156@tcp: Connection to MGS (at 192.168.202.156@tcp) was lost; in progress operations using this service will fail [ 4905.492368] Lustre: Evicted from MGS (at 192.168.202.156@tcp) after server handle changed from 0x66da280ed31c3d8d to 0x66da280ed320fb18 [ 4906.876885] LustreError: lustre-MDT0000-mdc-ffff9a3e08114800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 4924.189735] Lustre: DEBUG MARKER: == recovery-small test 65: lock enqueue for destroyed export ========================================================== 05:37:09 (1769078229) [ 4924.666252] Lustre: Mounted lustre-client [ 4932.042680] LustreError: lustre-OST0000-osc-ffff9a3e08114800: operation ldlm_enqueue to node 192.168.202.156@tcp failed: rc = -107 [ 4932.061697] LustreError: lustre-OST0000-osc-ffff9a3e08114800: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 4944.464151] LustreError: 59908:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff9a3e04c34000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 4944.481644] LustreError: 59908:0:(lov_obd.c:783:lov_cleanup()) Skipped 1 previous similar message [ 4944.504817] LustreError: 59908:0:(obd_class.h:479:obd_check_dev()) Device 10 not setup [ 4944.512964] LustreError: 59908:0:(obd_class.h:479:obd_check_dev()) Skipped 5 previous similar messages [ 4944.583746] Lustre: Unmounted lustre-client [ 4952.010650] Lustre: DEBUG MARKER: == recovery-small test 66: lock enqueue re-send vs client eviction ========================================================== 05:37:36 (1769078256) [ 4958.726646] LustreError: lustre-MDT0000-mdc-ffff9a3e08114800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 4958.753249] LustreError: 60551:0:(file.c:6123:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -5 [ 4967.516609] Lustre: DEBUG MARKER: == recovery-small test 67: connect vs import invalidate race ========================================================== 05:37:52 (1769078272) [ 4967.871189] LustreError: 61255:0:(recover.c:330:ptlrpc_recover_import()) cfs_race id 531 sleeping [ 4972.965474] LustreError: lustre-MDT0000-mdc-ffff9a3e08114800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 4972.989580] LustreError: 61272:0:(import.c:291:ptlrpc_invalidate_import()) cfs_fail_race id 531 waking [ 4973.007344] LustreError: 61255:0:(recover.c:330:ptlrpc_recover_import()) cfs_fail_race id 531 awake: rc=1 [ 4973.023862] LustreError: 61255:0:(import.c:716:ptlrpc_connect_import_locked()) already connecting [ 4973.096731] LustreError: 61277:0:(file.c:6123:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 4974.203950] LustreError: 61283:0:(file.c:6123:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 4974.222240] LustreError: 61283:0:(file.c:6123:ll_inode_revalidate_fini()) Skipped 5 previous similar messages [ 4976.547069] LustreError: 61306:0:(file.c:6123:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 4976.557897] LustreError: 61306:0:(file.c:6123:ll_inode_revalidate_fini()) Skipped 13 previous similar messages [ 4981.485501] LustreError: 61351:0:(file.c:6123:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 4981.497424] LustreError: 61351:0:(file.c:6123:ll_inode_revalidate_fini()) Skipped 27 previous similar messages [ 4991.786463] Lustre: DEBUG MARKER: == recovery-small test 100: IR: Make sure normal recovery still works w/o IR ========================================================== 05:38:16 (1769078296) [ 4997.617270] Lustre: lustre-OST0000-osc-ffff9a3e08114800: Connection to lustre-OST0000 (at 192.168.202.156@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 4997.647159] Lustre: Skipped 18 previous similar messages [ 5035.850745] Lustre: DEBUG MARKER: oleg256-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 5037.802683] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 5052.067485] Lustre: DEBUG MARKER: == recovery-small test 101a: IR: Make sure IR works w/o normal recovery ========================================================== 05:39:17 (1769078357) [ 5091.960592] Lustre: DEBUG MARKER: oleg256-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 5094.657027] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 5107.830448] Lustre: DEBUG MARKER: == recovery-small test 101b: IR: Make sure IR works w/o normal recovery and proceed EAGAIN ========================================================== 05:40:12 (1769078412) [ 5172.965710] Lustre: DEBUG MARKER: oleg256-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 5174.576422] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 5183.659872] Lustre: DEBUG MARKER: == recovery-small test 102: IR: New client gets updated nidtbl after MGS restart ========================================================== 05:41:28 (1769078488) [ 5222.713930] Lustre: DEBUG MARKER: oleg256-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 5224.223984] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 5230.708364] LustreError: 66930:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff9a3e08114800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 5230.712704] LustreError: 66930:0:(lov_obd.c:783:lov_cleanup()) Skipped 1 previous similar message [ 5230.725161] LustreError: 66930:0:(obd_class.h:479:obd_check_dev()) Device 5 not setup [ 5230.730154] LustreError: 66930:0:(obd_class.h:479:obd_check_dev()) Skipped 5 previous similar messages [ 5230.761882] Lustre: Unmounted lustre-client [ 5296.171557] Lustre: DEBUG MARKER: oleg256-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 5299.546262] Lustre: Mounted lustre-client [ 5309.276804] Lustre: DEBUG MARKER: == recovery-small test 103: IR: MDS can start w/o MGS and get updated nidtbl later ========================================================== 05:43:33 (1769078613) [ 5311.711637] Lustre: DEBUG MARKER: SKIP: recovery-small test_103 needs separate mgs and mds [ 5314.254357] Lustre: DEBUG MARKER: == recovery-small test 104: IR: ost can disable IR voluntarily ========================================================== 05:43:38 (1769078618) [ 5347.421391] Lustre: DEBUG MARKER: == recovery-small test 105: IR: NON IR clients support === 05:44:12 (1769078652) [ 5348.849793] Lustre: DEBUG MARKER: SKIP: recovery-small test_105 Needs multiple clients [ 5350.514727] Lustre: DEBUG MARKER: == recovery-small test 106: lightweight connection support ========================================================== 05:44:15 (1769078655) [ 5352.187298] Lustre: *** cfs_fail_loc=805, val=0*** [ 5352.241297] Lustre: Mounted lustre-client [ 5358.533230] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5378.848181] Lustre: 2378:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1769078669/real 1769078669] req@ffff9a3e09932680 x1855007974823808/t0(0) o400->MGC192.168.202.156@tcp@192.168.202.156@tcp:26/25 lens 224/224 e 0 to 1 dl 1769078685 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5378.868554] Lustre: 2378:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 5378.872321] LustreError: MGC192.168.202.156@tcp: Connection to MGS (at 192.168.202.156@tcp) was lost; in progress operations using this service will fail [ 5389.163315] Lustre: Evicted from MGS (at 192.168.202.156@tcp) after server handle changed from 0x66da280ed321083f to 0x66da280ed3210a5a [ 5389.179299] Lustre: MGC192.168.202.156@tcp: Connection restored to 192.168.202.156@tcp (at 192.168.202.156@tcp) [ 5389.191367] Lustre: Skipped 12 previous similar messages [ 5403.503140] LustreError: 2374:0:(ldlm_resource.c:981:ldlm_resource_complain()) lustre-MDT0000-mdc-ffff9a3e0c958000: namespace resource [0x200000007:0x1:0x0].0x0 (ffff9a3e15e67c00) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 5406.941216] LustreError: 70286:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff9a3e0c958000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 5406.957361] LustreError: 70286:0:(lov_obd.c:783:lov_cleanup()) Skipped 1 previous similar message [ 5406.969645] LustreError: 70286:0:(obd_class.h:479:obd_check_dev()) Device 10 not setup [ 5406.972570] LustreError: 70286:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 5407.021416] Lustre: Unmounted lustre-client [ 5415.242448] Lustre: DEBUG MARKER: == recovery-small test 107: drop reint reply, then restart MDT ========================================================== 05:45:20 (1769078720) [ 5457.948981] LustreError: 2374:0:(client.c:3418:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9a3e099aed80 x1855007974836224/t94489280517(94489280517) o101->lustre-MDT0000-mdc-ffff9a3e081a5800@192.168.202.156@tcp:12/10 lens 648/608 e 0 to 0 dl 1769078780 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'multiop.0' uid:0 gid:0 projid:0 [ 5462.468438] Lustre: DEBUG MARKER: oleg256-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 5464.568564] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5472.864291] Lustre: DEBUG MARKER: == recovery-small test 108: client eviction don't crash == 05:46:18 (1769078778) [ 5474.216708] LustreError: lustre-OST0000-osc-ffff9a3e081a5800: operation ost_write to node 192.168.202.156@tcp failed: rc = -107 [ 5474.224354] LustreError: Skipped 2 previous similar messages [ 5474.238904] LustreError: lustre-OST0000-osc-ffff9a3e081a5800: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 5474.255538] Lustre: 2375:0:(llite_lib.c:4226:ll_dirty_page_discard_warn()) lustre: dirty page discard: 192.168.202.156@tcp:/lustre/fid: [0x20000a042:0x6:0x0]// may get corrupted (rc -5) [ 5474.284049] LustreError: 72282:0:(ldlm_resource.c:981:ldlm_resource_complain()) lustre-OST0000-osc-ffff9a3e081a5800: namespace resource [0x240000400:0x3ec2:0x0].0x0 (ffff9a3e0cb32200) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 5474.293524] LustreError: 72282:0:(ldlm_resource.c:981:ldlm_resource_complain()) Skipped 1 previous similar message [ 5481.770428] Lustre: DEBUG MARKER: == recovery-small test 110a: create remote directory: drop client req ========================================================== 05:46:27 (1769078787) [ 5483.148386] Lustre: DEBUG MARKER: SKIP: recovery-small test_110a needs >= 2 MDTs [ 5484.612034] Lustre: DEBUG MARKER: == recovery-small test 110b: create remote directory: drop Master rep ========================================================== 05:46:29 (1769078789) [ 5485.996671] Lustre: DEBUG MARKER: SKIP: recovery-small test_110b needs >= 2 MDTs [ 5487.657439] Lustre: DEBUG MARKER: == recovery-small test 110c: create remote directory: drop update rep on slave MDT ========================================================== 05:46:32 (1769078792) [ 5489.143982] Lustre: DEBUG MARKER: SKIP: recovery-small test_110c needs >= 2 MDTs [ 5490.472782] Lustre: DEBUG MARKER: == recovery-small test 110d: remove remote directory: drop client req ========================================================== 05:46:35 (1769078795) [ 5492.005635] Lustre: DEBUG MARKER: SKIP: recovery-small test_110d needs >= 2 MDTs [ 5493.476629] Lustre: DEBUG MARKER: == recovery-small test 110e: remove remote directory: drop master rep ========================================================== 05:46:38 (1769078798) [ 5495.123611] Lustre: DEBUG MARKER: SKIP: recovery-small test_110e needs >= 2 MDTs [ 5496.757154] Lustre: DEBUG MARKER: == recovery-small test 110f: remove remote directory: drop slave rep ========================================================== 05:46:42 (1769078802) [ 5498.502904] Lustre: DEBUG MARKER: SKIP: recovery-small test_110f needs >= 2 MDTs [ 5500.542298] Lustre: DEBUG MARKER: == recovery-small test 110g: drop reply during migration ========================================================== 05:46:45 (1769078805) [ 5502.107586] Lustre: DEBUG MARKER: SKIP: recovery-small test_110g needs >= 2 MDTs [ 5504.039770] Lustre: DEBUG MARKER: == recovery-small test 110h: drop update reply during cross-MDT file rename ========================================================== 05:46:49 (1769078809) [ 5506.005258] Lustre: DEBUG MARKER: SKIP: recovery-small test_110h needs >= 2 MDTs [ 5507.622775] Lustre: DEBUG MARKER: == recovery-small test 110i: drop update reply during cross-MDT dir rename ========================================================== 05:46:52 (1769078812) [ 5509.077556] Lustre: DEBUG MARKER: SKIP: recovery-small test_110i needs >= 2 MDTs [ 5510.851356] Lustre: DEBUG MARKER: == recovery-small test 110j: drop update reply during cross-MDT ln ========================================================== 05:46:56 (1769078816) [ 5512.438337] Lustre: DEBUG MARKER: SKIP: recovery-small test_110j needs >= 2 MDTs [ 5514.007380] Lustre: DEBUG MARKER: == recovery-small test 110k: FID_QUERY failed during recovery ========================================================== 05:46:59 (1769078819) [ 5515.581744] Lustre: DEBUG MARKER: SKIP: recovery-small test_110k needs >= 2 MDTS [ 5517.176823] Lustre: DEBUG MARKER: == recovery-small test 110m: update resent vs original RPC race ========================================================== 05:47:02 (1769078822) [ 5519.672454] Lustre: DEBUG MARKER: SKIP: recovery-small test_110m needs at least 2 MDTs [ 5521.261722] Lustre: DEBUG MARKER: == recovery-small test 111: mdd setup fail should not cause umount oops ========================================================== 05:47:06 (1769078826) [ 5554.286882] Lustre: DEBUG MARKER: == recovery-small test 112a: bulk resend while orignal request is in progress ========================================================== 05:47:39 (1769078859) [ 5584.522291] Lustre: DEBUG MARKER: == recovery-small test 115a: read: late REQ MDunlink and no bulk ========================================================== 05:48:09 (1769078889) [ 5584.832438] Lustre: *** cfs_fail_loc=51b, val=3*** [ 5596.124929] Lustre: DEBUG MARKER: == recovery-small test 115b: write: late REQ MDunlink and no bulk ========================================================== 05:48:21 (1769078901) [ 5596.634647] Lustre: *** cfs_fail_loc=51b, val=4*** [ 5608.485526] Lustre: DEBUG MARKER: == recovery-small test 115c: read: late Reply MDunlink and no bulk ========================================================== 05:48:33 (1769078913) [ 5608.961064] Lustre: *** cfs_fail_loc=50f, val=3*** [ 5620.652490] Lustre: DEBUG MARKER: == recovery-small test 115d: write: late Reply MDunlink and no bulk ========================================================== 05:48:45 (1769078925) [ 5620.940906] Lustre: *** cfs_fail_loc=50f, val=4*** [ 5631.586271] Lustre: DEBUG MARKER: == recovery-small test 115e: read: late Bulk MDunlink and no reply ========================================================== 05:48:56 (1769078936) [ 5632.093827] Lustre: *** cfs_fail_loc=510, val=3*** [ 5643.222775] Lustre: DEBUG MARKER: == recovery-small test 115f: read: late REQ MDunlink and no reply ========================================================== 05:49:07 (1769078947) [ 5643.646863] Lustre: *** cfs_fail_loc=51b, val=3*** [ 5655.820372] Lustre: DEBUG MARKER: == recovery-small test 115g: read: late REQ MDunlink and Reply MDunlink ========================================================== 05:49:20 (1769078960) [ 5656.283839] Lustre: *** cfs_fail_loc=51c, val=3*** [ 5714.912478] Lustre: lustre-OST0001-osc-ffff9a3e081a5800: Connection to lustre-OST0001 (at 192.168.202.156@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 5714.931331] Lustre: Skipped 8 previous similar messages [ 5722.479118] Lustre: DEBUG MARKER: == recovery-small test 120: flock race: completion vs. evict ========================================================== 05:50:27 (1769079027) [ 5723.314368] LustreError: 82478:0:(ldlm_flock.c:802:ldlm_flock_completion_ast()) cfs_fail_timeout id 320 sleeping for 4000ms [ 5726.241785] LustreError: lustre-MDT0000-mdc-ffff9a3e081a5800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5726.271659] LustreError: 82493:0:(ldlm_resource.c:981:ldlm_resource_complain()) lustre-MDT0000-mdc-ffff9a3e081a5800: namespace resource [0x200000007:0x1:0x0].0x0 (ffff9a3e04007a00) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 5727.392297] LustreError: 82478:0:(ldlm_flock.c:802:ldlm_flock_completion_ast()) cfs_fail_timeout id 320 awake [ 5729.541086] LustreError: 82508:0:(ldlm_flock.c:802:ldlm_flock_completion_ast()) cfs_fail_timeout id 320 sleeping for 4000ms [ 5732.796963] LustreError: lustre-MDT0000-mdc-ffff9a3e081a5800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5732.830268] LustreError: 82523:0:(ldlm_resource.c:981:ldlm_resource_complain()) lustre-MDT0000-mdc-ffff9a3e081a5800: namespace resource [0x20000a042:0x11:0x0].0xc (ffff9a3e0cb32c00) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 5732.878871] LustreError: 82523:0:(ldlm_resource.c:981:ldlm_resource_complain()) Skipped 2 previous similar messages [ 5733.624376] LustreError: 82508:0:(ldlm_flock.c:802:ldlm_flock_completion_ast()) cfs_fail_timeout id 320 awake [ 5740.703102] LustreError: lustre-MDT0000-mdc-ffff9a3e081a5800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5741.079071] LustreError: 82564:0:(ldlm_flock.c:807:ldlm_flock_completion_ast()) cfs_fail_timeout id 321 sleeping for 4000ms [ 5744.227339] LustreError: lustre-MDT0000-mdc-ffff9a3e081a5800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5744.323124] LustreError: 82584:0:(file.c:6123:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 5744.342057] LustreError: 82584:0:(file.c:6123:ll_inode_revalidate_fini()) Skipped 13 previous similar messages [ 5745.168202] LustreError: 82564:0:(ldlm_flock.c:807:ldlm_flock_completion_ast()) cfs_fail_timeout id 321 awake [ 5745.175953] LustreError: 82564:0:(file.c:249:ll_close_inode_openhandle()) lustre-clilmv-ffff9a3e081a5800: inode [0x20000a042:0x11:0x0] mdc close failed: rc = -108 [ 5745.480855] LustreError: 82590:0:(file.c:6123:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 5745.498833] LustreError: 82590:0:(file.c:6123:ll_inode_revalidate_fini()) Skipped 5 previous similar messages [ 5747.940102] LustreError: 82613:0:(file.c:6123:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 5747.964942] LustreError: 82613:0:(file.c:6123:ll_inode_revalidate_fini()) Skipped 13 previous similar messages [ 5751.734418] LustreError: 82639:0:(ldlm_flock.c:807:ldlm_flock_completion_ast()) cfs_fail_timeout id 321 sleeping for 4000ms [ 5754.809342] LustreError: lustre-MDT0000-mdc-ffff9a3e081a5800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5754.848200] LustreError: 82654:0:(ldlm_resource.c:981:ldlm_resource_complain()) lustre-MDT0000-mdc-ffff9a3e081a5800: namespace resource [0x20000a042:0x11:0x0].0xc (ffff9a3e0cb32b00) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 5754.891817] LustreError: 82654:0:(ldlm_resource.c:981:ldlm_resource_complain()) Skipped 1 previous similar message [ 5755.800305] LustreError: 82639:0:(ldlm_flock.c:807:ldlm_flock_completion_ast()) cfs_fail_timeout id 321 awake [ 5762.809231] LustreError: lustre-MDT0000-mdc-ffff9a3e081a5800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5763.209475] LustreError: 82696:0:(ldlm_flock.c:856:ldlm_flock_completion_ast()) cfs_fail_timeout id 322 sleeping for 4000ms [ 5766.292606] LustreError: lustre-MDT0000-mdc-ffff9a3e081a5800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5766.314699] LustreError: 82710:0:(ldlm_resource.c:981:ldlm_resource_complain()) lustre-MDT0000-mdc-ffff9a3e081a5800: namespace resource [0x20000a042:0x11:0x0].0xc (ffff9a3e0cb32b00) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 5766.362115] LustreError: 82710:0:(ldlm_resource.c:981:ldlm_resource_complain()) Skipped 1 previous similar message [ 5767.288138] LustreError: 82696:0:(ldlm_flock.c:856:ldlm_flock_completion_ast()) cfs_fail_timeout id 322 awake [ 5770.507817] LustreError: lustre-MDT0000-mdc-ffff9a3e081a5800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5770.617307] LustreError: 82743:0:(file.c:6123:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 5770.629250] LustreError: 82743:0:(file.c:6123:ll_inode_revalidate_fini()) Skipped 6 previous similar messages [ 5771.416813] LustreError: 82723:0:(file.c:249:ll_close_inode_openhandle()) lustre-clilmv-ffff9a3e081a5800: inode [0x20000a042:0x11:0x0] mdc close failed: rc = -108 [ 5779.793228] LustreError: 82795:0:(ldlm_flock.c:802:ldlm_flock_completion_ast()) cfs_fail_timeout id 320 sleeping for 4000ms [ 5779.800616] LustreError: 82795:0:(ldlm_flock.c:802:ldlm_flock_completion_ast()) Skipped 1 previous similar message [ 5783.368664] LustreError: lustre-MDT0000-mdc-ffff9a3e081a5800: operation ldlm_enqueue to node 192.168.202.156@tcp failed: rc = -107 [ 5783.376952] LustreError: Skipped 8 previous similar messages [ 5783.390512] LustreError: lustre-MDT0000-mdc-ffff9a3e081a5800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5783.483864] LustreError: 82817:0:(file.c:6123:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 5783.498550] LustreError: 82817:0:(file.c:6123:ll_inode_revalidate_fini()) Skipped 26 previous similar messages [ 5783.875571] LustreError: 82795:0:(ldlm_flock.c:802:ldlm_flock_completion_ast()) cfs_fail_timeout id 320 awake [ 5783.885463] LustreError: 82795:0:(ldlm_flock.c:802:ldlm_flock_completion_ast()) Skipped 1 previous similar message [ 5783.903975] LustreError: 82795:0:(file.c:249:ll_close_inode_openhandle()) lustre-clilmv-ffff9a3e081a5800: inode [0x20000a042:0x11:0x0] mdc close failed: rc = -108 [ 5796.828359] Lustre: DEBUG MARKER: == recovery-small test 113: ldlm enqueue dropped reply should not cause deadlocks ========================================================== 05:51:41 (1769079101) [ 5817.466406] LustreError: 67767:0:(ldlm_lockd.c:2882:ldlm_bl_thread_blwi()) cfs_fail_timeout id 31f sleeping for 4000ms [ 5817.475993] LustreError: 67767:0:(ldlm_lockd.c:2882:ldlm_bl_thread_blwi()) Skipped 1 previous similar message [ 5821.536210] LustreError: 67767:0:(ldlm_lockd.c:2882:ldlm_bl_thread_blwi()) cfs_fail_timeout id 31f awake [ 5821.548874] LustreError: 67767:0:(ldlm_lockd.c:2882:ldlm_bl_thread_blwi()) Skipped 1 previous similar message [ 5828.397295] Lustre: DEBUG MARKER: == recovery-small test 130a: enqueue resend on not existing file ========================================================== 05:52:13 (1769079133) [ 5880.807818] Lustre: DEBUG MARKER: == recovery-small test 130b: enqueue resend on a stale inode ========================================================== 05:53:05 (1769079185) [ 5946.434680] Lustre: DEBUG MARKER: == recovery-small test 130c: layout intent resend on a stale inode ========================================================== 05:54:11 (1769079251) [ 5979.557659] Lustre: DEBUG MARKER: == recovery-small test 132: long punch =================== 05:54:44 (1769079284) [ 5979.982594] Lustre: Mounted lustre-client [ 6103.577125] LustreError: 86514:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff9a3e02a35800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 6103.584733] LustreError: 86514:0:(lov_obd.c:783:lov_cleanup()) Skipped 1 previous similar message [ 6103.590496] LustreError: 86514:0:(obd_class.h:479:obd_check_dev()) Device 10 not setup [ 6103.593989] LustreError: 86514:0:(obd_class.h:479:obd_check_dev()) Skipped 5 previous similar messages [ 6103.628614] Lustre: Unmounted lustre-client [ 6110.349635] Lustre: DEBUG MARKER: == recovery-small test 131: IO vs evict results to IO under staled lock ========================================================== 05:56:55 (1769079415) [ 6111.042288] LustreError: 87129:0:(osc_request.c:2944:osc_build_rpc()) cfs_fail_timeout id 414 sleeping for 4000ms [ 6114.348185] LustreError: lustre-OST0000-osc-ffff9a3e081a5800: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 6114.377474] LustreError: 87211:0:(ldlm_resource.c:981:ldlm_resource_complain()) lustre-OST0000-osc-ffff9a3e081a5800: namespace resource [0x240000400:0x3eed:0x0].0x0 (ffff9a3e0cb32b00) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 6114.397328] LustreError: 87211:0:(ldlm_resource.c:981:ldlm_resource_complain()) Skipped 1 previous similar message [ 6115.144767] LustreError: 87129:0:(osc_request.c:2944:osc_build_rpc()) cfs_fail_timeout id 414 awake [ 6115.151500] Lustre: 2376:0:(llite_lib.c:4226:ll_dirty_page_discard_warn()) lustre: dirty page discard: 192.168.202.156@tcp:/lustre/fid: [0x20000bf89:0x9:0x0]// may get corrupted (rc -108) [ 6121.715872] Lustre: DEBUG MARKER: == recovery-small test 133: don't fail on flock resend === 05:57:07 (1769079427) [ 6179.811126] Lustre: 87796:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1769079430/real 1769079430] req@ffff9a3e088f5880 x1855007975010176/t0(0) o101->lustre-MDT0000-mdc-ffff9a3e081a5800@192.168.202.156@tcp:12/10 lens 328/344 e 0 to 1 dl 1769079486 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'multiop.0' uid:0 gid:0 projid:0 [ 6179.845314] Lustre: 87796:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 9 previous similar messages [ 6179.860699] Lustre: lustre-MDT0000-mdc-ffff9a3e081a5800: Connection restored to 192.168.202.156@tcp (at 192.168.202.156@tcp) [ 6179.868054] Lustre: Skipped 18 previous similar messages [ 6186.626115] Lustre: DEBUG MARKER: == recovery-small test 134: race between failover and search for reply data free slot ========================================================== 05:58:11 (1769079491) [ 6188.132817] Lustre: DEBUG MARKER: SKIP: recovery-small test_134 Need 2+ clients, have 1 [ 6189.757403] Lustre: DEBUG MARKER: == recovery-small test 135: DOM: open/create resend to return size ========================================================== 05:58:14 (1769079494) [ 6253.706089] Lustre: DEBUG MARKER: SKIP: recovery-small test_136 skipping excluded test 136 [ 6255.191679] Lustre: DEBUG MARKER: == recovery-small test 137: late resend must be skipped if already applied ========================================================== 05:59:20 (1769079560) [ 6314.763697] Lustre: DEBUG MARKER: == recovery-small test 138: Umount MDT during recovery === 06:00:19 (1769079619) [ 6316.879972] Lustre: DEBUG MARKER: SKIP: recovery-small test_138 needs >= 2 MDTs [ 6318.747313] Lustre: DEBUG MARKER: == recovery-small test 139: corrupted catid won't cause crash ========================================================== 06:00:23 (1769079623) [ 6319.992161] Lustre: DEBUG MARKER: SKIP: recovery-small test_139 needs >= 2 MDTs [ 6322.012811] Lustre: DEBUG MARKER: == recovery-small test 140a: local mount is flagged properly ========================================================== 06:00:27 (1769079627) [ 6352.938735] Lustre: DEBUG MARKER: == recovery-small test 140b: local mount is excluded from recovery ========================================================== 06:00:57 (1769079657) [ 6363.748167] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 6389.728322] LustreError: MGC192.168.202.156@tcp: Connection to MGS (at 192.168.202.156@tcp) was lost; in progress operations using this service will fail [ 6389.747480] LustreError: Skipped 2 previous similar messages [ 6389.788380] Lustre: Evicted from MGS (at 192.168.202.156@tcp) after server handle changed from 0x66da280ed321164d to 0x66da280ed3212e64 [ 6389.805168] Lustre: Skipped 2 previous similar messages [ 6395.936530] Lustre: lustre-MDT0000-mdc-ffff9a3e081a5800: Connection to lustre-MDT0000 (at 192.168.202.156@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 6395.948145] Lustre: Skipped 16 previous similar messages [ 6413.073670] Lustre: DEBUG MARKER: oleg256-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 6415.292785] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6426.133621] Lustre: DEBUG MARKER: == recovery-small test 141: do not lose locks on MGS restart ========================================================== 06:02:11 (1769079731) [ 6428.779459] Lustre: DEBUG MARKER: SKIP: recovery-small test_141 cannot run in local mode or from build tree [ 6430.630723] Lustre: DEBUG MARKER: == recovery-small test 142: orphan name stub can be cleaned up in startup ========================================================== 06:02:15 (1769079735) [ 6441.964404] LustreError: MGC192.168.202.156@tcp: Connection to MGS (at 192.168.202.156@tcp) was lost; in progress operations using this service will fail [ 6441.985243] Lustre: Evicted from MGS (at 192.168.202.156@tcp) after server handle changed from 0x66da280ed3212e64 to 0x66da280ed32131a5 [ 6455.168517] Lustre: DEBUG MARKER: == recovery-small test 143: orphan cleanup thread shouldn't be blocked even delete failed ========================================================== 06:02:40 (1769079760) [ 6490.274558] Lustre: DEBUG MARKER: == recovery-small test 144a: MDT failover should stop precreation threads ========================================================== 06:03:15 (1769079795) [ 6496.430987] LustreError: lustre-OST0000-osc-ffff9a3e081a5800: operation ost_setattr to node 192.168.202.156@tcp failed: rc = -107 [ 6496.449941] LustreError: Skipped 1 previous similar message [ 6539.770800] Lustre: DEBUG MARKER: oleg256-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 6543.643726] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 6627.298094] LustreError: MGC192.168.202.156@tcp: Connection to MGS (at 192.168.202.156@tcp) was lost; in progress operations using this service will fail [ 6627.313739] LustreError: Skipped 1 previous similar message [ 6627.344549] Lustre: Evicted from MGS (at 192.168.202.156@tcp) after server handle changed from 0x66da280ed3213851 to 0x66da280ed3214436 [ 6627.356701] Lustre: Skipped 1 previous similar message [ 6636.084916] Lustre: DEBUG MARKER: oleg256-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 6637.140185] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6667.190745] Lustre: DEBUG MARKER: oleg256-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 6668.452240] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6754.658390] Lustre: DEBUG MARKER: == recovery-small test 144b: orphan cleanup shouldn't be blocked for no objects+failover situation ========================================================== 06:07:40 (1769080060) [ 6797.663320] Lustre: DEBUG MARKER: oleg256-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 6799.938102] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 6999.540419] Lustre: DEBUG MARKER: == recovery-small test 144c: reconnection during orphan cleanup shouldn't lose LAST_ID synchronization ========================================================== 06:11:45 (1769080305) [ 7118.821241] Lustre: lustre-MDT0000-mdc-ffff9a3e081a5800: Connection to lustre-MDT0000 (at 192.168.202.156@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 7118.834376] Lustre: Skipped 6 previous similar messages [ 7118.841501] LustreError: MGC192.168.202.156@tcp: Connection to MGS (at 192.168.202.156@tcp) was lost; in progress operations using this service will fail [ 7118.848260] LustreError: Skipped 1 previous similar message [ 7118.860843] Lustre: Evicted from MGS (at 192.168.202.156@tcp) after server handle changed from 0x66da280ed321475b to 0x66da280ed3309777 [ 7118.868645] Lustre: Skipped 1 previous similar message [ 7118.886056] Lustre: MGC192.168.202.156@tcp: Connection restored to 192.168.202.156@tcp (at 192.168.202.156@tcp) [ 7118.894915] Lustre: Skipped 12 previous similar messages [ 7141.567522] Lustre: DEBUG MARKER: == recovery-small test 145: connect mdtlovs and process update logs after recovery expire ========================================================== 06:14:07 (1769080447) [ 7142.436808] Lustre: DEBUG MARKER: SKIP: recovery-small test_145 needs >= 3 MDTs [ 7143.325236] Lustre: DEBUG MARKER: == recovery-small test 146: test eviction is counted properly ========================================================== 06:14:09 (1769080449) [ 7144.587284] LustreError: lustre-MDT0000-mdc-ffff9a3e081a5800: operation ldlm_enqueue to node 192.168.202.156@tcp failed: rc = -107 [ 7144.592904] LustreError: Skipped 127 previous similar messages [ 7144.608951] LustreError: lustre-MDT0000-mdc-ffff9a3e081a5800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 7149.723698] Lustre: DEBUG MARKER: == recovery-small test 147: Check client reconnect ======= 06:14:15 (1769080455) [ 7315.942162] LustreError: lustre-OST0000-osc-ffff9a3e081a5800: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 7316.772979] Lustre: DEBUG MARKER: == recovery-small test 148: data corruption through resend ========================================================== 06:17:02 (1769080622) [ 7339.424174] Lustre: 2378:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1769080625/real 1769080625] req@ffff9a3e04e4c700 x1855007992327168/t0(0) o4->lustre-OST0000-osc-ffff9a3e081a5800@192.168.202.156@tcp:6/4 lens 4584/448 e 0 to 1 dl 1769080645 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'dd.0' uid:0 gid:0 projid:0 [ 7339.443147] Lustre: 2378:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 23 previous similar messages [ 7352.723336] Lustre: DEBUG MARKER: == recovery-small test 149: skip orphan removal at umount ========================================================== 06:17:38 (1769080658) [ 7353.399825] Lustre: DEBUG MARKER: SKIP: recovery-small test_149 needs >= 2 MDTs [ 7354.204627] Lustre: DEBUG MARKER: == recovery-small test 150: statfs when MDT0 offline with lazystatfs option ========================================================== 06:17:40 (1769080660) [ 7354.914444] Lustre: DEBUG MARKER: SKIP: recovery-small test_150 needs >= 2 MDTs [ 7355.923453] Lustre: DEBUG MARKER: == recovery-small test 152: QoS object allocation could be awakened in case of OST failover ========================================================== 06:17:41 (1769080661) [ 7383.098492] Lustre: DEBUG MARKER: == recovery-small test 153: evict vs reconnect race ====== 06:18:08 (1769080688) [ 7413.227789] LustreError: MGC192.168.202.156@tcp: Connection to MGS (at 192.168.202.156@tcp) was lost; in progress operations using this service will fail [ 7413.245792] Lustre: Evicted from MGS (at 192.168.202.156@tcp) after server handle changed from 0x66da280ed3309777 to 0x66da280ed330be91 [ 7413.249546] Lustre: Skipped 1 previous similar message [ 7421.113681] Lustre: DEBUG MARKER: == recovery-small test 154a: corruption update llog can be skipped ========================================================== 06:18:46 (1769080726) [ 7421.807983] Lustre: DEBUG MARKER: SKIP: recovery-small test_154a needs >= 2 MDTs [ 7422.722246] Lustre: DEBUG MARKER: == recovery-small test 154b: restore update llog after failed recovery ========================================================== 06:18:48 (1769080728) [ 7423.456099] Lustre: DEBUG MARKER: SKIP: recovery-small test_154b needs >= 2 MDTs [ 7424.375194] Lustre: DEBUG MARKER: == recovery-small test 155: failover after client remount ========================================================== 06:18:50 (1769080730) [ 7428.985426] LustreError: 106000:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff9a3e081a5800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 7428.990589] LustreError: 106000:0:(lov_obd.c:783:lov_cleanup()) Skipped 1 previous similar message [ 7429.002817] LustreError: 106000:0:(obd_class.h:479:obd_check_dev()) Device 5 not setup [ 7429.006426] LustreError: 106000:0:(obd_class.h:479:obd_check_dev()) Skipped 5 previous similar messages [ 7429.057169] Lustre: Unmounted lustre-client [ 7429.636785] Lustre: Mounted lustre-client [ 7431.074794] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 7453.124296] Lustre: DEBUG MARKER: == recovery-small test 156: tot_granted miscount after client eviction ========================================================== 06:19:18 (1769080758) [ 7456.486827] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-OST0000 [ 7471.588328] LustreError: 2374:0:(client.c:3503:ptlrpc_replay_req()) cfs_fail_timeout id 536 sleeping for 45000ms [ 7516.632131] LustreError: 2374:0:(client.c:3503:ptlrpc_replay_req()) cfs_fail_timeout id 536 awake [ 7516.639918] LustreError: lustre-OST0000-osc-ffff9a3e09106800: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 7518.311750] Lustre: DEBUG MARKER: oleg256-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 7519.136846] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 7524.398699] Lustre: DEBUG MARKER: == recovery-small test 157: eviction during mmaped i/o === 06:20:30 (1769080830) [ 7524.616143] LustreError: 108384:0:(vvp_io.c:1522:vvp_io_fault_start()) cfs_fail_timeout id 1432 sleeping for 3000ms [ 7527.632123] LustreError: 108384:0:(vvp_io.c:1522:vvp_io_fault_start()) cfs_fail_timeout id 1432 awake [ 7527.655270] LustreError: lustre-OST0000-osc-ffff9a3e09106800: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 7527.663645] LustreError: 108399:0:(ldlm_resource.c:981:ldlm_resource_complain()) lustre-OST0000-osc-ffff9a3e09106800: namespace resource [0x240000401:0x2303:0x0].0x0 (ffff9a3e040a3f00) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 7530.599422] Lustre: DEBUG MARKER: == recovery-small test 158a: connect without access right ========================================================== 06:20:36 (1769080836) [ 7531.429818] Lustre: DEBUG MARKER: SKIP: recovery-small test_158a needs >= 2 MDTS [ 7532.422666] Lustre: DEBUG MARKER: == recovery-small test 160: MDT destroys are blocked by grouplocks ========================================================== 06:20:38 (1769080838) [ 7534.984124] LustreError: lustre-MDT0000-mdc-ffff9a3e09106800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 7534.995155] LustreError: 109297:0:(file.c:249:ll_close_inode_openhandle()) lustre-clilmv-ffff9a3e09106800: inode [0x20000fe01:0x3:0x0] mdc close failed: rc = -108 [ 7535.012133] LustreError: 109302:0:(file.c:6123:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 7535.016277] LustreError: 109302:0:(file.c:6123:ll_inode_revalidate_fini()) Skipped 26 previous similar messages [ 7572.713630] Lustre: DEBUG MARKER: == recovery-small test 161: evict osp by ping evictor ==== 06:21:18 (1769080878) [ 7573.400807] Lustre: DEBUG MARKER: SKIP: recovery-small test_161 needs >= 2 MDTs [ 7574.259940] Lustre: DEBUG MARKER: == recovery-small test 162: File attributes should be persisted after MDS failover ========================================================== 06:21:19 (1769080879) [ 7582.198311] LustreError: 2374:0:(client.c:3418:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9a3e0426a680 x1855007992589568/t137438953528(137438953528) o101->lustre-MDT0000-mdc-ffff9a3e09106800@192.168.202.156@tcp:12/10 lens 576/608 e 0 to 0 dl 1769080948 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'chattr.0' uid:0 gid:0 projid:0 [ 7585.203844] Lustre: DEBUG MARKER: == recovery-small test 163: changelog check for fail write and processing records ========================================================== 06:21:31 (1769080891) [ 7593.698421] Lustre: DEBUG MARKER: == recovery-small test complete, duration 7256 sec ======= 06:21:39 (1769080899) [ 7594.419292] Lustre: DEBUG MARKER: === recovery-small: start cleanup 06:21:40 (1769080900) === [ 7709.181976] Lustre: DEBUG MARKER: === recovery-small: finish cleanup 06:23:35 (1769081015) === [ 7725.539105] Lustre: lustre-MDT0000-mdc-ffff9a3e09106800: Connection to lustre-MDT0000 (at 192.168.202.156@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 7725.543855] Lustre: Skipped 9 previous similar messages [ 7725.546664] Lustre: MGC192.168.202.156@tcp: Connection restored to 192.168.202.156@tcp (at 192.168.202.156@tcp) [ 7725.550039] Lustre: Skipped 12 previous similar messages [ 7727.842885] Lustre: DEBUG MARKER: oleg256-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 7728.441393] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7730.063376] LustreError: 113103:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff9a3e09106800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 7730.066865] LustreError: 113103:0:(lov_obd.c:783:lov_cleanup()) Skipped 1 previous similar message [ 7730.072649] LustreError: 113103:0:(obd_class.h:479:obd_check_dev()) Device 5 not setup [ 7730.074941] LustreError: 113103:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 7730.090147] Lustre: Unmounted lustre-client [ 7760.719896] Key type lgssc unregistered [ 7760.880737] LNet: 113587:0:(lib-ptl.c:967:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 7760.886315] LNetError: 113587:0:(acceptor.c:264:lnet_acceptor_remove_socket()) Interface ens2 not found [ 7760.898590] LNet: Removed LNI 192.168.202.56@tcp [ 7761.340144] Key type .llcrypt unregistered [ 7761.342989] Key type ._llcrypt unregistered