[ 0.000000] Linux version 4.18.0rh8.10-debug (green@maintenance) (gcc version 8.5.0 20210514 (Red Hat 8.5.0-26) (GCC)) #2 SMP Mon Jul 14 01:24:22 EDT 2025 [ 0.000000] Command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers' [ 0.000000] x86/fpu: xstate_offset[2]: 576, xstate_sizes[2]: 256 [ 0.000000] x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'standard' format. [ 0.000000] signal: max sigframe size: 1776 [ 0.000000] BIOS-provided physical RAM map: [ 0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable [ 0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000000100000-0x00000000bffd9fff] usable [ 0.000000] BIOS-e820: [mem 0x00000000bffda000-0x00000000bfffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000100000000-0x0000000146dfffff] usable [ 0.000000] NX (Execute Disable) protection: active [ 0.000000] SMBIOS 2.8 present. [ 0.000000] DMI: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.16.2-1.fc38 04/01/2014 [ 0.000000] Hypervisor detected: KVM [ 0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00 [ 0.000000] kvm-clock: using sched offset of 478406493 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2399.998 MHz processor [ 0.000000] last_pfn = 0x146e00 max_arch_pfn = 0x400000000 [ 0.000000] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT [ 0.000000] last_pfn = 0xbffda max_arch_pfn = 0x400000000 [ 0.000000] found SMP MP-table at [mem 0x000f5b50-0x000f5b5f] [ 0.000000] RAMDISK: [mem 0xbcc64000-0xbffcffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F5970 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE1BB7 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE1A53 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 001A13 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE1AC7 000090 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE1B57 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE1B8F 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe1a53-0xbffe1ac6] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe1a52] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe1ac7-0xbffe1b56] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe1b57-0xbffe1b8e] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe1b8f-0xbffe1bb6] [ 0.000000] No NUMA configuration found [ 0.000000] Faking a node at [mem 0x0000000000000000-0x0000000146dfffff] [ 0.000000] NODE_DATA(0) allocated [mem 0x1465a3000-0x1465cdfff] [ 0.000000] Reserving 256MB of memory at 2752MB for crashkernel (System RAM: 4205MB) [ 0.000000] Zone ranges: [ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.000000] DMA32 [mem 0x0000000001000000-0x00000000ffffffff] [ 0.000000] Normal [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Device empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff] [ 0.000000] node 0: [mem 0x0000000000100000-0x00000000bffd9fff] [ 0.000000] node 0: [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Zeroed struct page in unavailable ranges: 4744 pages [ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x0000000146dfffff] [ 0.000000] ACPI: PM-Timer IO Port: 0x608 [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) [ 0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) [ 0.000000] Using ACPI (MADT) for SMP configuration information [ 0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000] TSC deadline timer available [ 0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs [ 0.000000] kvm-guest: KVM setup pv remote TLB flush [ 0.000000] kvm-guest: setup PV sched yield [ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff] [ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff] [ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff] [ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff] [ 0.000000] PM: Registered nosave memory: [mem 0xbffda000-0xbfffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xc0000000-0xfeffbfff] [ 0.000000] PM: Registered nosave memory: [mem 0xfeffc000-0xfeffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xff000000-0xfffbffff] [ 0.000000] PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff] [ 0.000000] [mem 0xc0000000-0xfeffbfff] available for PCI devices [ 0.000000] Booting paravirtualized kernel on KVM [ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns [ 0.000000] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1 [ 0.000000] percpu: Embedded 63 pages/cpu s221184 r8192 d28672 u524288 [ 0.000000] kvm-guest: PV spinlocks enabled [ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1059618 [ 0.000000] Policy zone: Normal [ 0.000000] Kernel command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] Specific versions of hardware are certified with Red Hat Enterprise Linux 8. Please see the list of hardware certified with Red Hat Enterprise Linux 8 at https://catalog.redhat.com. [ 0.000000] audit: disabled (until reboot) [ 0.000000] software IO TLB: area num 4. [ 0.000000] Memory: 2829700K/4306400K available (18435K kernel code, 11221K rwdata, 7248K rodata, 2908K init, 18040K bss, 524580K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] ftrace: allocating 41240 entries in 162 pages [ 0.000000] ftrace: allocated 162 pages with 3 groups [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] rcu: RCU event tracing is enabled. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ 0.000000] rcu: RCU callback double-/use-after-free debug enabled. [ 0.000000] Rude variant of Tasks RCU enabled. [ 0.000000] Tracing variant of Tasks RCU enabled. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 0.000000] NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16 [ 0.000000] random: get_random_bytes called from start_kernel+0x622/0x9a8 with crng_init=0 [ 0.001000] Console: colour *CGA 80x25 [ 0.001000] printk: console [ttyS1] enabled [ 0.001000] ACPI: Core revision 20220331 [ 0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.001009] APIC: Switch to symmetric I/O mode setup [ 0.003152] x2apic enabled [ 0.004007] Switched APIC routing to physical x2apic. [ 0.005018] kvm-guest: setup PV IPIs [ 0.008000] ..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.008023] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.009010] pid_max: default: 32768 minimum: 301 [ 0.010134] LSM: Security Framework initializing [ 0.011039] Yama: becoming mindful. [ 0.012035] SELinux: Initializing. [ 0.013068] *** VALIDATE selinux *** [ 0.021772] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.025745] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.026144] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.027116] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.028124] *** VALIDATE tmpfs *** [ 0.029486] *** VALIDATE proc *** [ 0.030272] *** VALIDATE cgroup *** [ 0.031009] *** VALIDATE cgroup2 *** [ 0.032271] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.033144] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.035004] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.036031] Spectre V2 : User space: Vulnerable [ 0.037010] Speculative Store Bypass: Vulnerable [ 0.040298] debug: unmapping init [mem 0xffffffff85259000-0xffffffff85260fff] [ 0.042155] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.043599] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.044023] ... version: 2 [ 0.045013] ... bit width: 48 [ 0.046013] ... generic registers: 4 [ 0.047014] ... value mask: 0000ffffffffffff [ 0.048014] ... max period: 00007fffffffffff [ 0.049018] ... fixed-purpose events: 3 [ 0.050013] ... event mask: 000000070000000f [ 0.052224] rcu: Hierarchical SRCU implementation. [ 0.054421] smp: Bringing up secondary CPUs ... [ 0.055596] x86: Booting SMP configuration: [ 0.056025] .... node #0, CPUs: #1 #2 #3 [ 0.059389] smp: Brought up 1 node, 4 CPUs [ 0.061013] smpboot: Max logical packages: 1 [ 0.062019] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.185868] node 0 deferred pages initialised in 120ms [ 0.189145] devtmpfs: initialized [ 0.190194] x86/mm: Memory block size: 128MB [ 0.192476] gcov: version magic: 0x41383552 [ 0.194080] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.195086] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.196242] pinctrl core: initialized pinctrl subsystem [ 0.197204] [ 0.197795] ************************************************************* [ 0.198012] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.199017] ** ** [ 0.200013] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.201015] ** ** [ 0.202012] ** This means that this kernel is built to expose internal ** [ 0.203015] ** IOMMU data structures, which may compromise security on ** [ 0.204016] ** your system. ** [ 0.205019] ** ** [ 0.206012] ** If you see this message and you are not debugging the ** [ 0.207017] ** kernel, report this immediately to your vendor! ** [ 0.208013] ** ** [ 0.209012] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.210013] ************************************************************* [ 0.211633] NET: Registered protocol family 16 [ 0.212440] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.213058] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.214058] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.215420] cpuidle: using governor menu [ 0.218050] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.221686] PCI: Using configuration type 1 for base access [ 0.223152] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.233127] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.234021] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.236114] cryptd: max_cpu_qlen set to 1000 [ 0.240227] ACPI: Added _OSI(Module Device) [ 0.241020] ACPI: Added _OSI(Processor Device) [ 0.242019] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.243020] ACPI: Added _OSI(Processor Aggregator Device) [ 0.246679] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.251612] ACPI: Interpreter enabled [ 0.252086] ACPI: PM: (supports S0 S3 S4 S5) [ 0.253017] ACPI: Using IOAPIC for interrupt routing [ 0.254173] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.255441] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.264561] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.265073] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.266030] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.267124] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.269469] acpiphp: Slot [2] registered [ 0.270273] acpiphp: Slot [3] registered [ 0.271118] acpiphp: Slot [4] registered [ 0.272153] acpiphp: Slot [5] registered [ 0.273222] acpiphp: Slot [6] registered [ 0.274180] acpiphp: Slot [7] registered [ 0.275187] acpiphp: Slot [8] registered [ 0.276157] acpiphp: Slot [9] registered [ 0.277170] acpiphp: Slot [10] registered [ 0.278181] acpiphp: Slot [11] registered [ 0.279145] acpiphp: Slot [12] registered [ 0.280153] acpiphp: Slot [13] registered [ 0.281193] acpiphp: Slot [14] registered [ 0.282637] acpiphp: Slot [15] registered [ 0.283000] acpiphp: Slot [16] registered [ 0.283157] acpiphp: Slot [17] registered [ 0.285158] acpiphp: Slot [18] registered [ 0.288135] acpiphp: Slot [19] registered [ 0.289212] acpiphp: Slot [20] registered [ 0.291144] acpiphp: Slot [21] registered [ 0.293179] acpiphp: Slot [22] registered [ 0.295204] acpiphp: Slot [23] registered [ 0.297173] acpiphp: Slot [24] registered [ 0.298217] acpiphp: Slot [25] registered [ 0.300159] acpiphp: Slot [26] registered [ 0.302165] acpiphp: Slot [27] registered [ 0.304163] acpiphp: Slot [28] registered [ 0.306209] acpiphp: Slot [29] registered [ 0.307145] acpiphp: Slot [30] registered [ 0.309151] acpiphp: Slot [31] registered [ 0.310171] PCI host bridge to bus 0000:00 [ 0.312031] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.315052] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.318043] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.319041] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.320000] pci_bus 0000:00: root bus resource [mem 0x180000000-0x1ffffffff window] [ 0.322039] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.325238] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.329836] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.334762] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.343019] pci 0000:00:01.1: reg 0x20: [io 0xc120-0xc12f] [ 0.348069] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.349033] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.351032] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.353036] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.356641] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.359934] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.363070] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.365736] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.370025] pci 0000:00:02.0: reg 0x10: [io 0xc100-0xc11f] [ 0.380021] pci 0000:00:02.0: reg 0x20: [mem 0xfebf4000-0xfebf7fff 64bit pref] [ 0.386039] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.391602] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.397027] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.402017] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.413019] pci 0000:00:05.0: reg 0x20: [mem 0xfebf8000-0xfebfbfff 64bit pref] [ 0.422326] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.429021] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.435026] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.446018] pci 0000:00:06.0: reg 0x20: [mem 0xfebfc000-0xfebfffff 64bit pref] [ 0.454434] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.459164] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.461398] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.464393] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.467242] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.472169] iommu: Default domain type: Passthrough [ 0.474440] SCSI subsystem initialized [ 0.475142] ACPI: bus type USB registered [ 0.477112] usbcore: registered new interface driver usbfs [ 0.479093] usbcore: registered new interface driver hub [ 0.480067] usbcore: registered new device driver usb [ 0.481116] pps_core: LinuxPPS API ver. 1 registered [ 0.483011] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.485066] PTP clock support registered [ 0.488041] EDAC MC: Ver: 3.0.0 [ 0.490177] PCI: Using ACPI for IRQ routing [ 0.492014] NetLabel: Initializing [ 0.493014] NetLabel: domain hash size = 128 [ 0.494014] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.495386] NetLabel: unlabeled traffic allowed by default [ 0.498046] vgaarb: loaded [ 0.500008] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.501020] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.510919] clocksource: Switched to clocksource kvm-clock [ 0.622051] VFS: Disk quotas dquot_6.6.0 [ 0.623564] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.625212] *** VALIDATE ramfs *** [ 0.626028] *** VALIDATE hugetlbfs *** [ 0.627063] pnp: PnP ACPI init [ 0.629316] pnp: PnP ACPI: found 6 devices [ 0.652304] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.655164] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.657509] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.659576] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.661530] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.663420] pci_bus 0000:00: resource 8 [mem 0x180000000-0x1ffffffff window] [ 0.665708] NET: Registered protocol family 2 [ 0.667951] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.672068] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.675900] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.681899] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.685221] TCP: Hash tables configured (established 65536 bind 65536) [ 0.688401] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.691920] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.695349] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.698819] NET: Registered protocol family 1 [ 0.701827] RPC: Registered named UNIX socket transport module. [ 0.703857] RPC: Registered udp transport module. [ 0.705326] RPC: Registered tcp transport module. [ 0.706635] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.708460] NET: Registered protocol family 44 [ 0.710024] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.711910] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.714429] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.716953] PCI: CLS 0 bytes, default 64 [ 0.718827] Unpacking initramfs... [ 2.128175] debug: unmapping init [mem 0xffff947d7cc64000-0xffff947d7ffcffff] [ 2.132216] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.134600] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.137715] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 2.643768] Initialise system trusted keyrings [ 2.645542] Key type blacklist registered [ 2.647369] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.656288] zbud: loaded [ 2.659154] *** VALIDATE nfs *** [ 2.660340] *** VALIDATE nfs4 *** [ 2.661687] pstore: using deflate compression [ 2.665243] Platform Keyring initialized [ 2.767926] NET: Registered protocol family 38 [ 2.769394] Key type asymmetric registered [ 2.770451] Asymmetric key parser 'x509' registered [ 2.772810] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 2.775880] io scheduler mq-deadline registered [ 2.777596] io scheduler kyber registered [ 2.779464] io scheduler bfq registered [ 2.781918] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 2.784741] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 2.787318] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 2.790142] ACPI: Power Button [PWRF] [ 2.886308] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 2.978038] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 3.077708] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 3.111017] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.141335] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.146307] Non-volatile memory driver v1.3 [ 3.148048] Linux agpgart interface v0.103 [ 3.179122] virtio_blk virtio1: [vda] 133840 512-byte logical blocks (68.5 MB/65.4 MiB) [ 3.181833] vda: detected capacity change from 0 to 68526080 [ 3.199061] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.201869] vdb: detected capacity change from 0 to 1073741824 [ 3.208894] libphy: Fixed MDIO Bus: probed [ 3.219941] usbcore: registered new interface driver usbserial_generic [ 3.222371] usbserial: USB Serial support registered for generic [ 3.224679] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.227774] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.229055] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.230764] mousedev: PS/2 mouse device common for all mice [ 3.232684] rtc_cmos 00:05: RTC can wake from S4 [ 3.234641] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.235913] rtc_cmos 00:05: registered as rtc0 [ 3.239699] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.239917] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.242583] intel_pstate: CPU model not supported [ 3.247462] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.253172] hid: raw HID events driver (C) Jiri Kosina [ 3.255445] usbcore: registered new interface driver usbhid [ 3.257890] usbhid: USB HID core driver [ 3.260135] drop_monitor: Initializing network drop monitor service [ 3.262901] Initializing XFRM netlink socket [ 3.264753] NET: Registered protocol family 10 [ 3.267509] Segment Routing with IPv6 [ 3.269076] NET: Registered protocol family 17 [ 3.271071] mpls_gso: MPLS GSO support [ 3.275950] RAS: Correctable Errors collector initialized. [ 3.278304] AVX version of gcm_enc/dec engaged. [ 3.280273] AES CTR mode by8 optimization enabled [ 3.375831] sched_clock: Marking stable (3375814173, 0)->(4386054354, -1010240181) [ 3.379619] registered taskstats version 1 [ 3.381955] Loading compiled-in X.509 certificates [ 3.387327] zswap: loaded using pool lzo/zbud [ 3.424063] Key type big_key registered [ 3.444271] Key type encrypted registered [ 3.445775] ima: No TPM chip found, activating TPM-bypass! [ 3.448054] ima: Allocated hash algorithm: sha1 [ 3.450272] ima: No architecture policies found [ 3.452514] evm: Initialising EVM extended attributes: [ 3.454372] evm: security.selinux [ 3.455710] evm: security.ima [ 3.456691] evm: security.capability [ 3.458171] evm: HMAC attrs: 0x1 [ 3.461734] rtc_cmos 00:05: setting system clock to 2025-11-17 03:15:42 UTC (1763349342) [ 3.468261] debug: unmapping init [mem 0xffffffff86203000-0xffffffff863fffff] [ 3.470480] debug: unmapping init [mem 0xffffffff84f82000-0xffffffff85258fff] [ 3.474155] Write protecting the kernel read-only data: 28672k [ 3.477716] debug: unmapping init [mem 0xffffffff83603000-0xffffffff837fffff] [ 3.480673] debug: unmapping init [mem 0xffffffff83f14000-0xffffffff83ffffff] [ 3.516632] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 3.525485] systemd[1]: Detected virtualization kvm. [ 3.527509] systemd[1]: Detected architecture x86-64. [ 3.529797] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.559204] systemd[1]: No hostname configured. [ 3.561152] systemd[1]: Set hostname to . [ 3.563541] random: systemd: uninitialized urandom read (16 bytes read) [ 3.566397] systemd[1]: Initializing machine ID from random generator. [ 3.619041] random: ln: uninitialized urandom read (6 bytes read) [ 3.721418] random: systemd: uninitialized urandom read (16 bytes read) [ 3.724513] systemd[1]: Listening on Journal Socket (/dev/log). [ OK ] Listening on Journal Socket (/dev/log). [ 3.732839] systemd[1]: Started Dispatch Password Requests to Console Directory Watch. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ 3.740457] systemd[1]: Reached target Swap. [ OK ] Reached target Swap. [ OK ] Listening on udev Control Socket. [ OK ] Reached target Timers. [ OK ] Listening on udev Kernel Socket. [ OK ] Reached target Initrd Root Device. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Listening on Journal Socket. Starting Create list of required st…ce nodes for the current kernel... Starting Journal Service... [ OK ] Started Memstrack Anylazing Service. [ OK ] Reached target Sockets. [ OK ] Reached target Slices. [ OK ] Reached target Local File Systems. Starting Setup Virtual Console... [ OK ] Reached target Paths. Starting Create Volatile Files and Directories... Starting Apply Kernel Variables... [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Setup Virtual Console. Starting dracut cmdline hook... Starting Create Static Device Nodes in /dev... [ OK ] Started Apply Kernel Variables. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started Journal Service. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 4.428604] device-mapper: uevent: version 1.0.3 [ 4.432793] device-mapper: ioctl: 4.46.0-ioctl (2022-02-22) initialised: dm-devel@redhat.com [ OK ] Started dracut pre-udev hook. Starting udev Kernel Device Manager... [ OK ] Started udev Kernel Device Manager. Starting dracut pre-trigger hook... [ OK ] Started dracut pre-trigger hook. Starting udev Coldplug all Devices... Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting dracut initqueue hook... [ 5.180132] virtio_net virtio0 ens2: renamed from eth0 [ 5.243829] scsi host0: ata_piix [ 5.257822] scsi host1: ata_piix [ 5.259345] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc120 irq 14 [ 5.262055] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc128 irq 15 [ 9.478926] dracut-initqueue[587]: RTNETLINK answers: File exists [ 9.971239] random: crng init done [ 9.972664] random: 7 urandom warning(s) missed due to ratelimiting Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Mounting /sysroot... [ 10.355566] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped target Timers. [ 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. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Paths. [ OK ] Stopped target Sockets. [ OK ] Stopped target Slices. [ OK ] Stopped target System Initialization. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped target Swap. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. [ OK ] Stopped target Local File Systems. Stopping udev Kernel Device Manager... [ OK ] Stopped Apply Kernel Variables. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Closed udev Control Socket. [ OK ] Closed udev Kernel Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 11.470612] printk: systemd: 25 output lines suppressed due to ratelimiting [ 11.692579] SELinux: Disabled at runtime. [ 11.754335] 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) [ 11.762583] systemd[1]: Detected virtualization kvm. [ 11.764391] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 12.232548] systemd[1]: initrd-switch-root.service: Succeeded. [ 12.239430] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 12.244436] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 12.250577] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 12.256443] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 12.284600] systemd[1]: Starting Journal Service... Starting Journal Service... [ 12.292108] systemd[1]: Listening on udev Control Socket. [ OK ] Listening on udev Control Socket. Activating swap /dev/disk/by-label/SWAP... [ OK ] Started Forward Password Requests to Wall Directory Watch. Starting Remount Root and Kernel File Systems... [ OK ] Created slice system-getty.slice. Mounting Kernel Debug File System... [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd File Systems. Starting Create list of required st…ce nodes for the current kernel... [ 12.336092] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS [ OK ] Reached target rpc_pipefs.target. Mounting Huge Pages File System... [ OK ] Listening on RPCbind Server Activation Socket. [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Listening on Process Core Dump Socket. [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Stopped target Initrd Root File System. Starting Apply Kernel Variables... Mounting POSIX Message Queue File System... [ OK ] Reached target RPC Port Mapper. [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Listening on udev Kernel Socket. Starting udev Coldplug all Devices... [ OK ] Created slice User and Session Slice. [ OK ] Reached target Slices. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Started Journal Service. [ OK ] Activated swap /dev/disk/by-label/SWAP. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Mounted Kernel Debug File System. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Mounted Huge Pages File System. [ OK ] Started Apply Kernel Variables. [ OK ] Mounted POSIX Message Queue File System. Starting Create Static Device Nodes in /dev... Starting Configure read-only root support... [ OK ] Reached target Swap. Starting Flush Journal to Persistent Storage... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. Starting udev Kernel Device Manager... [ OK ] Reached target Local File Systems (Pre). Mounting /mnt... Mounting /home/green/git/lustre-release... [ OK ] Started udev Coldplug all Devices. [ OK ] Mounted /mnt. [ 12.739646] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 13.014315] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 13.035952] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 13.162487] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 13.182264] EDAC sbridge: Ver: 1.1.2 [ 14.344310] Key type dns_resolver registered [ 14.638682] NFS: Registering the id_resolver key type [ 14.640785] Key type id_resolver registered [ 14.642361] Key type id_legacy registered [ 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 ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. Starting Login Service... [ OK ] Reached target sshd-keygen.target. [ OK ] Started irqbalance daemon. [ OK ] Started dnf makecache --timer. Starting Restore /run/initramfs on shutdown... [ OK ] Started D-Bus System Message Bus. Starting Network Manager... [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Reached target Timers. [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Login Service. [ OK ] Started Network Manager. [ OK ] Reached target Network. Starting Dynamic System Tuning Daemon... Starting GSSAPI Proxy Daemon... Starting OpenSSH server daemon... Starting Network Manager Wait Online... Starting Hostname Service... [ OK ] Started OpenSSH server daemon. [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... [ OK ] Started Permit User Sessions. [ OK ] Started Command Scheduler. [ OK ] Started Getty on tty1. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Serial Getty on ttyS1. [ OK ] Reached target Login Prompts. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting Crash recovery kernel arming... Starting System Logging Service... Starting Notify NFS peers of a restart... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Starting Authorization Manager... [ OK ] Started Authorization Manager. [ OK ] Started Dynamic System Tuning Daemon. [ OK ] Reached target Multi-User System. [ OK ] Reached target Graphical Interface. Starting Update UTMP about System Runlevel Changes... [ OK ] Started Update UTMP about System Runlevel Changes. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg356-client login: [ 44.210742] libcfs: loading out-of-tree module taints kernel. [ 44.236299] Key type ._llcrypt registered [ 44.239041] Key type .llcrypt registered [ 44.552775] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [ 44.560228] alg: No test for adler32 (adler32-zlib) [ 45.588501] Lustre: Lustre: Build Version: 2.16.61_42_gb9e4aef [ 45.943807] LNet: Added LNI 192.168.203.56@tcp [8/256/0/180] [ 47.567157] Key type lgssc registered [ 48.296280] Lustre: Echo OBD driver; http://www.lustre.org/ [ 171.940427] hrtimer: interrupt took 8883952 ns [ 198.117932] Lustre: Mounted lustre-client [ 202.721264] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 219.182529] Lustre: DEBUG MARKER: oleg356-client.virtnet: executing check_logdir /tmp/testlogs/ [ 223.199446] Lustre: DEBUG MARKER: oleg356-client.virtnet: executing yml_node [ 223.714501] Lustre: lustre-OST0000-osc-ffff947dc517f000: disconnect after 23s idle [ 227.540560] Lustre: DEBUG MARKER: Client: 2.16.61.42 [ 230.483401] Lustre: DEBUG MARKER: MDS: 2.16.61.42 [ 233.369800] Lustre: DEBUG MARKER: OSS: 2.16.61.42 [ 235.075068] Lustre: DEBUG MARKER: -----============= acceptance-small: recovery-small ============----- Sun Nov 16 22:19:32 EST 2025 [ 252.858894] Lustre: DEBUG MARKER: excepting tests: 136 [ 254.476373] Lustre: DEBUG MARKER: === recovery-small: start setup 22:19:52 (1763349592) === [ 258.209809] Lustre: DEBUG MARKER: oleg356-client.virtnet: executing check_config_client /mnt/lustre [ 277.535071] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 289.941396] Lustre: DEBUG MARKER: === recovery-small: finish setup 22:20:27 (1763349627) === [ 291.433137] Lustre: DEBUG MARKER: == recovery-small test 1: create, chmod, stat: drop req, drop rep ========================================================== 22:20:29 (1763349629) [ 308.703211] Lustre: 10794:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763349631/real 1763349631] req@ffff947dc8f62680 x1849005843692288/t0(0) o700->lustre-MDT0000-mdc-ffff947dc517f000@192.168.203.156@tcp:30/10 lens 264/248 e 0 to 1 dl 1763349647 ref 2 fl Rpc:XQr/200/ffffffff rc 0/-1 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 308.750104] Lustre: lustre-MDT0000-mdc-ffff947dc517f000: Connection to lustre-MDT0000 (at 192.168.203.156@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 308.787487] Lustre: lustre-MDT0000-mdc-ffff947dc517f000: Connection restored to 192.168.203.156@tcp (at 192.168.203.156@tcp) [ 327.135223] Lustre: 10815:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763349650/real 1763349650] req@ffff947dc91dc380 x1849005843694592/t0(0) o36->lustre-MDT0000-mdc-ffff947dc517f000@192.168.203.156@tcp:12/10 lens 520/576 e 0 to 1 dl 1763349666 ref 2 fl Rpc:XQr/200/ffffffff rc 0/-1 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 327.181422] Lustre: lustre-MDT0000-mdc-ffff947dc517f000: Connection to lustre-MDT0000 (at 192.168.203.156@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 327.234382] Lustre: lustre-MDT0000-mdc-ffff947dc517f000: Connection restored to 192.168.203.156@tcp (at 192.168.203.156@tcp) [ 346.595034] Lustre: 10841:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763349669/real 1763349669] req@ffff947dc91dea00 x1849005843696384/t0(0) o101->lustre-MDT0000-mdc-ffff947dc517f000@192.168.203.156@tcp:12/10 lens 576/1152 e 0 to 1 dl 1763349685 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'tchmod.0' uid:0 gid:0 projid:0 [ 346.660635] Lustre: lustre-MDT0000-mdc-ffff947dc517f000: Connection to lustre-MDT0000 (at 192.168.203.156@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 346.752085] Lustre: lustre-MDT0000-mdc-ffff947dc517f000: Connection restored to 192.168.203.156@tcp (at 192.168.203.156@tcp) [ 366.559163] Lustre: 10861:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763349689/real 1763349689] req@ffff947dc91dfb80 x1849005843699200/t0(0) o36->lustre-MDT0000-mdc-ffff947dc517f000@192.168.203.156@tcp:12/10 lens 488/512 e 0 to 1 dl 1763349705 ref 2 fl Rpc:XQr/200/ffffffff rc 0/-1 job:'tchmod.0' uid:0 gid:0 projid:4294967295 [ 366.585436] Lustre: lustre-MDT0000-mdc-ffff947dc517f000: Connection to lustre-MDT0000 (at 192.168.203.156@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 366.609702] Lustre: lustre-MDT0000-mdc-ffff947dc517f000: Connection restored to 192.168.203.156@tcp (at 192.168.203.156@tcp) [ 383.967202] Lustre: 10887:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763349707/real 1763349707] req@ffff947dd122f800 x1849005843700992/t0(0) o34->lustre-MDT0000-mdc-ffff947dc517f000@192.168.203.156@tcp:12/10 lens 472/728 e 0 to 1 dl 1763349723 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'statone.0' uid:0 gid:0 projid:0 [ 383.993874] Lustre: lustre-MDT0000-mdc-ffff947dc517f000: Connection to lustre-MDT0000 (at 192.168.203.156@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 384.028065] Lustre: lustre-MDT0000-mdc-ffff947dc517f000: Connection restored to 192.168.203.156@tcp (at 192.168.203.156@tcp) [ 402.911424] Lustre: 10908:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763349725/real 1763349725] req@ffff947dd122f480 x1849005843702784/t0(0) o34->lustre-MDT0000-mdc-ffff947dc517f000@192.168.203.156@tcp:12/10 lens 472/728 e 0 to 1 dl 1763349741 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'statone.0' uid:0 gid:0 projid:0 [ 402.951699] Lustre: lustre-MDT0000-mdc-ffff947dc517f000: Connection to lustre-MDT0000 (at 192.168.203.156@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 402.973597] Lustre: lustre-MDT0000-mdc-ffff947dc517f000: Connection restored to 192.168.203.156@tcp (at 192.168.203.156@tcp) [ 410.372647] Lustre: DEBUG MARKER: == recovery-small test 4: open: drop req, drop rep ======= 22:22:28 (1763349748) [ 426.975176] Lustre: 11519:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763349750/real 1763349750] req@ffff947dc91dc000 x1849005843705728/t0(0) o101->lustre-MDT0000-mdc-ffff947dc517f000@192.168.203.156@tcp:12/10 lens 576/1152 e 0 to 1 dl 1763349766 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'cat.0' uid:0 gid:0 projid:0 [ 427.012936] Lustre: lustre-MDT0000-mdc-ffff947dc517f000: Connection to lustre-MDT0000 (at 192.168.203.156@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 427.057893] Lustre: lustre-MDT0000-mdc-ffff947dc517f000: Connection restored to 192.168.203.156@tcp (at 192.168.203.156@tcp) [ 453.192203] Lustre: DEBUG MARKER: == recovery-small test 5: rename: drop req, drop rep ===== 22:23:10 (1763349790) [ 469.985103] Lustre: 12150:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763349793/real 1763349793] req@ffff947dd1262680 x1849005843713024/t0(0) o101->lustre-MDT0000-mdc-ffff947dc517f000@192.168.203.156@tcp:12/10 lens 576/1152 e 0 to 1 dl 1763349809 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'mv.0' uid:0 gid:0 projid:0 [ 470.022837] Lustre: 12150:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 470.032731] Lustre: lustre-MDT0000-mdc-ffff947dc517f000: Connection to lustre-MDT0000 (at 192.168.203.156@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 470.050336] Lustre: Skipped 1 previous similar message [ 470.086459] Lustre: lustre-MDT0000-mdc-ffff947dc517f000: Connection restored to 192.168.203.156@tcp (at 192.168.203.156@tcp) [ 470.101584] Lustre: Skipped 1 previous similar message [ 495.115931] Lustre: DEBUG MARKER: == recovery-small test 6: link, unlink: drop req, drop rep ========================================================== 22:23:52 (1763349832) [ 517.599630] Lustre: lustre-OST0000-osc-ffff947dc517f000: disconnect after 22s idle [ 517.617076] Lustre: Skipped 1 previous similar message [ 549.344077] Lustre: 12837:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763349872/real 1763349872] req@ffff947dd1261f80 x1849005843728000/t0(0) o101->lustre-MDT0000-mdc-ffff947dc517f000@192.168.203.156@tcp:12/10 lens 576/1152 e 0 to 1 dl 1763349888 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'unlink.0' uid:0 gid:0 projid:0 [ 549.362969] Lustre: 12837:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 549.368362] Lustre: lustre-MDT0000-mdc-ffff947dc517f000: Connection to lustre-MDT0000 (at 192.168.203.156@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 549.376270] Lustre: Skipped 3 previous similar messages [ 549.408404] Lustre: lustre-MDT0000-mdc-ffff947dc517f000: Connection restored to 192.168.203.156@tcp (at 192.168.203.156@tcp) [ 549.415109] Lustre: Skipped 3 previous similar messages [ 574.345266] Lustre: DEBUG MARKER: == recovery-small test 8: touch: drop rep (bug 1423) ===== 22:25:12 (1763349912) [ 599.833564] Lustre: DEBUG MARKER: == recovery-small test 9: pause bulk on OST (bug 1420) === 22:25:37 (1763349937) [ 614.631694] Lustre: DEBUG MARKER: == recovery-small test 10a: finish request on server after client eviction (bug 1521) ========================================================== 22:25:52 (1763349952) [ 615.127564] Lustre: *** cfs_fail_loc=305, val=0*** [ 631.567474] Lustre: *** cfs_fail_loc=305, val=0*** [ 637.407471] Lustre: lustre-OST0000-osc-ffff947dc517f000: disconnect after 23s idle [ 647.964688] Lustre: *** cfs_fail_loc=305, val=0*** [ 663.296888] Lustre: *** cfs_fail_loc=305, val=0*** [ 679.695394] Lustre: *** cfs_fail_loc=305, val=0*** [ 695.058104] Lustre: *** cfs_fail_loc=305, val=0*** [ 711.428242] Lustre: *** cfs_fail_loc=305, val=0*** [ 728.034721] LustreError: lustre-MDT0000-mdc-ffff947dc517f000: operation ldlm_enqueue to node 192.168.203.156@tcp failed: rc = -107 [ 728.039615] Lustre: lustre-MDT0000-mdc-ffff947dc517f000: Connection to lustre-MDT0000 (at 192.168.203.156@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 728.052120] Lustre: Skipped 2 previous similar messages [ 728.074734] LustreError: lustre-MDT0000-mdc-ffff947dc517f000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 728.093518] Lustre: lustre-MDT0000-mdc-ffff947dc517f000: Connection restored to 192.168.203.156@tcp (at 192.168.203.156@tcp) [ 728.101781] Lustre: Skipped 2 previous similar messages [ 736.121730] Lustre: DEBUG MARKER: == recovery-small test 10b: re-send BL AST =============== 22:27:54 (1763350074) [ 759.085438] Lustre: DEBUG MARKER: == recovery-small test 10c: re-send BL AST vs reconnect race (LU-5569) ========================================================== 22:28:16 (1763350096) [ 759.637608] Lustre: *** cfs_fail_loc=305, val=0*** [ 759.639180] Lustre: Skipped 1 previous similar message [ 766.930889] Lustre: DEBUG MARKER: == recovery-small test 10d: test failed blocking ast ===== 22:28:24 (1763350104) [ 769.289977] LustreError: 16745:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff947dc517f000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 769.312745] LustreError: 16745:0:(obd_class.h:479:obd_check_dev()) Device 6 not setup [ 769.382225] Lustre: Unmounted lustre-client [ 769.793892] Lustre: Mounted lustre-client [ 771.246315] LustreError: lustre-OST0000-osc-ffff947dd12f6800: operation ost_statfs to node 192.168.203.156@tcp failed: rc = -107 [ 771.271268] LustreError: lustre-OST0000-osc-ffff947dd12f6800: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 771.286750] Lustre: 2403:0:(llite_lib.c:4226:ll_dirty_page_discard_warn()) lustre: dirty page discard: 192.168.203.156@tcp:/lustre/fid: [0x200000404:0x1:0x0]/ may get corrupted (rc -108) [ 772.952892] LustreError: 16945:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff947dd10c0800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 772.961237] LustreError: 16945:0:(lov_obd.c:783:lov_cleanup()) Skipped 1 previous similar message [ 772.978703] LustreError: 16945:0:(obd_class.h:479:obd_check_dev()) Device 12 not setup [ 772.982032] LustreError: 16945:0:(obd_class.h:479:obd_check_dev()) Skipped 9 previous similar messages [ 773.044550] Lustre: Unmounted lustre-client [ 778.992575] Lustre: DEBUG MARKER: == recovery-small test 10e: re-send BL AST vs reconnect race 2 ========================================================== 22:28:36 (1763350116) [ 780.349985] Lustre: DEBUG MARKER: SKIP: recovery-small test_10e need two clients [ 781.871670] Lustre: DEBUG MARKER: == recovery-small test 11: wake up a thread waiting for completion after eviction (b=2460) ========================================================== 22:28:39 (1763350119) [ 806.987344] Lustre: DEBUG MARKER: == recovery-small test 12: recover from timed out resend in ptlrpcd (b=2494) ========================================================== 22:29:04 (1763350144) [ 807.194600] Lustre: DEBUG MARKER: multiop /mnt/lustre/f12.recovery-small OS_c [ 824.799248] Lustre: 18525:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763350147/real 1763350147] req@ffff947dd122c000 x1849005843805312/t0(0) o35->lustre-MDT0000-mdc-ffff947dd12f6800@192.168.203.156@tcp:23/10 lens 392/624 e 0 to 1 dl 1763350163 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'multiop.0' uid:0 gid:0 projid:0 [ 824.843698] Lustre: 18525:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 850.381444] Lustre: DEBUG MARKER: == recovery-small test 13: mdc_readpage restart test (bug 1138) ========================================================== 22:29:48 (1763350188) [ 874.476957] Lustre: DEBUG MARKER: == recovery-small test 14: mdc_readpage resend test (bug 1138) ========================================================== 22:30:12 (1763350212) [ 881.322939] Lustre: DEBUG MARKER: == recovery-small test 15: failed open (-ENOMEM) ========= 22:30:19 (1763350219) [ 887.203453] Lustre: DEBUG MARKER: == recovery-small test 16: timeout bulk put, don't evict client (2732) ========================================================== 22:30:25 (1763350225) [ 932.326666] Lustre: DEBUG MARKER: == recovery-small test 17a: timeout bulk get, don't evict client (2732) ========================================================== 22:31:10 (1763350270) [ 983.476282] Lustre: DEBUG MARKER: == recovery-small test 17b: timeout bulk get, dont evict client (3582) ========================================================== 22:32:01 (1763350321) [ 984.910907] Lustre: DEBUG MARKER: SKIP: recovery-small test_17b Needs multiple clients [ 986.533502] Lustre: DEBUG MARKER: == recovery-small test 18a: manual ost invalidate clears page cache immediately ========================================================== 22:32:04 (1763350324) [ 987.246410] Lustre: setting import lustre-OST0001_UUID INACTIVE by administrator request [ 987.301984] Lustre: lustre-OST0001-osc-ffff947dd12f6800: Connection to lustre-OST0001 (at 192.168.203.156@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 987.331635] Lustre: Skipped 5 previous similar messages [ 987.343818] LustreError: lustre-OST0001-osc-ffff947dd12f6800: This client was evicted by lustre-OST0001; in progress operations using this service will fail. [ 992.954257] Lustre: DEBUG MARKER: == recovery-small test 18b: eviction and reconnect clears page cache (2766) ========================================================== 22:32:10 (1763350330) [ 996.873410] LustreError: lustre-OST0000-osc-ffff947dd12f6800: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 996.895222] Lustre: lustre-OST0000-osc-ffff947dd12f6800: Connection restored to 192.168.203.156@tcp (at 192.168.203.156@tcp) [ 996.903811] Lustre: Skipped 4 previous similar messages [ 1023.173538] Lustre: DEBUG MARKER: == recovery-small test 18c: Dropped connect reply after eviction handing (14755) ========================================================== 22:32:40 (1763350360) [ 1027.339594] LustreError: lustre-OST0000-osc-ffff947dd12f6800: operation ost_statfs to node 192.168.203.156@tcp failed: rc = -107 [ 1037.827962] Lustre: Evicted from lustre-OST0000_UUID (at 192.168.203.156@tcp) after server handle changed from 0x991b1f37c5176b37 to 0x991b1f37c5176c9c [ 1037.842781] LustreError: lustre-OST0000-osc-ffff947dd12f6800: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 1046.162616] Lustre: DEBUG MARKER: == recovery-small test 19a: test expired_lock_main on mds (2867) ========================================================== 22:33:03 (1763350383) [ 1046.594860] Lustre: Mounted lustre-client [ 1046.597555] Lustre: Skipped 1 previous similar message [ 1096.161307] Lustre: 2403:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763350419/real 1763350419] req@ffff947dc6725c00 x1849005843869056/t0(0) o103->lustre-MDT0000-mdc-ffff947dd12f6800@192.168.203.156@tcp:17/18 lens 328/224 e 0 to 1 dl 1763350435 ref 1 fl Rpc:XQr/202/ffffffff rc 0/-1 job:'ldlm_bl.0' uid:0 gid:0 projid:4294967295 [ 1096.199112] Lustre: 2403:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 4 previous similar messages [ 1153.929557] LustreError: lustre-MDT0000-mdc-ffff947dd12f6800: operation ldlm_enqueue to node 192.168.203.156@tcp failed: rc = -107 [ 1153.943228] LustreError: lustre-MDT0000-mdc-ffff947dd12f6800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 1153.953285] LustreError: 24857:0:(file.c:249:ll_close_inode_openhandle()) lustre-clilmv-ffff947dd12f6800: inode [0x200000404:0x1:0x0] mdc close failed: rc = -108 [ 1153.953521] LustreError: 24856:0:(file.c:6099:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -5 [ 1154.925320] LustreError: 24866:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff947dc5cc4000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 1154.936297] LustreError: 24866:0:(lov_obd.c:783:lov_cleanup()) Skipped 1 previous similar message [ 1154.946142] LustreError: 24866:0:(obd_class.h:479:obd_check_dev()) Device 12 not setup [ 1154.955369] LustreError: 24866:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 1155.024465] Lustre: Unmounted lustre-client [ 1161.131987] Lustre: DEBUG MARKER: == recovery-small test 19b: test expired_lock_main on ost (2867) ========================================================== 22:34:58 (1763350498) [ 1161.561270] Lustre: Mounted lustre-client [ 1269.758358] LustreError: lustre-OST0001-osc-ffff947dd12f6800: This client was evicted by lustre-OST0001; in progress operations using this service will fail. [ 1269.977600] LustreError: 25666:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff947dc517f000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 1269.998118] LustreError: 25666:0:(lov_obd.c:783:lov_cleanup()) Skipped 1 previous similar message [ 1270.024057] LustreError: 25666:0:(obd_class.h:479:obd_check_dev()) Device 12 not setup [ 1270.030395] LustreError: 25666:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 1270.083276] Lustre: Unmounted lustre-client [ 1276.300940] Lustre: DEBUG MARKER: == recovery-small test 19c: check reconnect and lock resend do not trigger expired_lock_main ========================================================== 22:36:54 (1763350614) [ 1276.933584] Lustre: Mounted lustre-client [ 1281.480698] LustreError: 26346:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff947dc564f800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 1281.495771] LustreError: 26346:0:(lov_obd.c:783:lov_cleanup()) Skipped 1 previous similar message [ 1281.505920] LustreError: 26346:0:(obd_class.h:479:obd_check_dev()) Device 12 not setup [ 1281.508549] LustreError: 26346:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 1281.566585] Lustre: Unmounted lustre-client [ 1293.806051] Lustre: DEBUG MARKER: == recovery-small test 20a: ldlm_handle_enqueue error (should return error) ========================================================== 22:37:11 (1763350631) [ 1295.822281] LustreError: lustre-OST0000-osc-ffff947dd12f6800: operation ldlm_enqueue to node 192.168.203.156@tcp failed: rc = -12 [ 1303.125231] Lustre: DEBUG MARKER: == recovery-small test 20b: ldlm_handle_enqueue error (should return error) ========================================================== 22:37:20 (1763350640) [ 1305.039861] LustreError: lustre-OST0000-osc-ffff947dd12f6800: operation ldlm_enqueue to node 192.168.203.156@tcp failed: rc = -12 [ 1312.530181] Lustre: DEBUG MARKER: == recovery-small test 21a: drop close request while close and open are both in flight ========================================================== 22:37:30 (1763350650) [ 1340.453774] Lustre: DEBUG MARKER: == recovery-small test 21b: drop open request while close and open are both in flight ========================================================== 22:37:57 (1763350677) [ 1488.451889] Lustre: DEBUG MARKER: == recovery-small test 21c: drop both request while close and open are both in flight ========================================================== 22:40:26 (1763350826) [ 1510.879261] Lustre: lustre-MDT0000-mdc-ffff947dd12f6800: Connection to lustre-MDT0000 (at 192.168.203.156@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1510.896872] Lustre: Skipped 18 previous similar messages [ 1510.919571] Lustre: lustre-MDT0000-mdc-ffff947dd12f6800: Connection restored to 192.168.203.156@tcp (at 192.168.203.156@tcp) [ 1510.936232] Lustre: Skipped 16 previous similar messages [ 1518.272417] Lustre: DEBUG MARKER: == recovery-small test 21d: drop close reply while close and open are both in flight ========================================================== 22:40:56 (1763350856) [ 1545.887186] Lustre: DEBUG MARKER: == recovery-small test 21e: drop open reply while close and open are both in flight ========================================================== 22:41:23 (1763350883) [ 1687.519452] Lustre: 30706:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763350886/real 1763350886] req@ffff947dd1261500 x1849005844001280/t0(0) o36->lustre-MDT0000-mdc-ffff947dd12f6800@192.168.203.156@tcp:12/10 lens 488/512 e 0 to 1 dl 1763351026 ref 2 fl Rpc:XQr/200/ffffffff rc 0/-1 job:'touch.0' uid:0 gid:0 projid:4294967295 [ 1687.542120] Lustre: 30706:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 13 previous similar messages [ 1688.903369] Lustre: DEBUG MARKER: == recovery-small test 21f: drop both reply while close and open are both in flight ========================================================== 22:43:46 (1763351026) [ 1714.059254] Lustre: DEBUG MARKER: == recovery-small test 21g: drop open reply and close request while close and open are both in flight ========================================================== 22:44:12 (1763351052) [ 1739.339427] Lustre: DEBUG MARKER: == recovery-small test 21h: drop open request and close reply while close and open are both in flight ========================================================== 22:44:37 (1763351077) [ 1762.644327] Lustre: DEBUG MARKER: == recovery-small test 22: drop close request and do mknod ========================================================== 22:45:00 (1763351100) [ 1784.934796] Lustre: DEBUG MARKER: == recovery-small test 23: client hang when close a file after mds crash ========================================================== 22:45:22 (1763351122) [ 1810.911534] LustreError: MGC192.168.203.156@tcp: Connection to MGS (at 192.168.203.156@tcp) was lost; in progress operations using this service will fail [ 1820.841969] Lustre: Evicted from MGS (at 192.168.203.156@tcp) after server handle changed from 0x991b1f37c5176182 to 0x991b1f37c5178c69 [ 1822.464551] Lustre: DEBUG MARKER: oleg356-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1824.091869] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1832.310025] Lustre: DEBUG MARKER: == recovery-small test 24a: fsync error (should return error) ========================================================== 22:46:10 (1763351170) [ 1833.982064] LustreError: lustre-OST0000-osc-ffff947dd12f6800: operation ost_write to node 192.168.203.156@tcp failed: rc = -107 [ 1833.998696] LustreError: lustre-OST0000-osc-ffff947dd12f6800: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 1834.027375] Lustre: 2402:0:(llite_lib.c:4226:ll_dirty_page_discard_warn()) lustre: dirty page discard: 192.168.203.156@tcp:/lustre/fid: [0x240000402:0x8:0x0]// may get corrupted (rc -5) [ 1834.053431] LustreError: 35227:0:(ldlm_resource.c:981:ldlm_resource_complain()) lustre-OST0000-osc-ffff947dd12f6800: namespace resource [0x280000400:0x5:0x0].0x0 (ffff947dd02b0900) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 1840.315909] Lustre: DEBUG MARKER: == recovery-small test 24b: test dirty page discard due to client eviction ========================================================== 22:46:18 (1763351178) [ 1842.258251] LustreError: lustre-OST0000-osc-ffff947dd12f6800: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 1842.276957] Lustre: 2405:0:(llite_lib.c:4226:ll_dirty_page_discard_warn()) lustre: dirty page discard: 192.168.203.156@tcp:/lustre/fid: [0x240000402:0xb:0x0]// may get corrupted (rc -108) [ 1848.759807] Lustre: DEBUG MARKER: == recovery-small test 26a: evict dead exports =========== 22:46:26 (1763351186) [ 1850.741839] Lustre: DEBUG MARKER: SKIP: recovery-small test_26a msg and ost1 are at the same node [ 1852.583469] Lustre: DEBUG MARKER: == recovery-small test 26b: evict dead exports =========== 22:46:30 (1763351190) [ 1854.293642] Lustre: DEBUG MARKER: SKIP: recovery-small test_26b msg and ost1 are at the same node [ 1856.007605] Lustre: DEBUG MARKER: == recovery-small test 27: fail LOV while using OSC's ==== 22:46:33 (1763351193) [ 1880.578538] LustreError: MGC192.168.203.156@tcp: Connection to MGS (at 192.168.203.156@tcp) was lost; in progress operations using this service will fail [ 1880.643418] Lustre: Evicted from MGS (at 192.168.203.156@tcp) after server handle changed from 0x991b1f37c5178c69 to 0x991b1f37c517aa30 [ 1979.896715] LustreError: lustre-MDT0000-mdc-ffff947dd12f6800: operation ldlm_enqueue to node 192.168.203.156@tcp failed: rc = -19 [ 1979.915290] LustreError: Skipped 2 previous similar messages [ 1998.303401] LustreError: MGC192.168.203.156@tcp: Connection to MGS (at 192.168.203.156@tcp) was lost; in progress operations using this service will fail [ 2008.573985] Lustre: Evicted from MGS (at 192.168.203.156@tcp) after server handle changed from 0x991b1f37c517aa30 to 0x991b1f37c51a299f [ 2021.477539] Lustre: DEBUG MARKER: == recovery-small test 28: handle error adding new clients (bug 6086) ========================================================== 22:49:19 (1763351359) [ 2022.179689] Lustre: *** cfs_fail_loc=305, val=0*** [ 2022.181729] Lustre: Skipped 2 previous similar messages [ 2062.825986] LustreError: MGC192.168.203.156@tcp: Connection to MGS (at 192.168.203.156@tcp) was lost; in progress operations using this service will fail [ 2072.112629] Lustre: Evicted from MGS (at 192.168.203.156@tcp) after server handle changed from 0x991b1f37c51a299f to 0x991b1f37c51a3721 [ 2073.434675] Lustre: DEBUG MARKER: oleg356-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2074.866586] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2082.424139] Lustre: DEBUG MARKER: == recovery-small test 29a: error adding new clients doesn't cause LBUG (bug 22273) ========================================================== 22:50:20 (1763351420) [ 2097.638291] LustreError: MGC192.168.203.156@tcp: Connection to MGS (at 192.168.203.156@tcp) was lost; in progress operations using this service will fail [ 2097.660431] Lustre: Evicted from MGS (at 192.168.203.156@tcp) after server handle changed from 0x991b1f37c51a3721 to 0x991b1f37c51a392e [ 2129.734356] Lustre: DEBUG MARKER: == recovery-small test 29b: error adding new clients doesn't cause LBUG (bug 22273) ========================================================== 22:51:07 (1763351467) [ 2133.495298] Lustre: lustre-OST0000-osc-ffff947dd12f6800: Connection to lustre-OST0000 (at 192.168.203.156@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 2133.508662] Lustre: Skipped 13 previous similar messages [ 2143.739934] LustreError: lustre-OST0000-osc-ffff947dd12f6800: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 2143.758162] Lustre: lustre-OST0000-osc-ffff947dd12f6800: Connection restored to 192.168.203.156@tcp (at 192.168.203.156@tcp) [ 2143.762203] Lustre: Skipped 17 previous similar messages [ 2167.204558] Lustre: DEBUG MARKER: == recovery-small test 50: failover MDS under load ======= 22:51:45 (1763351505) [ 2180.129940] LustreError: lustre-MDT0000-mdc-ffff947dd12f6800: operation mds_close to node 192.168.203.156@tcp failed: rc = -19 [ 2180.142274] LustreError: Skipped 2 previous similar messages [ 2200.031349] LustreError: MGC192.168.203.156@tcp: Connection to MGS (at 192.168.203.156@tcp) was lost; in progress operations using this service will fail [ 2200.065868] Lustre: Evicted from MGS (at 192.168.203.156@tcp) after server handle changed from 0x991b1f37c51a392e to 0x991b1f37c51a99d0 [ 2222.191517] Lustre: DEBUG MARKER: oleg356-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2224.304646] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2307.551208] Lustre: 2405:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763351630/real 1763351630] req@ffff947dc5625880 x1849005848366592/t0(0) o400->MGC192.168.203.156@tcp@192.168.203.156@tcp:26/25 lens 224/224 e 0 to 1 dl 1763351646 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2307.567183] Lustre: 2405:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 9 previous similar messages [ 2307.572679] LustreError: MGC192.168.203.156@tcp: Connection to MGS (at 192.168.203.156@tcp) was lost; in progress operations using this service will fail [ 2317.876983] Lustre: Evicted from MGS (at 192.168.203.156@tcp) after server handle changed from 0x991b1f37c51a99d0 to 0x991b1f37c51ce7c8 [ 2320.006298] Lustre: DEBUG MARKER: oleg356-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2322.404802] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2386.601092] LustreError: lustre-MDT0000-mdc-ffff947dd12f6800: operation ldlm_enqueue to node 192.168.203.156@tcp failed: rc = -19 [ 2386.611642] LustreError: Skipped 1 previous similar message [ 2404.851425] LustreError: MGC192.168.203.156@tcp: Connection to MGS (at 192.168.203.156@tcp) was lost; in progress operations using this service will fail [ 2404.910877] Lustre: Evicted from MGS (at 192.168.203.156@tcp) after server handle changed from 0x991b1f37c51ce7c8 to 0x991b1f37c51f00bb [ 2414.371503] Lustre: DEBUG MARKER: oleg356-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2415.989410] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2443.192692] Lustre: DEBUG MARKER: == recovery-small test 51: failover MDS during recovery == 22:56:21 (1763351781) [ 2466.574235] Lustre: DEBUG MARKER: test_51: failover in 1 sec [ 2486.762202] LustreError: MGC192.168.203.156@tcp: Connection to MGS (at 192.168.203.156@tcp) was lost; in progress operations using this service will fail [ 2486.787616] LustreError: Skipped 1 previous similar message [ 2486.809683] Lustre: Evicted from MGS (at 192.168.203.156@tcp) after server handle changed from 0x991b1f37c52008e6 to 0x991b1f37c520139e [ 2486.813655] Lustre: Skipped 1 previous similar message [ 2491.639817] Lustre: DEBUG MARKER: test_51: failover in 5 sec [ 2521.346381] Lustre: DEBUG MARKER: test_51: failover in 10 sec [ 2554.334437] Lustre: DEBUG MARKER: test_51: failover in 20 sec [ 2597.173803] Lustre: DEBUG MARKER: test_51: failover in 25 sec [ 2640.364149] LustreError: MGC192.168.203.156@tcp: Connection to MGS (at 192.168.203.156@tcp) was lost; in progress operations using this service will fail [ 2640.370376] LustreError: Skipped 3 previous similar messages [ 2640.379939] Lustre: Evicted from MGS (at 192.168.203.156@tcp) after server handle changed from 0x991b1f37c52183c6 to 0x991b1f37c52270a0 [ 2640.384642] Lustre: Skipped 3 previous similar messages [ 2646.114296] Lustre: DEBUG MARKER: test_51: failover in 30 sec [ 2677.991906] LustreError: lustre-MDT0000-mdc-ffff947dd12f6800: operation ldlm_enqueue to node 192.168.203.156@tcp failed: rc = -19 [ 2677.997753] LustreError: Skipped 9 previous similar messages [ 2723.988226] Lustre: DEBUG MARKER: == recovery-small test 52: failover OST under load ======= 23:01:02 (1763352062) [ 2735.989135] Lustre: lustre-OST0000-osc-ffff947dd12f6800: Connection to lustre-OST0000 (at 192.168.203.156@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 2735.996582] Lustre: Skipped 10 previous similar messages [ 2752.173516] Lustre: lustre-OST0000-osc-ffff947dd12f6800: Connection restored to 192.168.203.156@tcp (at 192.168.203.156@tcp) [ 2752.180541] Lustre: Skipped 20 previous similar messages [ 2759.205972] Lustre: DEBUG MARKER: oleg356-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 2760.772710] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 3092.071677] Lustre: DEBUG MARKER: oleg356-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 3093.286762] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 3398.451260] LustreError: lustre-OST0000-osc-ffff947dd12f6800: operation ldlm_enqueue to node 192.168.203.156@tcp failed: rc = -107 [ 3398.458743] LustreError: Skipped 3 previous similar messages [ 3398.460607] Lustre: lustre-OST0000-osc-ffff947dd12f6800: Connection to lustre-OST0000 (at 192.168.203.156@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 3398.466445] Lustre: Skipped 1 previous similar message [ 3424.903947] Lustre: DEBUG MARKER: oleg356-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 3426.035094] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 3690.956568] Lustre: DEBUG MARKER: == recovery-small test 53a: touch: drop rep ============== 23:17:09 (1763353029) [ 3707.871156] Lustre: 51787:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763353030/real 1763353030] req@ffff947dc6706d80 x1849005884465024/t0(0) o101->lustre-MDT0000-mdc-ffff947dd12f6800@192.168.203.156@tcp:12/10 lens 576/1152 e 0 to 1 dl 1763353046 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'openfile.0' uid:0 gid:0 projid:0 [ 3707.883408] Lustre: 51787:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 3707.901698] Lustre: lustre-MDT0000-mdc-ffff947dd12f6800: Connection restored to 192.168.203.156@tcp (at 192.168.203.156@tcp) [ 3707.905556] Lustre: Skipped 1 previous similar message [ 3711.408136] Lustre: DEBUG MARKER: == recovery-small test 53b: touch: drop rep ============== 23:17:29 (1763353049) [ 3731.573467] Lustre: DEBUG MARKER: == recovery-small test 53c: touch: drop rep ============== 23:17:50 (1763353070) [ 3751.615932] Lustre: DEBUG MARKER: == recovery-small test 54: back in time ================== 23:18:10 (1763353090) [ 3751.831458] Lustre: Mounted lustre-client [ 3777.506909] LustreError: MGC192.168.203.156@tcp: Connection to MGS (at 192.168.203.156@tcp) was lost; in progress operations using this service will fail [ 3777.512635] LustreError: Skipped 1 previous similar message [ 3777.518616] Lustre: Evicted from MGS (at 192.168.203.156@tcp) after server handle changed from 0x991b1f37c523b34f to 0x991b1f37c5491b25 [ 3777.522723] Lustre: Skipped 1 previous similar message [ 3784.002268] Lustre: DEBUG MARKER: oleg356-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3784.660889] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3786.050789] LustreError: 54577:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff947dc91b4800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 3786.055981] LustreError: 54577:0:(lov_obd.c:783:lov_cleanup()) Skipped 1 previous similar message [ 3786.059787] LustreError: 54577:0:(obd_class.h:479:obd_check_dev()) Device 12 not setup [ 3786.062681] LustreError: 54577:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 3786.094433] Lustre: Unmounted lustre-client [ 3788.549053] Lustre: DEBUG MARKER: == recovery-small test 55: ost_brw_read/write drops timed-out read/write request ========================================================== 23:18:47 (1763353127) [ 3808.223240] Lustre: 2402:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763353131/real 1763353131] req@ffff947dc7fa5500 x1849005884503552/t0(0) o4->lustre-OST0000-osc-ffff947dd12f6800@192.168.203.156@tcp:6/4 lens 488/448 e 0 to 1 dl 1763353147 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'dd.0' uid:0 gid:0 projid:0 [ 3808.241655] Lustre: 2402:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 7 previous similar messages [ 3878.171157] Lustre: DEBUG MARKER: == recovery-small test 56: do not fail on getattr resend ========================================================== 23:20:16 (1763353216) [ 3921.915669] Lustre: DEBUG MARKER: == recovery-small test 57: read procfs entries causes kernel crash ========================================================== 23:21:00 (1763353260) [ 3923.355427] LustreError: 56523:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff947dd12f6800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 3923.361633] LustreError: 56523:0:(lov_obd.c:783:lov_cleanup()) Skipped 1 previous similar message [ 3923.368880] LustreError: 56523:0:(obd_class.h:479:obd_check_dev()) Device 6 not setup [ 3923.372016] LustreError: 56523:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 3923.407131] Lustre: Unmounted lustre-client [ 3940.426045] Lustre: Mounted lustre-client [ 3943.272050] Lustre: DEBUG MARKER: == recovery-small test 58: Eviction in the middle of open RPC reply processing ========================================================== 23:21:21 (1763353281) [ 3943.383520] LustreError: 57631:0:(mdc_locks.c:1335:mdc_finish_intent_lock()) cfs_fail_timeout id 801 sleeping for 20000ms [ 3944.431260] LustreError: 57631:0:(mdc_locks.c:1335:mdc_finish_intent_lock()) cfs_fail_timeout interrupted [ 3944.482452] Lustre: *** cfs_fail_loc=305, val=0*** [ 3963.041389] Lustre: DEBUG MARKER: == recovery-small test 59: Read cancel race on client eviction ========================================================== 23:21:41 (1763353301) [ 3963.210189] Lustre: Mounted lustre-client [ 3963.748530] Lustre: setting import lustre-MDT0000_UUID INACTIVE by administrator request [ 3973.992235] LustreError: 58320:0:(obd_class.h:479:obd_check_dev()) Device 12 not setup [ 3973.994995] LustreError: 58320:0:(obd_class.h:479:obd_check_dev()) Skipped 9 previous similar messages [ 3974.012038] Lustre: Unmounted lustre-client [ 3976.720112] Lustre: DEBUG MARKER: == recovery-small test 60: Add Changelog entries during MDS failover ========================================================== 23:21:55 (1763353315) [ 4011.705030] LustreError: lustre-MDT0000-mdc-ffff947dc5cc7000: operation mds_reint to node 192.168.203.156@tcp failed: rc = -19 [ 4011.708914] Lustre: lustre-MDT0000-mdc-ffff947dc5cc7000: Connection to lustre-MDT0000 (at 192.168.203.156@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 4011.715019] Lustre: Skipped 12 previous similar messages [ 4029.925833] LustreError: MGC192.168.203.156@tcp: Connection to MGS (at 192.168.203.156@tcp) was lost; in progress operations using this service will fail [ 4029.935790] Lustre: Evicted from MGS (at 192.168.203.156@tcp) after server handle changed from 0x991b1f37c549277a to 0x991b1f37c54c026e [ 4083.613152] Lustre: DEBUG MARKER: == recovery-small test 61: Verify to not reuse orphan objects - bug 17025 ========================================================== 23:23:42 (1763353422) [ 4087.109424] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4096.487717] LustreError: MGC192.168.203.156@tcp: Connection to MGS (at 192.168.203.156@tcp) was lost; in progress operations using this service will fail [ 4096.496425] Lustre: Evicted from MGS (at 192.168.203.156@tcp) after server handle changed from 0x991b1f37c54c026e to 0x991b1f37c54f8abe [ 4096.506363] LustreError: lustre-MDT0000-mdc-ffff947dc5cc7000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 4110.102586] Lustre: DEBUG MARKER: == recovery-small test 65: lock enqueue for destroyed export ========================================================== 23:24:08 (1763353448) [ 4110.307606] Lustre: Mounted lustre-client [ 4117.057944] LustreError: lustre-OST0000-osc-ffff947dc5cc7000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 4127.711781] Lustre: 2402:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763353450/real 1763353450] req@ffff947ddb288000 x1849005888775296/t0(0) o103->lustre-OST0000-osc-ffff947dd12f3000@192.168.203.156@tcp:17/18 lens 328/224 e 0 to 1 dl 1763353466 ref 1 fl Rpc:XQr/200/ffffffff rc 0/-1 job:'ldlm_bl.0' uid:0 gid:0 projid:4294967295 [ 4127.726651] Lustre: 2402:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 35 previous similar messages [ 4128.273210] LustreError: 61657:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff947dd12f3000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 4128.280169] LustreError: 61657:0:(lov_obd.c:783:lov_cleanup()) Skipped 1 previous similar message [ 4128.290065] LustreError: 61657:0:(obd_class.h:479:obd_check_dev()) Device 12 not setup [ 4128.292365] LustreError: 61657:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 4128.329196] Lustre: Unmounted lustre-client [ 4131.425804] Lustre: DEBUG MARKER: == recovery-small test 66: lock enqueue re-send vs client eviction ========================================================== 23:24:29 (1763353469) [ 4136.591816] LustreError: lustre-MDT0000-mdc-ffff947dc5cc7000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 4136.598440] LustreError: 62307:0:(file.c:6099:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -5 [ 4139.849984] Lustre: DEBUG MARKER: == recovery-small test 67: connect vs import invalidate race ========================================================== 23:24:38 (1763353478) [ 4139.913194] LustreError: 63014:0:(recover.c:330:ptlrpc_recover_import()) cfs_race id 531 sleeping [ 4144.482261] LustreError: lustre-MDT0000-mdc-ffff947dc5cc7000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 4144.488113] LustreError: 63035:0:(import.c:291:ptlrpc_invalidate_import()) cfs_fail_race id 531 waking [ 4144.491371] LustreError: 63014:0:(recover.c:330:ptlrpc_recover_import()) cfs_fail_race id 531 awake: rc=425 [ 4144.495297] LustreError: 63014:0:(import.c:716:ptlrpc_connect_import_locked()) already connecting [ 4144.513813] LustreError: 63040:0:(file.c:6099:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 4145.559930] LustreError: 63046:0:(file.c:6099:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 4145.564595] LustreError: 63046:0:(file.c:6099:ll_inode_revalidate_fini()) Skipped 5 previous similar messages [ 4147.680397] LustreError: 63068:0:(file.c:6099:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 4147.684206] LustreError: 63068:0:(file.c:6099:ll_inode_revalidate_fini()) Skipped 13 previous similar messages [ 4151.934877] LustreError: 63113:0:(file.c:6099:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 4151.939138] LustreError: 63113:0:(file.c:6099:ll_inode_revalidate_fini()) Skipped 27 previous similar messages [ 4158.114671] Lustre: DEBUG MARKER: == recovery-small test 100: IR: Make sure normal recovery still works w/o IR ========================================================== 23:24:56 (1763353496) [ 4180.990797] Lustre: DEBUG MARKER: oleg356-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 4181.867985] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4187.959390] Lustre: DEBUG MARKER: == recovery-small test 101a: IR: Make sure IR works w/o normal recovery ========================================================== 23:25:26 (1763353526) [ 4213.813334] Lustre: DEBUG MARKER: oleg356-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 4214.675372] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4219.837539] Lustre: DEBUG MARKER: == recovery-small test 101b: IR: Make sure IR works w/o normal recovery and proceed EAGAIN ========================================================== 23:25:58 (1763353558) [ 4266.506353] Lustre: DEBUG MARKER: oleg356-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 4267.129964] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4270.763575] Lustre: DEBUG MARKER: == recovery-small test 102: IR: New client gets updated nidtbl after MGS restart ========================================================== 23:26:49 (1763353609) [ 4291.588114] Lustre: DEBUG MARKER: oleg356-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 4292.247077] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4294.657373] LustreError: 68742:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff947dc5cc7000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 4294.662145] LustreError: 68742:0:(lov_obd.c:783:lov_cleanup()) Skipped 1 previous similar message [ 4294.669844] LustreError: 68742:0:(obd_class.h:479:obd_check_dev()) Device 6 not setup [ 4294.672536] LustreError: 68742:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 4294.706223] Lustre: Unmounted lustre-client [ 4321.578066] Lustre: DEBUG MARKER: oleg356-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 4323.154889] Lustre: Mounted lustre-client [ 4325.731235] Lustre: DEBUG MARKER: == recovery-small test 103: IR: MDS can start w/o MGS and get updated nidtbl later ========================================================== 23:27:44 (1763353664) [ 4326.919188] Lustre: DEBUG MARKER: SKIP: recovery-small test_103 needs separate mgs and mds [ 4327.668757] Lustre: DEBUG MARKER: == recovery-small test 104: IR: ost can disable IR voluntarily ========================================================== 23:27:46 (1763353666) [ 4334.523610] Lustre: lustre-OST0000-osc-ffff947dc9189800: Connection restored to 192.168.203.156@tcp (at 192.168.203.156@tcp) [ 4334.527449] Lustre: Skipped 24 previous similar messages [ 4340.045077] Lustre: DEBUG MARKER: == recovery-small test 105: IR: NON IR clients support === 23:27:58 (1763353678) [ 4340.626640] Lustre: DEBUG MARKER: SKIP: recovery-small test_105 Needs multiple clients [ 4341.257612] Lustre: DEBUG MARKER: == recovery-small test 106: lightweight connection support ========================================================== 23:27:59 (1763353679) [ 4341.799778] Lustre: *** cfs_fail_loc=805, val=0*** [ 4341.817533] Lustre: Mounted lustre-client [ 4345.418475] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4362.210223] LustreError: MGC192.168.203.156@tcp: Connection to MGS (at 192.168.203.156@tcp) was lost; in progress operations using this service will fail [ 4362.220842] Lustre: Evicted from MGS (at 192.168.203.156@tcp) after server handle changed from 0x991b1f37c54f963a to 0x991b1f37c54f9997 [ 4366.409344] LustreError: 72180:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff947dc51bb800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 4366.415070] LustreError: 72180:0:(lov_obd.c:783:lov_cleanup()) Skipped 1 previous similar message [ 4366.420576] LustreError: 72180:0:(obd_class.h:479:obd_check_dev()) Device 12 not setup [ 4366.424292] LustreError: 72180:0:(obd_class.h:479:obd_check_dev()) Skipped 9 previous similar messages [ 4366.446242] Lustre: Unmounted lustre-client [ 4369.294634] Lustre: DEBUG MARKER: == recovery-small test 107: drop reint reply, then restart MDT ========================================================== 23:28:27 (1763353707) [ 4387.825390] LustreError: 2401:0:(client.c:3418:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff947dc62df480 x1849005888854144/t94489280515(94489280515) o101->lustre-MDT0000-mdc-ffff947dc9189800@192.168.203.156@tcp:12/10 lens 536/664 e 0 to 0 dl 1763353786 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'multiop.0' uid:0 gid:0 projid:0 [ 4390.907357] Lustre: DEBUG MARKER: oleg356-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4391.583080] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4395.332457] Lustre: DEBUG MARKER: == recovery-small test 108: client eviction don't crash == 23:28:53 (1763353733) [ 4398.053259] LustreError: 2401:0:(osc_request.c:1010:osc_init_grant()) lustre-OST0000-osc-ffff947dc9189800: granted 8437760 but already consumed 12582912 [ 4398.057083] LustreError: lustre-OST0000-osc-ffff947dc9189800: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 4398.061025] Lustre: 2403:0:(llite_lib.c:4226:ll_dirty_page_discard_warn()) lustre: dirty page discard: 192.168.203.156@tcp:/lustre/fid: [0x20000a042:0x6:0x0]// may get corrupted (rc -5) [ 4398.146556] LustreError: 74195:0:(ldlm_resource.c:981:ldlm_resource_complain()) lustre-OST0000-osc-ffff947dc9189800: namespace resource [0x280000401:0x1d22:0x0].0x0 (ffff947dc6857700) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 4401.613560] Lustre: DEBUG MARKER: == recovery-small test 110a: create remote directory: drop client req ========================================================== 23:29:00 (1763353740) [ 4462.559146] Lustre: 74857:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763353741/real 1763353741] req@ffff947dc62ddf80 x1849005888866176/t0(0) o101->lustre-MDT0000-mdc-ffff947dc9189800@192.168.203.156@tcp:12/10 lens 576/1152 e 0 to 1 dl 1763353801 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'lfs.0' uid:0 gid:0 projid:0 [ 4465.798519] Lustre: DEBUG MARKER: == recovery-small test 110b: create remote directory: drop Master rep ========================================================== 23:30:04 (1763353804) [ 4528.921730] Lustre: DEBUG MARKER: == recovery-small test 110c: create remote directory: drop update rep on slave MDT ========================================================== 23:31:07 (1763353867) [ 4548.584618] Lustre: DEBUG MARKER: == recovery-small test 110d: remove remote directory: drop client req ========================================================== 23:31:27 (1763353887) [ 4611.743611] Lustre: DEBUG MARKER: == recovery-small test 110e: remove remote directory: drop master rep ========================================================== 23:32:30 (1763353950) [ 4672.479226] Lustre: lustre-MDT0001-mdc-ffff947dc9189800: Connection to lustre-MDT0001 (at 192.168.203.156@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 4672.485841] Lustre: Skipped 19 previous similar messages [ 4675.458202] Lustre: DEBUG MARKER: == recovery-small test 110f: remove remote directory: drop slave rep ========================================================== 23:33:33 (1763354013) [ 4694.697402] Lustre: DEBUG MARKER: == recovery-small test 110g: drop reply during migration ========================================================== 23:33:53 (1763354033) [ 4757.925672] Lustre: DEBUG MARKER: == recovery-small test 110h: drop update reply during cross-MDT file rename ========================================================== 23:34:56 (1763354096) [ 4777.268949] Lustre: DEBUG MARKER: == recovery-small test 110i: drop update reply during cross-MDT dir rename ========================================================== 23:35:15 (1763354115) [ 4795.718623] Lustre: DEBUG MARKER: == recovery-small test 110j: drop update reply during cross-MDT ln ========================================================== 23:35:34 (1763354134) [ 4815.209553] Lustre: DEBUG MARKER: == recovery-small test 110k: FID_QUERY failed during recovery ========================================================== 23:35:53 (1763354153) [ 4815.259799] LustreError: 80916:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff947dc9189800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 4815.264951] LustreError: 80916:0:(lov_obd.c:783:lov_cleanup()) Skipped 1 previous similar message [ 4815.274474] LustreError: 80916:0:(obd_class.h:479:obd_check_dev()) Device 6 not setup [ 4815.277692] LustreError: 80916:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 4815.316131] Lustre: Unmounted lustre-client [ 4829.780187] Lustre: Mounted lustre-client [ 4839.322610] Lustre: DEBUG MARKER: == recovery-small test 110m: update resent vs original RPC race ========================================================== 23:36:17 (1763354177) [ 4850.391125] Lustre: DEBUG MARKER: == recovery-small test 111: mdd setup fail should not cause umount oops ========================================================== 23:36:29 (1763354189) [ 4860.386207] LustreError: MGC192.168.203.156@tcp: Connection to MGS (at 192.168.203.156@tcp) was lost; in progress operations using this service will fail [ 4860.390101] LustreError: Skipped 1 previous similar message [ 4860.393511] Lustre: Evicted from MGS (at 192.168.203.156@tcp) after server handle changed from 0x991b1f37c54fc08e to 0x991b1f37c54fc5ce [ 4860.398012] Lustre: Skipped 1 previous similar message [ 4860.974490] Lustre: DEBUG MARKER: == recovery-small test 112a: bulk resend while orignal request is in progress ========================================================== 23:36:39 (1763354199) [ 4884.810198] Lustre: DEBUG MARKER: == recovery-small test 115a: read: late REQ MDunlink and no bulk ========================================================== 23:37:03 (1763354223) [ 4884.900415] Lustre: *** cfs_fail_loc=51b, val=3*** [ 4890.844837] Lustre: DEBUG MARKER: == recovery-small test 115b: write: late REQ MDunlink and no bulk ========================================================== 23:37:09 (1763354229) [ 4890.923341] Lustre: *** cfs_fail_loc=51b, val=4*** [ 4896.892249] Lustre: DEBUG MARKER: == recovery-small test 115c: read: late Reply MDunlink and no bulk ========================================================== 23:37:15 (1763354235) [ 4896.968101] Lustre: *** cfs_fail_loc=50f, val=3*** [ 4900.316751] Lustre: DEBUG MARKER: == recovery-small test 115d: write: late Reply MDunlink and no bulk ========================================================== 23:37:18 (1763354238) [ 4900.377589] Lustre: *** cfs_fail_loc=50f, val=4*** [ 4903.776201] Lustre: DEBUG MARKER: == recovery-small test 115e: read: late Bulk MDunlink and no reply ========================================================== 23:37:22 (1763354242) [ 4903.863635] Lustre: *** cfs_fail_loc=510, val=3*** [ 4907.231196] Lustre: DEBUG MARKER: == recovery-small test 115f: read: late REQ MDunlink and no reply ========================================================== 23:37:25 (1763354245) [ 4907.320214] Lustre: *** cfs_fail_loc=51b, val=3*** [ 4913.377799] Lustre: DEBUG MARKER: == recovery-small test 115g: read: late REQ MDunlink and Reply MDunlink ========================================================== 23:37:31 (1763354251) [ 4974.240451] Lustre: DEBUG MARKER: == recovery-small test 120: flock race: completion vs. evict ========================================================== 23:38:32 (1763354312) [ 4974.320311] LustreError: 88978:0:(ldlm_flock.c:802:ldlm_flock_completion_ast()) cfs_fail_timeout id 320 sleeping for 4000ms [ 4976.622346] LustreError: lustre-MDT0000-mdc-ffff947dc51bb800: operation ldlm_enqueue to node 192.168.203.156@tcp failed: rc = -107 [ 4976.625138] LustreError: Skipped 3 previous similar messages [ 4976.629142] LustreError: lustre-MDT0000-mdc-ffff947dc51bb800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 4976.635529] LustreError: 88992:0:(file.c:249:ll_close_inode_openhandle()) lustre-clilmv-ffff947dc51bb800: inode [0x20000afe2:0x3:0x0] mdc close failed: rc = -108 [ 4976.644519] LustreError: 88992:0:(ldlm_resource.c:981:ldlm_resource_complain()) lustre-MDT0000-mdc-ffff947dc51bb800: namespace resource [0x20000afe2:0xc:0x0].0xc (ffff947dda3c4d00) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 4976.651306] LustreError: 88997:0:(file.c:6099:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 4976.652544] LustreError: 88992:0:(ldlm_resource.c:981:ldlm_resource_complain()) Skipped 1 previous similar message [ 4976.656170] LustreError: 88997:0:(file.c:6099:ll_inode_revalidate_fini()) Skipped 20 previous similar messages [ 4976.664609] Lustre: lustre-MDT0000-mdc-ffff947dc51bb800: Connection restored to 192.168.203.156@tcp (at 192.168.203.156@tcp) [ 4976.668671] Lustre: Skipped 12 previous similar messages [ 4978.375122] LustreError: 88978:0:(ldlm_flock.c:802:ldlm_flock_completion_ast()) cfs_fail_timeout id 320 awake [ 4980.408878] LustreError: 89019:0:(ldlm_flock.c:802:ldlm_flock_completion_ast()) cfs_fail_timeout id 320 sleeping for 4000ms [ 4982.701872] LustreError: lustre-MDT0000-mdc-ffff947dc51bb800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 4982.709163] LustreError: 89033:0:(ldlm_resource.c:981:ldlm_resource_complain()) lustre-MDT0000-mdc-ffff947dc51bb800: namespace resource [0x20000afe2:0xc:0x0].0xc (ffff947dd19e4300) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 4982.715172] LustreError: 89033:0:(ldlm_resource.c:981:ldlm_resource_complain()) Skipped 1 previous similar message [ 4984.471095] LustreError: 89019:0:(ldlm_flock.c:802:ldlm_flock_completion_ast()) cfs_fail_timeout id 320 awake [ 4990.707654] LustreError: lustre-MDT0000-mdc-ffff947dc51bb800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 4990.815074] LustreError: 89075:0:(ldlm_flock.c:807:ldlm_flock_completion_ast()) cfs_fail_timeout id 321 sleeping for 4000ms [ 4993.091266] LustreError: lustre-MDT0000-mdc-ffff947dc51bb800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 4993.110981] LustreError: 89094:0:(file.c:6099:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 4993.114981] LustreError: 89094:0:(file.c:6099:ll_inode_revalidate_fini()) Skipped 1 previous similar message [ 4994.871099] LustreError: 89075:0:(ldlm_flock.c:807:ldlm_flock_completion_ast()) cfs_fail_timeout id 321 awake [ 4994.873512] LustreError: 89075:0:(file.c:249:ll_close_inode_openhandle()) lustre-clilmv-ffff947dc51bb800: inode [0x20000afe2:0xc:0x0] mdc close failed: rc = -108 [ 4994.876554] LustreError: 89075:0:(file.c:249:ll_close_inode_openhandle()) Skipped 4 previous similar messages [ 4995.190312] LustreError: 89111:0:(file.c:6099:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 4995.194828] LustreError: 89111:0:(file.c:6099:ll_inode_revalidate_fini()) Skipped 12 previous similar messages [ 4999.403175] LustreError: 89149:0:(ldlm_flock.c:807:ldlm_flock_completion_ast()) cfs_fail_timeout id 321 sleeping for 4000ms [ 5001.694479] LustreError: lustre-MDT0000-mdc-ffff947dc51bb800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5001.701501] LustreError: 89163:0:(ldlm_resource.c:981:ldlm_resource_complain()) lustre-MDT0000-mdc-ffff947dc51bb800: namespace resource [0x20000afe2:0xc:0x0].0xc (ffff947dc5c07400) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 5001.707695] LustreError: 89163:0:(ldlm_resource.c:981:ldlm_resource_complain()) Skipped 1 previous similar message [ 5003.463113] LustreError: 89149:0:(ldlm_flock.c:807:ldlm_flock_completion_ast()) cfs_fail_timeout id 321 awake [ 5009.719340] LustreError: lustre-MDT0000-mdc-ffff947dc51bb800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5009.828254] LustreError: 89204:0:(ldlm_flock.c:856:ldlm_flock_completion_ast()) cfs_fail_timeout id 322 sleeping for 4000ms [ 5012.124266] LustreError: lustre-MDT0000-mdc-ffff947dc51bb800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5012.128752] LustreError: 89219:0:(ldlm_resource.c:981:ldlm_resource_complain()) lustre-MDT0000-mdc-ffff947dc51bb800: namespace resource [0x20000afe2:0xc:0x0].0xc (ffff947dda3c4500) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 5012.135868] LustreError: 89219:0:(ldlm_resource.c:981:ldlm_resource_complain()) Skipped 1 previous similar message [ 5013.887122] LustreError: 89204:0:(ldlm_flock.c:856:ldlm_flock_completion_ast()) cfs_fail_timeout id 322 awake [ 5016.212465] LustreError: lustre-MDT0000-mdc-ffff947dc51bb800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5016.234094] LustreError: 89251:0:(file.c:6099:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 5016.238191] LustreError: 89251:0:(file.c:6099:ll_inode_revalidate_fini()) Skipped 13 previous similar messages [ 5017.967494] LustreError: 89232:0:(file.c:249:ll_close_inode_openhandle()) lustre-clilmv-ffff947dc51bb800: inode [0x20000afe2:0xc:0x0] mdc close failed: rc = -108 [ 5024.500598] LustreError: 89303:0:(ldlm_flock.c:802:ldlm_flock_completion_ast()) cfs_fail_timeout id 320 sleeping for 4000ms [ 5024.504548] LustreError: 89303:0:(ldlm_flock.c:802:ldlm_flock_completion_ast()) Skipped 1 previous similar message [ 5027.031042] LustreError: lustre-MDT0000-mdc-ffff947dc51bb800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5027.052986] LustreError: 89325:0:(file.c:6099:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 5027.056458] LustreError: 89325:0:(file.c:6099:ll_inode_revalidate_fini()) Skipped 26 previous similar messages [ 5028.567071] LustreError: 89303:0:(ldlm_flock.c:802:ldlm_flock_completion_ast()) cfs_fail_timeout id 320 awake [ 5028.569873] LustreError: 89303:0:(ldlm_flock.c:802:ldlm_flock_completion_ast()) Skipped 1 previous similar message [ 5028.572405] LustreError: 89303:0:(file.c:249:ll_close_inode_openhandle()) lustre-clilmv-ffff947dc51bb800: inode [0x20000afe2:0xc:0x0] mdc close failed: rc = -108 [ 5033.336692] Lustre: DEBUG MARKER: == recovery-small test 113: ldlm enqueue dropped reply should not cause deadlocks ========================================================== 23:39:31 (1763354371) [ 5093.343227] Lustre: 90021:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763354372/real 1763354372] req@ffff947dc68a0380 x1849005889074688/t0(0) o101->lustre-MDT0000-mdc-ffff947dc51bb800@192.168.203.156@tcp:12/10 lens 576/1152 e 0 to 1 dl 1763354432 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'stat.0' uid:0 gid:0 projid:0 [ 5093.353133] Lustre: 90021:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 5 previous similar messages [ 5093.956238] LustreError: 84386:0:(ldlm_lockd.c:2882:ldlm_bl_thread_blwi()) cfs_fail_timeout id 31f sleeping for 4000ms [ 5093.959331] LustreError: 84386:0:(ldlm_lockd.c:2882:ldlm_bl_thread_blwi()) Skipped 1 previous similar message [ 5098.015146] LustreError: 84386:0:(ldlm_lockd.c:2882:ldlm_bl_thread_blwi()) cfs_fail_timeout id 31f awake [ 5098.017983] LustreError: 84386:0:(ldlm_lockd.c:2882:ldlm_bl_thread_blwi()) Skipped 1 previous similar message [ 5100.207861] Lustre: DEBUG MARKER: == recovery-small test 130a: enqueue resend on not existing file ========================================================== 23:40:38 (1763354438) [ 5163.097778] Lustre: DEBUG MARKER: == recovery-small test 130b: enqueue resend on a stale inode ========================================================== 23:41:41 (1763354501) [ 5225.655970] Lustre: DEBUG MARKER: == recovery-small test 130c: layout intent resend on a stale inode ========================================================== 23:42:44 (1763354564) [ 5251.542914] Lustre: DEBUG MARKER: == recovery-small test 132: long punch =================== 23:43:10 (1763354590) [ 5251.673258] Lustre: Mounted lustre-client [ 5372.390447] LustreError: 93088:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff947dc8fe7800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 5372.397375] LustreError: 93088:0:(lov_obd.c:783:lov_cleanup()) Skipped 1 previous similar message [ 5372.401337] LustreError: 93088:0:(obd_class.h:479:obd_check_dev()) Device 12 not setup [ 5372.405741] LustreError: 93088:0:(obd_class.h:479:obd_check_dev()) Skipped 9 previous similar messages [ 5372.432137] Lustre: Unmounted lustre-client [ 5374.724178] Lustre: DEBUG MARKER: == recovery-small test 131: IO vs evict results to IO under staled lock ========================================================== 23:45:13 (1763354713) [ 5374.902853] LustreError: 93711:0:(osc_request.c:2944:osc_build_rpc()) cfs_fail_timeout id 414 sleeping for 4000ms [ 5376.668585] Lustre: lustre-OST0000-osc-ffff947dc51bb800: Connection to lustre-OST0000 (at 192.168.203.156@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 5376.675165] Lustre: Skipped 15 previous similar messages [ 5376.678852] LustreError: lustre-OST0000-osc-ffff947dc51bb800: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 5376.683494] LustreError: 93798:0:(ldlm_resource.c:981:ldlm_resource_complain()) lustre-OST0000-osc-ffff947dc51bb800: namespace resource [0x280000401:0x1d4d:0x0].0x0 (ffff947dc6827500) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 5376.689517] LustreError: 93798:0:(ldlm_resource.c:981:ldlm_resource_complain()) Skipped 1 previous similar message [ 5378.967161] LustreError: 93711:0:(osc_request.c:2944:osc_build_rpc()) cfs_fail_timeout id 414 awake [ 5378.970917] Lustre: 2403:0:(llite_lib.c:4226:ll_dirty_page_discard_warn()) lustre: dirty page discard: 192.168.203.156@tcp:/lustre/fid: [0x20000bf89:0x9:0x0]// may get corrupted (rc -108) [ 5381.098575] Lustre: DEBUG MARKER: == recovery-small test 133: don't fail on flock resend === 23:45:19 (1763354719) [ 5423.540645] Lustre: DEBUG MARKER: == recovery-small test 134: race between failover and search for reply data free slot ========================================================== 23:46:02 (1763354762) [ 5424.040521] Lustre: DEBUG MARKER: SKIP: recovery-small test_134 Need 2+ clients, have 1 [ 5424.618851] Lustre: DEBUG MARKER: == recovery-small test 135: DOM: open/create resend to return size ========================================================== 23:46:03 (1763354763) [ 5450.070604] Lustre: DEBUG MARKER: SKIP: recovery-small test_136 skipping excluded test 136 [ 5450.691478] Lustre: DEBUG MARKER: == recovery-small test 137: late resend must be skipped if already applied ========================================================== 23:46:29 (1763354789) [ 5474.331895] Lustre: DEBUG MARKER: == recovery-small test 138: Umount MDT during recovery === 23:46:52 (1763354812) [ 5474.755750] LustreError: 96759:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff947dc51bb800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 5474.760637] LustreError: 96759:0:(lov_obd.c:783:lov_cleanup()) Skipped 1 previous similar message [ 5577.717328] Lustre: Mounted lustre-client [ 5579.960604] Lustre: DEBUG MARKER: == recovery-small test 139: corrupted catid won't cause crash ========================================================== 23:48:38 (1763354918) [ 5587.938665] LustreError: MGC192.168.203.156@tcp: Connection to MGS (at 192.168.203.156@tcp) was lost; in progress operations using this service will fail [ 5587.949785] Lustre: Evicted from MGS (at 192.168.203.156@tcp) after server handle changed from 0x991b1f37c54fe149 to 0x991b1f37c54fe49f [ 5587.954475] Lustre: MGC192.168.203.156@tcp: Connection restored to 192.168.203.156@tcp (at 192.168.203.156@tcp) [ 5587.957695] Lustre: Skipped 15 previous similar messages [ 5588.323422] Lustre: DEBUG MARKER: == recovery-small test 140a: local mount is flagged properly ========================================================== 23:48:46 (1763354926) [ 5598.718357] Lustre: DEBUG MARKER: == recovery-small test 140b: local mount is excluded from recovery ========================================================== 23:48:57 (1763354937) [ 5603.587554] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5626.885404] Lustre: DEBUG MARKER: oleg356-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 5627.504905] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5631.714986] Lustre: DEBUG MARKER: == recovery-small test 141: do not lose locks on MGS restart ========================================================== 23:49:30 (1763354970) [ 5632.530277] Lustre: DEBUG MARKER: SKIP: recovery-small test_141 cannot run in local mode or from build tree [ 5633.097098] Lustre: DEBUG MARKER: == recovery-small test 142: orphan name stub can be cleaned up in startup ========================================================== 23:49:31 (1763354971) [ 5641.512561] Lustre: DEBUG MARKER: == recovery-small test 143: orphan cleanup thread shouldn't be blocked even delete failed ========================================================== 23:49:40 (1763354980) [ 5667.831288] Lustre: DEBUG MARKER: == recovery-small test 144a: MDT failover should stop precreation threads ========================================================== 23:50:06 (1763355006) [ 5669.956805] LustreError: lustre-OST0000-osc-ffff947dc62bb800: operation ost_setattr to node 192.168.203.156@tcp failed: rc = -107 [ 5669.960690] LustreError: Skipped 10 previous similar messages [ 5690.192894] Lustre: DEBUG MARKER: oleg356-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 5691.449053] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 5771.999202] Lustre: 2403:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763355095/real 1763355095] req@ffff947dc7732d80 x1849005895663744/t0(0) o400->MGC192.168.203.156@tcp@192.168.203.156@tcp:26/25 lens 224/224 e 0 to 1 dl 1763355111 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5772.008963] Lustre: 2403:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 6 previous similar messages [ 5774.284230] Lustre: DEBUG MARKER: oleg356-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 5774.895813] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5796.833345] Lustre: DEBUG MARKER: oleg356-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 5797.436492] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5866.551908] Lustre: DEBUG MARKER: == recovery-small test 144b: orphan cleanup shouldn't be blocked for no objects+failover situation ========================================================== 23:53:25 (1763355205) [ 5904.643754] Lustre: DEBUG MARKER: oleg356-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 5906.105849] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 6027.678579] Lustre: DEBUG MARKER: == recovery-small test 144c: reconnection during orphan cleanup shouldn't lose LAST_ID synchronization ========================================================== 23:56:06 (1763355366) [ 6053.346435] Lustre: lustre-MDT0000-mdc-ffff947dc62bb800: Connection to lustre-MDT0000 (at 192.168.203.156@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 6053.353995] Lustre: Skipped 9 previous similar messages [ 6079.173840] Lustre: DEBUG MARKER: == recovery-small test 145: connect mdtlovs and process update logs after recovery expire ========================================================== 23:56:57 (1763355417) [ 6079.715353] Lustre: DEBUG MARKER: SKIP: recovery-small test_145 needs >= 3 MDTs [ 6080.272571] Lustre: DEBUG MARKER: == recovery-small test 146: test eviction is counted properly ========================================================== 23:56:58 (1763355418) [ 6080.965692] LustreError: lustre-MDT0000-mdc-ffff947dc62bb800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 6083.452235] Lustre: DEBUG MARKER: == recovery-small test 147: Check client reconnect ======= 23:57:02 (1763355422) [ 6249.506774] Lustre: Evicted from lustre-OST0000_UUID (at 192.168.203.156@tcp) after server handle changed from 0x991b1f37c55faa5d to 0x991b1f37c55fab60 [ 6249.511338] Lustre: Skipped 6 previous similar messages [ 6249.513026] LustreError: lustre-OST0000-osc-ffff947dc62bb800: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 6250.124126] Lustre: DEBUG MARKER: == recovery-small test 148: data corruption through resend ========================================================== 23:59:48 (1763355588) [ 6272.996332] Lustre: lustre-OST0000-osc-ffff947dc62bb800: Connection restored to 192.168.203.156@tcp (at 192.168.203.156@tcp) [ 6273.000573] Lustre: Skipped 13 previous similar messages [ 6284.694827] Lustre: DEBUG MARKER: == recovery-small test 149: skip orphan removal at umount ========================================================== 00:00:23 (1763355623) [ 6303.713701] LustreError: MGC192.168.203.156@tcp: Connection to MGS (at 192.168.203.156@tcp) was lost; in progress operations using this service will fail [ 6303.719462] LustreError: Skipped 6 previous similar messages [ 6308.593470] LustreError: lustre-MDT0001-mdc-ffff947dc62bb800: This client was evicted by lustre-MDT0001; in progress operations using this service will fail. [ 6313.954880] LustreError: lustre-MDT0000-mdc-ffff947dc62bb800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 6313.959684] LustreError: 111448:0:(file.c:249:ll_close_inode_openhandle()) lustre-clilmv-ffff947dc62bb800: inode [0x2000105d1:0x6:0x0] mdc close failed: rc = -5 [ 6317.477468] Lustre: DEBUG MARKER: == recovery-small test 150: statfs when MDT0 offline with lazystatfs option ========================================================== 00:00:56 (1763355656) [ 6318.998324] LustreError: lustre-MDT0000-mdc-ffff947dc62bb800: operation mds_statfs to node 192.168.203.156@tcp failed: rc = -107 [ 6319.000954] LustreError: Skipped 6 previous similar messages [ 6319.002511] LustreError: 112573:0:(lmv_obd.c:1435:lmv_statfs()) lustre-MDT0000-mdc-ffff947dc62bb800: can't stat MDS #0: rc = -107 [ 6328.329318] Lustre: DEBUG MARKER: == recovery-small test 152: QoS object allocation could be awakened in case of OST failover ========================================================== 00:01:06 (1763355666) [ 6353.929856] Lustre: DEBUG MARKER: == recovery-small test 153: evict vs reconnect race ====== 00:01:32 (1763355692) [ 6391.684052] Lustre: DEBUG MARKER: == recovery-small test 154a: corruption update llog can be skipped ========================================================== 00:02:10 (1763355730) [ 6414.215317] Lustre: DEBUG MARKER: == recovery-small test 154b: restore update llog after failed recovery ========================================================== 00:02:32 (1763355752) [ 6425.572108] LustreError: lustre-MDT0000-mdc-ffff947dc62bb800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 6426.742479] Lustre: Mounted lustre-client [ 6427.074206] LustreError: 116475:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff947dc34bb000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 6427.079732] LustreError: 116475:0:(lov_obd.c:783:lov_cleanup()) Skipped 1 previous similar message [ 6427.085831] LustreError: 116475:0:(obd_class.h:479:obd_check_dev()) Device 12 not setup [ 6427.087721] LustreError: 116475:0:(obd_class.h:479:obd_check_dev()) Skipped 17 previous similar messages [ 6427.110510] Lustre: Unmounted lustre-client [ 6427.111813] Lustre: Skipped 1 previous similar message [ 6432.075821] Lustre: DEBUG MARKER: == recovery-small test 155: failover after client remount ========================================================== 00:02:50 (1763355770) [ 6435.483513] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 6461.397401] Lustre: DEBUG MARKER: == recovery-small test 156: tot_granted miscount after client eviction ========================================================== 00:03:19 (1763355799) [ 6464.957253] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-OST0000 [ 6480.354961] LustreError: 2401:0:(client.c:3503:ptlrpc_replay_req()) cfs_fail_timeout id 536 sleeping for 45000ms [ 6525.391137] LustreError: 2401:0:(client.c:3503:ptlrpc_replay_req()) cfs_fail_timeout id 536 awake [ 6525.398155] LustreError: lustre-OST0000-osc-ffff947dc6293800: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 6526.733805] Lustre: DEBUG MARKER: oleg356-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 6527.318450] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 6531.841704] Lustre: DEBUG MARKER: == recovery-small test 157: eviction during mmaped i/o === 00:04:30 (1763355870) [ 6531.979023] LustreError: 119698:0:(vvp_io.c:1501:vvp_io_fault_start()) cfs_fail_timeout id 1432 sleeping for 3000ms [ 6533.605650] LustreError: lustre-OST0000-osc-ffff947dc6293800: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 6533.610491] LustreError: 119712:0:(ldlm_resource.c:981:ldlm_resource_complain()) lustre-OST0000-osc-ffff947dc6293800: namespace resource [0x280000402:0x663:0x0].0x0 (ffff947dd95bb200) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 6533.615457] LustreError: 119712:0:(ldlm_resource.c:981:ldlm_resource_complain()) Skipped 1 previous similar message [ 6534.999189] LustreError: 119698:0:(vvp_io.c:1501:vvp_io_fault_start()) cfs_fail_timeout id 1432 awake [ 6537.186812] Lustre: DEBUG MARKER: == recovery-small test 158a: connect without access right ========================================================== 00:04:35 (1763355875) [ 6537.504987] LustreError: 120316:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff947dc6293800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 6537.511852] LustreError: 120316:0:(lov_obd.c:783:lov_cleanup()) Skipped 5 previous similar messages [ 6537.519240] LustreError: 120316:0:(obd_class.h:479:obd_check_dev()) Device 6 not setup [ 6537.521474] LustreError: 120316:0:(obd_class.h:479:obd_check_dev()) Skipped 27 previous similar messages [ 6537.564114] Lustre: Unmounted lustre-client [ 6537.565079] Lustre: Skipped 2 previous similar messages [ 6552.942970] Lustre: lustre-MDT0001-mdc-ffff947dd00c5000: connection denied by lustre-MDT0001_UUID: rc = -13 [ 6552.946941] LustreError: lustre-MDT0001-mdc-ffff947dd00c5000: This client was evicted by lustre-MDT0001; in progress operations using this service will fail. [ 6570.060517] LustreError: lustre-MDT0001-mdc-ffff947dd00c5000: This client was evicted by lustre-MDT0001; in progress operations using this service will fail. [ 6572.282712] LustreError: 121154:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff947dd00c5000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 6572.287729] LustreError: 121154:0:(lov_obd.c:783:lov_cleanup()) Skipped 1 previous similar message [ 6572.293861] LustreError: 121154:0:(obd_class.h:479:obd_check_dev()) Device 6 not setup [ 6572.296788] LustreError: 121154:0:(obd_class.h:479:obd_check_dev()) Skipped 9 previous similar messages [ 6572.324561] Lustre: Unmounted lustre-client [ 6574.468053] Lustre: DEBUG MARKER: == recovery-small test 160: MDT destroys are blocked by grouplocks ========================================================== 00:05:13 (1763355913) [ 6576.937175] LustreError: lustre-MDT0000-mdc-ffff947dc91b4000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 6617.320062] Lustre: DEBUG MARKER: == recovery-small test 161: evict osp by ping evictor ==== 00:05:55 (1763355955) [ 6629.874860] Lustre: DEBUG MARKER: == recovery-small test 162: File attributes should be persisted after MDS failover ========================================================== 00:06:08 (1763355968) [ 6633.968962] LustreError: 2401:0:(client.c:3418:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff947dc6120000 x1849005907171712/t158913790019(158913790019) o101->lustre-MDT0000-mdc-ffff947dc91b4000@192.168.203.156@tcp:12/10 lens 576/608 e 0 to 0 dl 1763356027 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'chattr.0' uid:0 gid:0 projid:0 [ 6643.994817] Lustre: DEBUG MARKER: == recovery-small test 163: changelog check for fail write and processing records ========================================================== 00:06:22 (1763355982) [ 6652.238454] Lustre: DEBUG MARKER: == recovery-small test complete, duration 6416 sec ======= 00:06:30 (1763355990) [ 6652.743732] Lustre: DEBUG MARKER: === recovery-small: start cleanup 00:06:31 (1763355991) === [ 6737.434801] Lustre: DEBUG MARKER: === recovery-small: finish cleanup 00:07:55 (1763356075) === [ 6737.743516] LustreError: 124993:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff947dc91b4000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 6737.746496] LustreError: 124993:0:(lov_obd.c:783:lov_cleanup()) Skipped 1 previous similar message [ 6737.752772] LustreError: 124993:0:(obd_class.h:479:obd_check_dev()) Device 6 not setup [ 6737.754521] LustreError: 124993:0:(obd_class.h:479:obd_check_dev()) Skipped 9 previous similar messages [ 6737.793595] Lustre: Unmounted lustre-client [ 6774.362466] Key type lgssc unregistered [ 6774.491648] LNet: 125679:0:(lib-ptl.c:967:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 6774.494552] LNetError: 125679:0:(acceptor.c:264:lnet_acceptor_remove_socket()) Interface ens2 not found [ 6774.504533] LNet: Removed LNI 192.168.203.56@tcp [ 6774.794135] Key type .llcrypt unregistered [ 6774.795375] Key type ._llcrypt unregistered