[ 0.000000] Linux version 4.18.0rh8.10-debug (green@maintenance) (gcc version 8.5.0 20210514 (Red Hat 8.5.0-26) (GCC)) #2 SMP Mon Jul 14 01:24:22 EDT 2025 [ 0.000000] Command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers' [ 0.000000] x86/fpu: xstate_offset[2]: 576, xstate_sizes[2]: 256 [ 0.000000] x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'standard' format. [ 0.000000] signal: max sigframe size: 1776 [ 0.000000] BIOS-provided physical RAM map: [ 0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable [ 0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000000100000-0x00000000bffd9fff] usable [ 0.000000] BIOS-e820: [mem 0x00000000bffda000-0x00000000bfffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000100000000-0x0000000146dfffff] usable [ 0.000000] NX (Execute Disable) protection: active [ 0.000000] SMBIOS 2.8 present. [ 0.000000] DMI: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.17.0-10.fc44 06/10/2025 [ 0.000000] Hypervisor detected: KVM [ 0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00 [ 0.000000] kvm-clock: using sched offset of 442325414 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2399.998 MHz processor [ 0.000000] last_pfn = 0x146e00 max_arch_pfn = 0x400000000 [ 0.000000] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT [ 0.000000] last_pfn = 0xbffda max_arch_pfn = 0x400000000 [ 0.000000] found SMP MP-table at [mem 0x000f54d0-0x000f54df] [ 0.000000] RAMDISK: [mem 0xbcc64000-0xbffcffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F52F0 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE2464 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE2300 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 0022C0 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE2374 000090 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE2404 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE243C 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe2300-0xbffe2373] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe22ff] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe2374-0xbffe2403] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe2404-0xbffe243b] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe243c-0xbffe2463] [ 0.000000] No NUMA configuration found [ 0.000000] Faking a node at [mem 0x0000000000000000-0x0000000146dfffff] [ 0.000000] NODE_DATA(0) allocated [mem 0x1465a3000-0x1465cdfff] [ 0.000000] Reserving 256MB of memory at 2752MB for crashkernel (System RAM: 4205MB) [ 0.000000] Zone ranges: [ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.000000] DMA32 [mem 0x0000000001000000-0x00000000ffffffff] [ 0.000000] Normal [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Device empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff] [ 0.000000] node 0: [mem 0x0000000000100000-0x00000000bffd9fff] [ 0.000000] node 0: [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Zeroed struct page in unavailable ranges: 4744 pages [ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x0000000146dfffff] [ 0.000000] ACPI: PM-Timer IO Port: 0x608 [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) [ 0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) [ 0.000000] Using ACPI (MADT) for SMP configuration information [ 0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000] TSC deadline timer available [ 0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs [ 0.000000] kvm-guest: KVM setup pv remote TLB flush [ 0.000000] kvm-guest: setup PV sched yield [ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff] [ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff] [ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff] [ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff] [ 0.000000] PM: Registered nosave memory: [mem 0xbffda000-0xbfffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xc0000000-0xfeffbfff] [ 0.000000] PM: Registered nosave memory: [mem 0xfeffc000-0xfeffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xff000000-0xfffbffff] [ 0.000000] PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff] [ 0.000000] [mem 0xc0000000-0xfeffbfff] available for PCI devices [ 0.000000] Booting paravirtualized kernel on KVM [ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns [ 0.000000] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1 [ 0.000000] percpu: Embedded 63 pages/cpu s221184 r8192 d28672 u524288 [ 0.000000] kvm-guest: PV spinlocks enabled [ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1059618 [ 0.000000] Policy zone: Normal [ 0.000000] Kernel command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] Specific versions of hardware are certified with Red Hat Enterprise Linux 8. Please see the list of hardware certified with Red Hat Enterprise Linux 8 at https://catalog.redhat.com. [ 0.000000] audit: disabled (until reboot) [ 0.000000] software IO TLB: area num 4. [ 0.000000] Memory: 2895288K/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.001013] APIC: Switch to symmetric I/O mode setup [ 0.002278] x2apic enabled [ 0.003007] Switched APIC routing to physical x2apic. [ 0.004014] kvm-guest: setup PV IPIs [ 0.006916] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.007000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.007019] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.008012] pid_max: default: 32768 minimum: 301 [ 0.010122] LSM: Security Framework initializing [ 0.012024] Yama: becoming mindful. [ 0.013039] SELinux: Initializing. [ 0.014077] *** VALIDATE selinux *** [ 0.022764] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.027142] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.028169] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.029112] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.030115] *** VALIDATE tmpfs *** [ 0.032389] *** VALIDATE proc *** [ 0.034053] *** VALIDATE cgroup *** [ 0.035008] *** VALIDATE cgroup2 *** [ 0.037221] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.038147] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.039008] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.040025] Spectre V2 : User space: Vulnerable [ 0.041010] Speculative Store Bypass: Vulnerable [ 0.044515] debug: unmapping init [mem 0xffffffff97459000-0xffffffff97460fff] [ 0.046172] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.047728] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.048025] ... version: 2 [ 0.049014] ... bit width: 48 [ 0.050012] ... generic registers: 4 [ 0.051012] ... value mask: 0000ffffffffffff [ 0.052018] ... max period: 00007fffffffffff [ 0.053019] ... fixed-purpose events: 3 [ 0.054013] ... event mask: 000000070000000f [ 0.055348] rcu: Hierarchical SRCU implementation. [ 0.057476] smp: Bringing up secondary CPUs ... [ 0.058610] x86: Booting SMP configuration: [ 0.059021] .... node #0, CPUs: #1 #2 #3 [ 0.063275] smp: Brought up 1 node, 4 CPUs [ 0.065018] smpboot: Max logical packages: 1 [ 0.066014] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.139466] node 0 deferred pages initialised in 69ms [ 0.143360] devtmpfs: initialized [ 0.144240] x86/mm: Memory block size: 128MB [ 0.146970] gcov: version magic: 0x41383552 [ 0.148176] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.149074] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.150208] pinctrl core: initialized pinctrl subsystem [ 0.151182] [ 0.151582] ************************************************************* [ 0.152016] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.153016] ** ** [ 0.154015] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.155014] ** ** [ 0.156027] ** This means that this kernel is built to expose internal ** [ 0.157009] ** IOMMU data structures, which may compromise security on ** [ 0.158014] ** your system. ** [ 0.159016] ** ** [ 0.160017] ** If you see this message and you are not debugging the ** [ 0.161011] ** kernel, report this immediately to your vendor! ** [ 0.162016] ** ** [ 0.163014] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.164014] ************************************************************* [ 0.165826] NET: Registered protocol family 16 [ 0.166459] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.167063] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.168079] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.169415] cpuidle: using governor menu [ 0.171623] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.174560] PCI: Using configuration type 1 for base access [ 0.177126] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.188175] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.190025] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.194074] cryptd: max_cpu_qlen set to 1000 [ 0.197250] ACPI: Added _OSI(Module Device) [ 0.198017] ACPI: Added _OSI(Processor Device) [ 0.200015] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.202013] ACPI: Added _OSI(Processor Aggregator Device) [ 0.207458] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.214313] ACPI: Interpreter enabled [ 0.215120] ACPI: PM: (supports S0 S3 S4 S5) [ 0.216011] ACPI: Using IOAPIC for interrupt routing [ 0.217175] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.221525] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.233000] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.236049] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.238023] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.242085] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.246401] acpiphp: Slot [2] registered [ 0.248141] acpiphp: Slot [5] registered [ 0.250091] acpiphp: Slot [6] registered [ 0.253167] acpiphp: Slot [3] registered [ 0.254119] acpiphp: Slot [4] registered [ 0.256104] acpiphp: Slot [7] registered [ 0.257083] acpiphp: Slot [8] registered [ 0.258149] acpiphp: Slot [9] registered [ 0.260079] acpiphp: Slot [10] registered [ 0.261148] acpiphp: Slot [11] registered [ 0.263089] acpiphp: Slot [12] registered [ 0.264084] acpiphp: Slot [13] registered [ 0.266122] acpiphp: Slot [14] registered [ 0.267116] acpiphp: Slot [15] registered [ 0.269099] acpiphp: Slot [16] registered [ 0.270148] acpiphp: Slot [17] registered [ 0.272095] acpiphp: Slot [18] registered [ 0.274099] acpiphp: Slot [19] registered [ 0.276143] acpiphp: Slot [20] registered [ 0.277218] acpiphp: Slot [21] registered [ 0.278076] acpiphp: Slot [22] registered [ 0.280101] acpiphp: Slot [23] registered [ 0.282216] acpiphp: Slot [24] registered [ 0.284091] acpiphp: Slot [25] registered [ 0.285096] acpiphp: Slot [26] registered [ 0.287123] acpiphp: Slot [27] registered [ 0.288093] acpiphp: Slot [28] registered [ 0.290093] acpiphp: Slot [29] registered [ 0.292104] acpiphp: Slot [30] registered [ 0.293080] acpiphp: Slot [31] registered [ 0.295089] PCI host bridge to bus 0000:00 [ 0.296015] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.298034] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.301041] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.304059] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.307030] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.310030] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.312217] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.315464] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.319694] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.328016] pci 0000:00:01.1: reg 0x20: [io 0xc120-0xc12f] [ 0.333056] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.336024] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.338018] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.341022] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.345578] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.348787] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.351042] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.353837] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.357962] pci 0000:00:02.0: reg 0x10: [io 0xc100-0xc11f] [ 0.369017] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.374024] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.380175] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.391017] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.399013] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.428018] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.449617] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.456014] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.462012] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.477018] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.492085] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.494383] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.496385] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.500419] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.503204] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.508027] iommu: Default domain type: Passthrough [ 0.510447] SCSI subsystem initialized [ 0.512176] ACPI: bus type USB registered [ 0.514115] usbcore: registered new interface driver usbfs [ 0.516072] usbcore: registered new interface driver hub [ 0.518082] usbcore: registered new device driver usb [ 0.521168] pps_core: LinuxPPS API ver. 1 registered [ 0.523014] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.526064] PTP clock support registered [ 0.528173] EDAC MC: Ver: 3.0.0 [ 0.530162] PCI: Using ACPI for IRQ routing [ 0.532850] NetLabel: Initializing [ 0.535012] NetLabel: domain hash size = 128 [ 0.537010] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.539084] NetLabel: unlabeled traffic allowed by default [ 0.541163] vgaarb: loaded [ 0.543320] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.544014] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.548285] clocksource: Switched to clocksource kvm-clock [ 0.668692] VFS: Disk quotas dquot_6.6.0 [ 0.670199] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.672978] *** VALIDATE ramfs *** [ 0.674168] *** VALIDATE hugetlbfs *** [ 0.676030] pnp: PnP ACPI init [ 0.678291] pnp: PnP ACPI: found 6 devices [ 0.700514] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.704620] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.707135] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.709314] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.711908] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.714171] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.717073] NET: Registered protocol family 2 [ 0.719392] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.723636] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.727773] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.734111] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.737863] TCP: Hash tables configured (established 65536 bind 65536) [ 0.740371] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.743476] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.746413] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.749092] NET: Registered protocol family 1 [ 0.751784] RPC: Registered named UNIX socket transport module. [ 0.754133] RPC: Registered udp transport module. [ 0.755923] RPC: Registered tcp transport module. [ 0.757396] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.760020] NET: Registered protocol family 44 [ 0.762089] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.764280] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.766746] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.769143] PCI: CLS 0 bytes, default 64 [ 0.770953] Unpacking initramfs... [ 2.153585] debug: unmapping init [mem 0xffff936e3cc64000-0xffff936e3ffcffff] [ 2.157713] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.159838] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.162940] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 2.672947] Initialise system trusted keyrings [ 2.674938] Key type blacklist registered [ 2.676820] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.688659] zbud: loaded [ 2.693258] *** VALIDATE nfs *** [ 2.694553] *** VALIDATE nfs4 *** [ 2.696491] pstore: using deflate compression [ 2.700132] Platform Keyring initialized [ 2.798303] NET: Registered protocol family 38 [ 2.800496] Key type asymmetric registered [ 2.802840] Asymmetric key parser 'x509' registered [ 2.805123] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 2.808486] io scheduler mq-deadline registered [ 2.810312] io scheduler kyber registered [ 2.811834] io scheduler bfq registered [ 2.813809] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 2.816660] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 2.818894] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 2.821748] ACPI: Power Button [PWRF] [ 2.827633] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 2.834232] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 2.848480] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 2.879447] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 2.907877] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 2.913400] Non-volatile memory driver v1.3 [ 2.915636] Linux agpgart interface v0.103 [ 2.954151] virtio_blk virtio1: [vda] 146976 512-byte logical blocks (75.3 MB/71.8 MiB) [ 2.957136] vda: detected capacity change from 0 to 75251712 [ 2.971947] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 2.974351] vdb: detected capacity change from 0 to 1073741824 [ 2.981171] libphy: Fixed MDIO Bus: probed [ 2.987217] usbcore: registered new interface driver usbserial_generic [ 2.990688] usbserial: USB Serial support registered for generic [ 2.993208] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 2.998082] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.000082] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.002712] mousedev: PS/2 mouse device common for all mice [ 3.005888] rtc_cmos 00:05: RTC can wake from S4 [ 3.008514] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.008769] rtc_cmos 00:05: registered as rtc0 [ 3.013382] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.016168] intel_pstate: CPU model not supported [ 3.019326] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.024659] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.024747] hid: raw HID events driver (C) Jiri Kosina [ 3.031362] usbcore: registered new interface driver usbhid [ 3.033546] usbhid: USB HID core driver [ 3.035192] drop_monitor: Initializing network drop monitor service [ 3.037783] Initializing XFRM netlink socket [ 3.039306] NET: Registered protocol family 10 [ 3.041629] Segment Routing with IPv6 [ 3.042616] NET: Registered protocol family 17 [ 3.045202] mpls_gso: MPLS GSO support [ 3.049730] RAS: Correctable Errors collector initialized. [ 3.051338] AVX version of gcm_enc/dec engaged. [ 3.052779] AES CTR mode by8 optimization enabled [ 3.119937] sched_clock: Marking stable (3119865341, 0)->(4040998423, -921133082) [ 3.122890] registered taskstats version 1 [ 3.125166] Loading compiled-in X.509 certificates [ 3.127321] zswap: loaded using pool lzo/zbud [ 3.153841] Key type big_key registered [ 3.167859] Key type encrypted registered [ 3.169477] ima: No TPM chip found, activating TPM-bypass! [ 3.171696] ima: Allocated hash algorithm: sha1 [ 3.173771] ima: No architecture policies found [ 3.175909] evm: Initialising EVM extended attributes: [ 3.178239] evm: security.selinux [ 3.179524] evm: security.ima [ 3.181131] evm: security.capability [ 3.182453] evm: HMAC attrs: 0x1 [ 3.185508] rtc_cmos 00:05: setting system clock to 2026-08-27 22:03:21 UTC (1787868201) [ 3.192154] debug: unmapping init [mem 0xffffffff98403000-0xffffffff985fffff] [ 3.196453] debug: unmapping init [mem 0xffffffff97182000-0xffffffff97458fff] [ 3.205080] Write protecting the kernel read-only data: 28672k [ 3.209197] debug: unmapping init [mem 0xffffffff95803000-0xffffffff959fffff] [ 3.212293] debug: unmapping init [mem 0xffffffff96114000-0xffffffff961fffff] [ 3.242363] 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.248109] systemd[1]: Detected virtualization kvm. [ 3.249725] systemd[1]: Detected architecture x86-64. [ 3.251358] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.276233] systemd[1]: No hostname configured. [ 3.277437] systemd[1]: Set hostname to . [ 3.278840] random: systemd: uninitialized urandom read (16 bytes read) [ 3.280183] systemd[1]: Initializing machine ID from random generator. [ 3.317752] random: ln: uninitialized urandom read (6 bytes read) [ 3.400273] random: systemd: uninitialized urandom read (16 bytes read) [ 3.403881] systemd[1]: Listening on Journal Socket. [ OK ] Listening on Journal Socket. [ 3.408485] systemd[1]: Reached target Timers. [ OK ] Reached target Timers. [ 3.416567] systemd[1]: Started Memstrack Anylazing Service. [ OK ] Started Memstrack Anylazing Service. [ OK ] Listening on Journal Socket (/dev/log). Starting Journal Service... [ OK ] Reached target Local File Systems. Starting Create Volatile Files and Directories... [ OK ] Reached target Slices. [ OK ] Listening on udev Kernel Socket. [ OK ] Reached target Swap. [ OK ] Reached target Initrd Root Device. [ OK ] Listening on udev Control Socket. [ OK ] Reached target Sockets. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Local Encrypted Volumes. Starting Setup Virtual Console... Starting Create list of required st…ce nodes for the current kernel... [ OK ] Reached target Paths. Starting Apply Kernel Variables... [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Setup Virtual Console. [ OK ] Started Apply Kernel Variables. Starting dracut cmdline hook... Starting Create Static Device Nodes in /dev... [ OK ] Started Journal Service. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 3.991100] device-mapper: uevent: version 1.0.3 [ 3.993350] device-mapper: ioctl: 4.46.0-ioctl (2022-02-22) initialised: dm-devel@redhat.com [ OK ] Started dracut pre-udev hook. Starting udev Kernel Device Manager... [ OK ] Started udev Kernel Device Manager. Starting dracut pre-trigger hook... [ OK ] Started dracut pre-trigger hook. Starting udev Coldplug all Devices... Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. Starting dracut initqueue hook... [ OK ] Reached target System Initialization. [[ 4.632004] random: fast init done  OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ 4.668254] virtio_net virtio0 ens2: renamed from eth0 [ 4.833036] scsi host0: ata_piix [ 4.857964] scsi host1: ata_piix [ 4.868909] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc120 irq 14 [ 4.871179] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc128 irq 15 [ 9.135964] dracut-initqueue[585]: RTNETLINK answers: File exists [ 9.689334] random: crng init done [ 9.691142] random: 7 urandom warning(s) missed due to ratelimiting Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. Mounting /sysroot... [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. [ 10.099762] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped target Timers. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Slices. [ OK ] Stopped target Paths. [ OK ] Stopped target Sockets. [ OK ] Stopped target System Initialization. [ OK ] Stopped target Swap. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. Stopping udev Kernel Device Manager... [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Closed udev 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.338317] printk: systemd: 25 output lines suppressed due to ratelimiting [ 11.626273] SELinux: Disabled at runtime. [ 11.689439] 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.700000] systemd[1]: Detected virtualization kvm. [ 11.702183] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 12.242884] systemd[1]: initrd-switch-root.service: Succeeded. [ 12.246802] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 12.253590] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 12.259396] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 12.263317] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 12.271396] systemd[1]: Starting Journal Service... Starting Journal Service... [ 12.276690] systemd[1]: Started Forward Password Requests to Wall Directory Watch. [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Created slice system-getty.slice. Mounting POSIX Message Queue File System... [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd Root File System. [ OK ] Stopped target Initrd File Systems. [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Listening on initctl Compatibility Named Pipe. Mounting Kernel Debug File System... [ OK ] Reached target RPC Port Mapper. Starting Create list of required st…ce nodes for the current kernel... [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Created slice User and Session Slice. [ OK ] Reached target rpc_pipefs.target. [ OK ] Listening on udev Kernel Socket. [ OK ] Reached target Slices. [ OK ] Listening on Process Core Dump Socket. [ OK ] Listening on udev Control Socket. Mounting Huge Pages File System... [ OK ] Reached target Paths. Starting udev Coldplug all Devices... Starting Apply Kernel Variables... Activating swap /dev/disk/by-label/SWAP... Starting Remount Root and Kernel File Systems... [ OK ] Reached target Local Encrypted Volumes. [ OK ] Started Journal Service. [ 12.495689] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS [ OK ] Mounted POSIX Message Queue File System. [ 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 ] 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. Starting Configure read-only root support... [ OK ] Reached target Swap. Starting Create Static Device Nodes in /dev... Starting Flush Journal to Persistent Storage... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. Starting udev Kernel Device Manager... [ OK ] Reached target Local File Systems (Pre). Mounting /home/green/git/lustre-release... Mounting /mnt... [ OK ] Started udev Coldplug all Devices. [ 12.825118] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /mnt. [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 13.223079] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 13.250336] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 13.342671] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 13.356243] EDAC sbridge: Ver: 1.1.2 [ 14.752365] Key type dns_resolver registered [ 15.055830] NFS: Registering the id_resolver key type [ 15.058141] Key type id_resolver registered [ 15.059853] Key type id_legacy registered [ OK ] Started Configure read-only root support. Starting Load/Save Random Seed... [ 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... [ OK ] Started Load/Save Random Seed. [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Create Volatile Files and Directories. Starting RPC Bind... Starting Update UTMP about System Boot/Shutdown... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Started dnf makecache --timer. [ OK ] Reached target Timers. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting Restore /run/initramfs on shutdown... [ OK ] Started irqbalance daemon. [ OK ] Reached target sshd-keygen.target. [ OK ] Started D-Bus System Message Bus. Starting Login Service... Starting Network Manager... [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Login Service. [ OK ] Started Network Manager. [ OK ] Reached target Network. Starting GSSAPI Proxy Daemon... Starting Dynamic System Tuning Daemon... Starting OpenSSH server daemon... Starting Network Manager Wait Online... [ 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... Starting Hostname Service... [ 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 System Logging Service... Starting Notify NFS peers of a restart... Starting Crash recovery kernel arming... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Starting Authorization Manager... [ 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 oleg411-client login: [ 47.991190] libcfs: loading out-of-tree module taints kernel. [ 48.035938] Key type ._llcrypt registered [ 48.042295] Key type .llcrypt registered [ 48.691990] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [ 48.706428] alg: No test for adler32 (adler32-zlib) [ 50.313508] Lustre: Lustre: Build Version: 2.17.57_103_gb165317 [ 51.056497] LNet: Added LNI 192.168.204.11@tcp [8/256/0/180] [ 52.856253] Key type lgssc registered [ 55.120868] Lustre: Echo OBD driver; http://www.lustre.org/ [ 116.413311] hrtimer: interrupt took 12409368 ns [ 201.976316] Lustre: Mounted lustre-client - version 2.17.57_103_gb165317 [ 207.357156] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 218.634951] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing check_logdir /tmp/testlogs/ [ 225.459244] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing yml_node [ 227.809694] Lustre: lustre-OST0000-osc-ffff936e9008e800: disconnect after 24s idle [ 229.324165] Lustre: DEBUG MARKER: Client: 2.17.57.103 [ 231.557628] Lustre: DEBUG MARKER: MDS: 2.17.57.103 [ 234.245836] Lustre: DEBUG MARKER: OSS: 2.17.57.103 [ 236.039969] Lustre: DEBUG MARKER: -----============= acceptance-small: recovery-small ============----- Thu Aug 27 18:07:12 EDT 2026 [ 253.843918] Lustre: DEBUG MARKER: excepting tests: 136 [ 256.496034] Lustre: DEBUG MARKER: === recovery-small: start setup 18:07:33 (1787868453) === [ 264.628350] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing check_config_client /mnt/lustre [ 288.093684] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 301.607717] Lustre: DEBUG MARKER: === recovery-small: finish setup 18:08:17 (1787868497) === [ 303.713559] Lustre: DEBUG MARKER: == recovery-small test 1: create, chmod, stat: drop req, drop rep ========================================================== 18:08:20 (1787868500) [ 321.505781] Lustre: 10009:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787868503/real 1787868503] req@ffff936e92882d00 x1874715737076224/t0(0) o700->lustre-MDT0000-mdc-ffff936e9008e800@192.168.204.111@tcp:30/10 lens 264/248 e 0 to 1 dl 1787868519 ref 2 fl Rpc:XQr/200/ffffffff rc 0/-1 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 321.576614] Lustre: lustre-MDT0000-mdc-ffff936e9008e800: Connection to lustre-MDT0000 (at 192.168.204.111@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 321.700035] Lustre: lustre-MDT0000-mdc-ffff936e9008e800: Connection restored to 192.168.204.111@tcp (at 192.168.204.111@tcp) [ 341.988192] Lustre: 10030:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787868524/real 1787868524] req@ffff936e8ac23480 x1874715737078016/t0(0) o36->lustre-MDT0000-mdc-ffff936e9008e800@192.168.204.111@tcp:12/10 lens 520/576 e 0 to 1 dl 1787868540 ref 2 fl Rpc:XQr/200/ffffffff rc 0/-1 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 342.028935] Lustre: lustre-MDT0000-mdc-ffff936e9008e800: Connection to lustre-MDT0000 (at 192.168.204.111@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 342.101265] Lustre: lustre-MDT0000-mdc-ffff936e9008e800: Connection restored to 192.168.204.111@tcp (at 192.168.204.111@tcp) [ 361.440319] Lustre: 10056:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787868543/real 1787868543] req@ffff936e8ac20f00 x1874715737079296/t0(0) o101->lustre-MDT0000-mdc-ffff936e9008e800@192.168.204.111@tcp:12/10 lens 576/1152 e 0 to 1 dl 1787868559 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'tchmod.0' uid:0 gid:0 projid:0 [ 361.478565] Lustre: lustre-MDT0000-mdc-ffff936e9008e800: Connection to lustre-MDT0000 (at 192.168.204.111@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 361.533819] Lustre: lustre-MDT0000-mdc-ffff936e9008e800: Connection restored to 192.168.204.111@tcp (at 192.168.204.111@tcp) [ 380.384237] Lustre: 10077:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787868562/real 1787868562] req@ffff936e92883c00 x1874715737081472/t0(0) o36->lustre-MDT0000-mdc-ffff936e9008e800@192.168.204.111@tcp:12/10 lens 488/512 e 0 to 1 dl 1787868578 ref 2 fl Rpc:XQr/200/ffffffff rc 0/-1 job:'tchmod.0' uid:0 gid:0 projid:4294967295 [ 380.428793] Lustre: lustre-MDT0000-mdc-ffff936e9008e800: Connection to lustre-MDT0000 (at 192.168.204.111@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 380.473641] Lustre: lustre-MDT0000-mdc-ffff936e9008e800: Connection restored to 192.168.204.111@tcp (at 192.168.204.111@tcp) [ 399.328211] Lustre: 10102:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787868581/real 1787868581] req@ffff936e922c4b40 x1874715737082752/t0(0) o34->lustre-MDT0000-mdc-ffff936e9008e800@192.168.204.111@tcp:12/10 lens 472/728 e 0 to 1 dl 1787868597 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'statone.0' uid:0 gid:0 projid:0 [ 399.363112] Lustre: lustre-MDT0000-mdc-ffff936e9008e800: Connection to lustre-MDT0000 (at 192.168.204.111@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 399.432763] Lustre: lustre-MDT0000-mdc-ffff936e9008e800: Connection restored to 192.168.204.111@tcp (at 192.168.204.111@tcp) [ 417.761477] Lustre: 10123:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787868600/real 1787868600] req@ffff936e8ac20b40 x1874715737084032/t0(0) o34->lustre-MDT0000-mdc-ffff936e9008e800@192.168.204.111@tcp:12/10 lens 472/728 e 0 to 1 dl 1787868616 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'statone.0' uid:0 gid:0 projid:0 [ 417.815485] Lustre: lustre-MDT0000-mdc-ffff936e9008e800: Connection to lustre-MDT0000 (at 192.168.204.111@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 417.886241] Lustre: lustre-MDT0000-mdc-ffff936e9008e800: Connection restored to 192.168.204.111@tcp (at 192.168.204.111@tcp) [ 427.414390] Lustre: DEBUG MARKER: == recovery-small test 4: open: drop req, drop rep ======= 18:10:24 (1787868624) [ 445.410094] Lustre: 10726:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787868627/real 1787868627] req@ffff936e922c5680 x1874715737086464/t0(0) o101->lustre-MDT0000-mdc-ffff936e9008e800@192.168.204.111@tcp:12/10 lens 576/1152 e 0 to 1 dl 1787868643 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'cat.0' uid:0 gid:0 projid:0 [ 445.449480] Lustre: lustre-MDT0000-mdc-ffff936e9008e800: Connection to lustre-MDT0000 (at 192.168.204.111@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 445.507079] Lustre: lustre-MDT0000-mdc-ffff936e9008e800: Connection restored to 192.168.204.111@tcp (at 192.168.204.111@tcp) [ 473.358665] Lustre: DEBUG MARKER: == recovery-small test 5: rename: drop req, drop rep ===== 18:11:10 (1787868670) [ 489.952626] Lustre: 11348:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787868672/real 1787868672] req@ffff936e8ac22580 x1874715737092608/t0(0) o101->lustre-MDT0000-mdc-ffff936e9008e800@192.168.204.111@tcp:12/10 lens 576/1152 e 0 to 1 dl 1787868688 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'mv.0' uid:0 gid:0 projid:0 [ 489.983219] Lustre: 11348:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 489.993561] Lustre: lustre-MDT0000-mdc-ffff936e9008e800: Connection to lustre-MDT0000 (at 192.168.204.111@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 490.013444] Lustre: Skipped 1 previous similar message [ 490.042883] Lustre: lustre-MDT0000-mdc-ffff936e9008e800: Connection restored to 192.168.204.111@tcp (at 192.168.204.111@tcp) [ 490.049235] Lustre: Skipped 1 previous similar message [ 519.014973] Lustre: DEBUG MARKER: == recovery-small test 6: link, unlink: drop req, drop rep ========================================================== 18:11:55 (1787868715) [ 535.009527] Lustre: lustre-OST0000-osc-ffff936e9008e800: disconnect after 22s idle [ 535.019843] Lustre: Skipped 1 previous similar message [ 556.000596] Lustre: 12006:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787868738/real 1787868738] req@ffff936e92883c00 x1874715737103616/t0(0) o36->lustre-MDT0000-mdc-ffff936e9008e800@192.168.204.111@tcp:12/10 lens 512/440 e 0 to 1 dl 1787868754 ref 2 fl Rpc:XQr/200/ffffffff rc 0/-1 job:'link.0' uid:0 gid:0 projid:4294967295 [ 556.026145] Lustre: 12006:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 556.031507] Lustre: lustre-MDT0000-mdc-ffff936e9008e800: Connection to lustre-MDT0000 (at 192.168.204.111@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 556.039514] Lustre: Skipped 2 previous similar messages [ 556.079375] Lustre: lustre-MDT0000-mdc-ffff936e9008e800: Connection restored to 192.168.204.111@tcp (at 192.168.204.111@tcp) [ 556.102630] Lustre: Skipped 2 previous similar messages [ 604.115383] Lustre: DEBUG MARKER: == recovery-small test 8: touch: drop rep (bug 1423) ===== 18:13:20 (1787868800) [ 630.062180] Lustre: DEBUG MARKER: == recovery-small test 9: pause bulk on OST (bug 1420) === 18:13:46 (1787868826) [ 647.161116] Lustre: DEBUG MARKER: == recovery-small test 10a: finish request on server after client eviction (bug 1521) ========================================================== 18:14:03 (1787868843) [ 648.118830] Lustre: *** cfs_fail_loc=305, val=0*** [ 661.986956] Lustre: lustre-OST0000-osc-ffff936e9008e800: disconnect after 21s idle [ 664.425536] Lustre: *** cfs_fail_loc=305, val=0*** [ 680.799704] Lustre: *** cfs_fail_loc=305, val=0*** [ 696.168482] Lustre: *** cfs_fail_loc=305, val=0*** [ 712.568512] Lustre: *** cfs_fail_loc=305, val=0*** [ 727.889147] Lustre: *** cfs_fail_loc=305, val=0*** [ 744.291914] Lustre: *** cfs_fail_loc=305, val=0*** [ 761.123058] LustreError: lustre-MDT0000-mdc-ffff936e9008e800: operation ldlm_enqueue to node 192.168.204.111@tcp failed: rc = -107 [ 761.135261] Lustre: lustre-MDT0000-mdc-ffff936e9008e800: Connection to lustre-MDT0000 (at 192.168.204.111@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 761.157266] Lustre: Skipped 3 previous similar messages [ 761.186373] LustreError: lustre-MDT0000-mdc-ffff936e9008e800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 761.233218] Lustre: lustre-MDT0000-mdc-ffff936e9008e800: Connection restored to 192.168.204.111@tcp (at 192.168.204.111@tcp) [ 761.238413] Lustre: Skipped 3 previous similar messages [ 773.152753] Lustre: DEBUG MARKER: == recovery-small test 10b: re-send BL AST =============== 18:16:10 (1787868970) [ 784.864683] Lustre: lustre-OST0000-osc-ffff936e9008e800: disconnect after 21s idle [ 798.936131] Lustre: DEBUG MARKER: == recovery-small test 10c: re-send BL AST vs reconnect race (LU-5569) ========================================================== 18:16:35 (1787868995) [ 799.583505] Lustre: *** cfs_fail_loc=305, val=0*** [ 799.587000] Lustre: Skipped 1 previous similar message [ 808.545655] Lustre: DEBUG MARKER: == recovery-small test 10d: test failed blocking ast ===== 18:16:45 (1787869005) [ 812.271948] Lustre: Unmounted lustre-client [ 812.766589] Lustre: Mounted lustre-client - version 2.17.57_103_gb165317 [ 813.397514] Lustre: Mounted lustre-client - version 2.17.57_103_gb165317 [ 814.841424] LustreError: lustre-OST0000-osc-ffff936e835a7000: operation ost_statfs to node 192.168.204.111@tcp failed: rc = -107 [ 814.867844] LustreError: lustre-OST0000-osc-ffff936e835a7000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 814.886728] Lustre: 2349:0:(llite_lib.c:4352:ll_dirty_page_discard_warn()) lustre: dirty page discard: 192.168.204.111@tcp:/lustre/fid: [0x200000403:0x1:0x0]/ may get corrupted (rc -108) [ 817.286179] Lustre: Unmounted lustre-client [ 824.116522] Lustre: DEBUG MARKER: == recovery-small test 10e: re-send BL AST vs reconnect race 2 ========================================================== 18:17:00 (1787869020) [ 825.894468] Lustre: DEBUG MARKER: SKIP: recovery-small test_10e need two clients [ 827.907762] Lustre: DEBUG MARKER: == recovery-small test 11: wake up a thread waiting for completion after eviction (b=2460) ========================================================== 18:17:04 (1787869024) [ 855.885521] Lustre: DEBUG MARKER: == recovery-small test 12: recover from timed out resend in ptlrpcd (b=2494) ========================================================== 18:17:32 (1787869052) [ 855.964347] Lustre: DEBUG MARKER: multiop /mnt/lustre/f12.recovery-small OS_c [ 873.440182] Lustre: 17640:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787869055/real 1787869055] req@ffff936e922c6d00 x1874715737175296/t0(0) o35->lustre-MDT0000-mdc-ffff936e835a7000@192.168.204.111@tcp:23/10 lens 392/624 e 0 to 1 dl 1787869071 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'multiop.0' uid:0 gid:0 projid:0 [ 873.465859] Lustre: 17640:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 900.273519] Lustre: DEBUG MARKER: == recovery-small test 13: mdc_readpage restart test (bug 1138) ========================================================== 18:18:16 (1787869096) [ 925.372303] Lustre: DEBUG MARKER: == recovery-small test 14: mdc_readpage resend test (bug 1138) ========================================================== 18:18:42 (1787869122) [ 934.566342] Lustre: DEBUG MARKER: == recovery-small test 15: failed open (-ENOMEM) ========= 18:18:51 (1787869131) [ 943.379415] Lustre: DEBUG MARKER: == recovery-small test 16: timeout bulk put, don't evict client (2732) ========================================================== 18:19:00 (1787869140) [ 991.610931] Lustre: DEBUG MARKER: == recovery-small test 17a: timeout bulk get, don't evict client (2732) ========================================================== 18:19:48 (1787869188) [ 1047.989768] Lustre: DEBUG MARKER: == recovery-small test 17b: timeout bulk get, dont evict client (3582) ========================================================== 18:20:44 (1787869244) [ 1049.605927] Lustre: DEBUG MARKER: SKIP: recovery-small test_17b Needs multiple clients [ 1051.323273] Lustre: DEBUG MARKER: == recovery-small test 18a: manual ost invalidate clears page cache immediately ========================================================== 18:20:48 (1787869248) [ 1052.372961] Lustre: setting import lustre-OST0001_UUID INACTIVE by administrator request [ 1052.446699] Lustre: lustre-OST0001-osc-ffff936e835a7000: Connection to lustre-OST0001 (at 192.168.204.111@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1052.464151] Lustre: Skipped 5 previous similar messages [ 1052.474947] LustreError: lustre-OST0001-osc-ffff936e835a7000: This client was evicted by lustre-OST0001; in progress operations using this service will fail. [ 1059.318532] Lustre: DEBUG MARKER: == recovery-small test 18b: eviction and reconnect clears page cache (2766) ========================================================== 18:20:56 (1787869256) [ 1063.934349] LustreError: lustre-OST0000-osc-ffff936e835a7000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 1063.952531] Lustre: lustre-OST0000-osc-ffff936e835a7000: Connection restored to 192.168.204.111@tcp (at 192.168.204.111@tcp) [ 1063.969626] Lustre: Skipped 4 previous similar messages [ 1093.007692] Lustre: DEBUG MARKER: == recovery-small test 18c: Dropped connect reply after eviction handing (14755) ========================================================== 18:21:29 (1787869289) [ 1097.400779] LustreError: lustre-OST0000-osc-ffff936e835a7000: operation ost_statfs to node 192.168.204.111@tcp failed: rc = -107 [ 1106.955488] Lustre: Evicted from lustre-OST0000_UUID (at 192.168.204.111@tcp) after server handle changed from 0x4d25ce6b38ecdaba to 0x4d25ce6b38ecdc0a [ 1106.965610] LustreError: lustre-OST0000-osc-ffff936e835a7000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 1116.698978] Lustre: DEBUG MARKER: == recovery-small test 19a: test expired_lock_main on mds (2867) ========================================================== 18:21:53 (1787869313) [ 1117.311330] Lustre: Mounted lustre-client - version 2.17.57_103_gb165317 [ 1135.072199] Lustre: 2346:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787869317/real 1787869317] req@ffff936e922c4f00 x1874715737233024/t0(0) o103->lustre-MDT0000-mdc-ffff936e835a7000@192.168.204.111@tcp:17/18 lens 328/224 e 0 to 1 dl 1787869333 ref 1 fl Rpc:XQr/200/ffffffff rc 0/-1 job:'ldlm_bl.0' uid:0 gid:0 projid:4294967295 [ 1135.102195] Lustre: 2346:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 1223.511593] LustreError: lustre-MDT0000-mdc-ffff936e835a7000: operation ldlm_enqueue to node 192.168.204.111@tcp failed: rc = -107 [ 1223.568431] LustreError: lustre-MDT0000-mdc-ffff936e835a7000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 1223.582814] LustreError: 23887:0:(file.c:6184:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -5 [ 1223.583893] LustreError: 23888:0:(file.c:251:ll_close_inode_openhandle()) lustre-clilmv-ffff936e835a7000: inode [0x200000403:0x1:0x0] mdc close failed: rc = -108 [ 1224.838734] Lustre: Unmounted lustre-client [ 1234.447696] Lustre: DEBUG MARKER: == recovery-small test 19b: test expired_lock_main on ost (2867) ========================================================== 18:23:50 (1787869430) [ 1234.887216] Lustre: Mounted lustre-client - version 2.17.57_103_gb165317 [ 1342.982089] LustreError: lustre-OST0001-osc-ffff936e835a7000: This client was evicted by lustre-OST0001; in progress operations using this service will fail. [ 1344.179206] Lustre: Unmounted lustre-client [ 1354.456898] Lustre: DEBUG MARKER: == recovery-small test 19c: check reconnect and lock resend do not trigger expired_lock_main ========================================================== 18:25:51 (1787869551) [ 1355.214667] Lustre: Mounted lustre-client - version 2.17.57_103_gb165317 [ 1361.166558] Lustre: Unmounted lustre-client [ 1375.131798] Lustre: DEBUG MARKER: == recovery-small test 20a: ldlm_handle_enqueue error (should return error) ========================================================== 18:26:11 (1787869571) [ 1376.746073] LustreError: lustre-OST0000-osc-ffff936e835a7000: operation ldlm_enqueue to node 192.168.204.111@tcp failed: rc = -12 [ 1385.569101] Lustre: DEBUG MARKER: == recovery-small test 20b: ldlm_handle_enqueue error (should return error) ========================================================== 18:26:21 (1787869581) [ 1387.624397] LustreError: lustre-OST0000-osc-ffff936e835a7000: operation ldlm_enqueue to node 192.168.204.111@tcp failed: rc = -12 [ 1396.339379] Lustre: DEBUG MARKER: == recovery-small test 21a: drop close request while close and open are both in flight ========================================================== 18:26:33 (1787869593) [ 1427.914899] Lustre: DEBUG MARKER: == recovery-small test 21b: drop open request while close and open are both in flight ========================================================== 18:27:04 (1787869624) [ 1565.664228] Lustre: lustre-MDT0000-mdc-ffff936e835a7000: Connection to lustre-MDT0000 (at 192.168.204.111@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1565.675293] Lustre: Skipped 17 previous similar messages [ 1574.128592] Lustre: DEBUG MARKER: == recovery-small test 21c: drop both request while close and open are both in flight ========================================================== 18:29:31 (1787869771) [ 1595.898047] Lustre: lustre-MDT0000-mdc-ffff936e835a7000: Connection restored to 192.168.204.111@tcp (at 192.168.204.111@tcp) [ 1595.912193] Lustre: Skipped 16 previous similar messages [ 1606.352689] Lustre: DEBUG MARKER: == recovery-small test 21d: drop close reply while close and open are both in flight ========================================================== 18:30:02 (1787869802) [ 1637.527408] Lustre: DEBUG MARKER: == recovery-small test 21e: drop open reply while close and open are both in flight ========================================================== 18:30:34 (1787869834) [ 1775.584378] Lustre: 29643:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787869837/real 1787869837] req@ffff936e922c5680 x1874715737343616/t0(0) o36->lustre-MDT0000-mdc-ffff936e835a7000@192.168.204.111@tcp:12/10 lens 488/512 e 0 to 1 dl 1787869973 ref 2 fl Rpc:XQr/200/ffffffff rc 0/-1 job:'touch.0' uid:0 gid:0 projid:4294967295 [ 1775.643194] Lustre: 29643:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 15 previous similar messages [ 1776.918678] Lustre: DEBUG MARKER: == recovery-small test 21f: drop both reply while close and open are both in flight ========================================================== 18:32:54 (1787869974) [ 1808.423900] Lustre: DEBUG MARKER: == recovery-small test 21g: drop open reply and close request while close and open are both in flight ========================================================== 18:33:25 (1787870005) [ 1834.578927] Lustre: DEBUG MARKER: == recovery-small test 21h: drop open request and close reply while close and open are both in flight ========================================================== 18:33:51 (1787870031) [ 1861.699302] Lustre: DEBUG MARKER: == recovery-small test 22: drop close request and do mknod ========================================================== 18:34:18 (1787870058) [ 1888.054443] Lustre: DEBUG MARKER: == recovery-small test 23: client hang when close a file after mds crash ========================================================== 18:34:44 (1787870084) [ 1919.458273] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 192.168.204.111@tcp) was lost; in progress operations using this service will fail [ 1929.712104] Lustre: Evicted from MGS (at 192.168.204.111@tcp) after server handle changed from 0x4d25ce6b38ecd1c2 to 0x4d25ce6b38ecf80a [ 1943.669987] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1946.151044] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1955.330507] Lustre: DEBUG MARKER: == recovery-small test 24a: fsync error (should return error) ========================================================== 18:35:52 (1787870152) [ 1957.037922] LustreError: lustre-OST0000-osc-ffff936e835a7000: operation ost_write to node 192.168.204.111@tcp failed: rc = -107 [ 1957.076778] LustreError: lustre-OST0000-osc-ffff936e835a7000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 1957.106405] Lustre: 2348:0:(llite_lib.c:4352:ll_dirty_page_discard_warn()) lustre: dirty page discard: 192.168.204.111@tcp:/lustre/fid: [0x200000404:0x30:0x0]// may get corrupted (rc -5) [ 1967.377884] Lustre: DEBUG MARKER: == recovery-small test 24b: test dirty page discard due to client eviction ========================================================== 18:36:03 (1787870163) [ 1969.973318] LustreError: lustre-OST0000-osc-ffff936e835a7000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 1970.016350] Lustre: 2349:0:(llite_lib.c:4352:ll_dirty_page_discard_warn()) lustre: dirty page discard: 192.168.204.111@tcp:/lustre/fid: [0x200000404:0x35:0x0]// may get corrupted (rc -108) [ 1980.015824] Lustre: DEBUG MARKER: == recovery-small test 26a: evict dead exports =========== 18:36:16 (1787870176) [ 1982.808457] Lustre: DEBUG MARKER: SKIP: recovery-small test_26a msg and ost1 are at the same node [ 1985.244099] Lustre: DEBUG MARKER: == recovery-small test 26b: evict dead exports =========== 18:36:21 (1787870181) [ 1987.412046] Lustre: DEBUG MARKER: SKIP: recovery-small test_26b msg and ost1 are at the same node [ 1989.390958] Lustre: DEBUG MARKER: == recovery-small test 27: fail LOV while using OSC's ==== 18:36:26 (1787870186) [ 1993.569451] LustreError: lustre-MDT0000-mdc-ffff936e835a7000: operation ldlm_enqueue to node 192.168.204.111@tcp failed: rc = -19 [ 1993.577396] LustreError: Skipped 1 previous similar message [ 2013.669992] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 192.168.204.111@tcp) was lost; in progress operations using this service will fail [ 2023.916049] Lustre: Evicted from MGS (at 192.168.204.111@tcp) after server handle changed from 0x4d25ce6b38ecf80a to 0x4d25ce6b38ed0e92 [ 2128.436409] LustreError: lustre-MDT0000-mdc-ffff936e835a7000: operation mds_reint to node 192.168.204.111@tcp failed: rc = -19 [ 2144.737793] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 192.168.204.111@tcp) was lost; in progress operations using this service will fail [ 2154.921141] Lustre: Evicted from MGS (at 192.168.204.111@tcp) after server handle changed from 0x4d25ce6b38ed0e92 to 0x4d25ce6b38eec7ae [ 2156.980499] Lustre: 15921:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.204.111@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 2175.732082] Lustre: DEBUG MARKER: == recovery-small test 28: handle error adding new clients (bug 6086) ========================================================== 18:39:32 (1787870372) [ 2176.531573] Lustre: *** cfs_fail_loc=305, val=0*** [ 2176.535115] Lustre: Skipped 2 previous similar messages [ 2200.050412] Lustre: lustre-MDT0000-mdc-ffff936e835a7000: Connection to lustre-MDT0000 (at 192.168.204.111@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 2200.069974] Lustre: Skipped 12 previous similar messages [ 2220.550365] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 192.168.204.111@tcp) was lost; in progress operations using this service will fail [ 2220.587713] Lustre: Evicted from MGS (at 192.168.204.111@tcp) after server handle changed from 0x4d25ce6b38eec7ae to 0x4d25ce6b38eedc1b [ 2220.606927] Lustre: MGC192.168.204.111@tcp: Connection restored to 192.168.204.111@tcp (at 192.168.204.111@tcp) [ 2220.615870] Lustre: Skipped 13 previous similar messages [ 2238.164405] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2240.088837] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2249.998693] Lustre: DEBUG MARKER: == recovery-small test 29a: error adding new clients doesn't cause LBUG (bug 22273) ========================================================== 18:40:46 (1787870446) [ 2266.613948] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 192.168.204.111@tcp) was lost; in progress operations using this service will fail [ 2266.656997] Lustre: Evicted from MGS (at 192.168.204.111@tcp) after server handle changed from 0x4d25ce6b38eedc1b to 0x4d25ce6b38eee34c [ 2266.747581] LustreError: lustre-MDT0000-mdc-ffff936e835a7000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 2290.898509] Lustre: DEBUG MARKER: == recovery-small test 29b: error adding new clients doesn't cause LBUG (bug 22273) ========================================================== 18:41:27 (1787870487) [ 2306.121880] LustreError: lustre-OST0000-osc-ffff936e835a7000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 2330.079193] Lustre: DEBUG MARKER: == recovery-small test 50: failover MDS under load ======= 18:42:07 (1787870527) [ 2344.914937] LustreError: lustre-MDT0000-mdc-ffff936e835a7000: operation mds_reint to node 192.168.204.111@tcp failed: rc = -19 [ 2363.872670] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 192.168.204.111@tcp) was lost; in progress operations using this service will fail [ 2374.073363] Lustre: Evicted from MGS (at 192.168.204.111@tcp) after server handle changed from 0x4d25ce6b38eee34c to 0x4d25ce6b38ef28ab [ 2392.473976] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2395.334941] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2480.616674] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 192.168.204.111@tcp) was lost; in progress operations using this service will fail [ 2480.641202] Lustre: Evicted from MGS (at 192.168.204.111@tcp) after server handle changed from 0x4d25ce6b38ef28ab to 0x4d25ce6b38f0bdd9 [ 2482.678897] Lustre: 15921:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.204.111@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 2507.758824] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2510.122721] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2597.372059] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 192.168.204.111@tcp) was lost; in progress operations using this service will fail [ 2597.422431] Lustre: Evicted from MGS (at 192.168.204.111@tcp) after server handle changed from 0x4d25ce6b38f0bdd9 to 0x4d25ce6b38f23d0b [ 2616.129703] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2619.025162] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2649.750194] Lustre: DEBUG MARKER: == recovery-small test 51: failover MDS during recovery == 18:47:26 (1787870846) [ 2655.079226] LustreError: lustre-MDT0000-mdc-ffff936e835a7000: operation mds_reint to node 192.168.204.111@tcp failed: rc = -19 [ 2655.091041] LustreError: Skipped 4 previous similar messages [ 2675.616438] Lustre: 2346:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787870857/real 1787870857] req@ffff936e84fa1e00 x1874715742701696/t0(0) o400->MGC192.168.204.111@tcp@192.168.204.111@tcp:26/25 lens 224/224 e 0 to 1 dl 1787870873 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2675.656566] Lustre: 2346:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 11 previous similar messages [ 2675.666726] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 192.168.204.111@tcp) was lost; in progress operations using this service will fail [ 2684.861873] Lustre: Evicted from MGS (at 192.168.204.111@tcp) after server handle changed from 0x4d25ce6b38f23d0b to 0x4d25ce6b38f32753 [ 2703.089306] Lustre: DEBUG MARKER: test_51: failover in 1 sec [ 2736.116441] Lustre: 15921:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.204.111@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 2751.640540] Lustre: DEBUG MARKER: test_51: failover in 5 sec [ 2781.553744] Lustre: 15921:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.204.111@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 2798.264697] Lustre: DEBUG MARKER: test_51: failover in 10 sec [ 2811.253865] Lustre: lustre-MDT0000-mdc-ffff936e835a7000: Connection to lustre-MDT0000 (at 192.168.204.111@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 2811.267140] Lustre: Skipped 8 previous similar messages [ 2832.352404] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 192.168.204.111@tcp) was lost; in progress operations using this service will fail [ 2832.365720] LustreError: Skipped 2 previous similar messages [ 2842.546652] Lustre: Evicted from MGS (at 192.168.204.111@tcp) after server handle changed from 0x4d25ce6b38f397ae to 0x4d25ce6b38f3d67d [ 2842.561983] Lustre: Skipped 2 previous similar messages [ 2842.581966] Lustre: MGC192.168.204.111@tcp: Connection restored to 192.168.204.111@tcp (at 192.168.204.111@tcp) [ 2842.588925] Lustre: Skipped 16 previous similar messages [ 2849.796199] Lustre: DEBUG MARKER: test_51: failover in 20 sec [ 2910.957299] Lustre: DEBUG MARKER: test_51: failover in 25 sec [ 2976.524377] Lustre: DEBUG MARKER: test_51: failover in 30 sec [ 3077.303639] Lustre: DEBUG MARKER: == recovery-small test 52: failover OST under load ======= 18:54:33 (1787871273) [ 3138.343896] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 3140.696429] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 3423.347737] LustreError: lustre-OST0000-osc-ffff936e835a7000: operation ldlm_enqueue to node 192.168.204.111@tcp failed: rc = -107 [ 3423.367273] LustreError: Skipped 12 previous similar messages [ 3423.378431] Lustre: lustre-OST0000-osc-ffff936e835a7000: Connection to lustre-OST0000 (at 192.168.204.111@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 3423.418031] Lustre: Skipped 4 previous similar messages [ 3471.056552] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 3473.912992] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 3802.064159] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 3804.364879] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4049.855789] Lustre: DEBUG MARKER: == recovery-small test 53a: touch: drop rep ============== 19:10:46 (1787872246) [ 4066.784229] Lustre: 50551:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787872249/real 1787872249] req@ffff936e863a52c0 x1874715761670912/t0(0) o101->lustre-MDT0000-mdc-ffff936e835a7000@192.168.204.111@tcp:12/10 lens 576/1152 e 0 to 1 dl 1787872265 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'openfile.0' uid:0 gid:0 projid:0 [ 4066.826266] Lustre: 50551:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 5 previous similar messages [ 4066.838403] Lustre: lustre-MDT0000-mdc-ffff936e835a7000: Connection to lustre-MDT0000 (at 192.168.204.111@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 4066.853395] Lustre: Skipped 1 previous similar message [ 4066.895062] Lustre: lustre-MDT0000-mdc-ffff936e835a7000: Connection restored to 192.168.204.111@tcp (at 192.168.204.111@tcp) [ 4066.906474] Lustre: Skipped 8 previous similar messages [ 4075.061525] Lustre: DEBUG MARKER: == recovery-small test 53b: touch: drop rep ============== 19:11:12 (1787872272) [ 4100.011780] Lustre: DEBUG MARKER: == recovery-small test 53c: touch: drop rep ============== 19:11:36 (1787872296) [ 4125.850468] Lustre: DEBUG MARKER: == recovery-small test 54: back in time ================== 19:12:02 (1787872322) [ 4126.372821] Lustre: Mounted lustre-client - version 2.17.57_103_gb165317 [ 4158.432290] Lustre: 2348:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787872340/real 1787872340] req@ffff936e862c9a40 x1874715761687808/t0(0) o400->MGC192.168.204.111@tcp@192.168.204.111@tcp:26/25 lens 224/224 e 0 to 1 dl 1787872356 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4158.457996] Lustre: 2348:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 4 previous similar messages [ 4158.469237] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 192.168.204.111@tcp) was lost; in progress operations using this service will fail [ 4158.487608] LustreError: Skipped 3 previous similar messages [ 4158.526943] Lustre: Evicted from MGS (at 192.168.204.111@tcp) after server handle changed from 0x4d25ce6b38f592be to 0x4d25ce6b39096fc0 [ 4158.545180] Lustre: Skipped 3 previous similar messages [ 4158.567807] Lustre: MGC192.168.204.111@tcp: Connection restored to 192.168.204.111@tcp (at 192.168.204.111@tcp) [ 4158.580738] Lustre: Skipped 2 previous similar messages [ 4174.049931] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4175.474659] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4177.541569] Lustre: Unmounted lustre-client [ 4183.755553] Lustre: DEBUG MARKER: == recovery-small test 55: ost_brw_read/write drops timed-out read/write request ========================================================== 19:13:00 (1787872380) [ 4320.224455] Lustre: 2348:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787872502/real 1787872502] req@ffff936e84f7b480 x1874715761720576/t0(0) o4->lustre-OST0000-osc-ffff936e835a7000@192.168.204.111@tcp:6/4 lens 488/448 e 0 to 1 dl 1787872518 ref 2 fl Rpc:XQr/602/ffffffff rc -11/-1 job:'dd.0' uid:0 gid:0 projid:0 [ 4320.259661] Lustre: 2348:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 67 previous similar messages [ 4320.266090] Lustre: lustre-OST0000-osc-ffff936e835a7000: Connection restored to 192.168.204.111@tcp (at 192.168.204.111@tcp) [ 4320.278380] Lustre: Skipped 8 previous similar messages [ 4477.709791] Lustre: DEBUG MARKER: == recovery-small test 56: do not fail on getattr resend ========================================================== 19:17:54 (1787872674) [ 4526.777237] Lustre: DEBUG MARKER: == recovery-small test 57: read procfs entries causes kernel crash ========================================================== 19:18:43 (1787872723) [ 4530.638774] Lustre: Unmounted lustre-client [ 4552.248388] Lustre: Mounted lustre-client - version 2.17.57_103_gb165317 [ 4557.779573] Lustre: DEBUG MARKER: == recovery-small test 58: Eviction in the middle of open RPC reply processing ========================================================== 19:19:14 (1787872754) [ 4558.124220] LustreError: 56472:0:(mdc_locks.c:1337:mdc_finish_intent_lock()) cfs_fail_timeout id 801 sleeping for 20000ms [ 4559.179468] LustreError: 56472:0:(mdc_locks.c:1337:mdc_finish_intent_lock()) cfs_fail_timeout interrupted [ 4559.438429] Lustre: *** cfs_fail_loc=305, val=0*** [ 4583.605097] Lustre: DEBUG MARKER: == recovery-small test 59: Read cancel race on client eviction ========================================================== 19:19:40 (1787872780) [ 4584.167196] Lustre: Mounted lustre-client - version 2.17.57_103_gb165317 [ 4587.952618] Lustre: setting import lustre-MDT0000_UUID INACTIVE by administrator request [ 4598.327101] Lustre: Unmounted lustre-client [ 4607.519506] Lustre: DEBUG MARKER: == recovery-small test 60: Add Changelog entries during MDS failover ========================================================== 19:20:04 (1787872804) [ 4702.356781] LustreError: lustre-MDT0000-mdc-ffff936e85a72800: operation mds_reint to node 192.168.204.111@tcp failed: rc = -19 [ 4702.371992] LustreError: Skipped 1 previous similar message [ 4702.379042] Lustre: lustre-MDT0000-mdc-ffff936e85a72800: Connection to lustre-MDT0000 (at 192.168.204.111@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 4702.406375] Lustre: Skipped 23 previous similar messages [ 4719.584520] Lustre: 2348:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787872901/real 1787872901] req@ffff936e88f72d00 x1874715764399360/t0(0) o400->MGC192.168.204.111@tcp@192.168.204.111@tcp:26/25 lens 224/224 e 0 to 1 dl 1787872917 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4719.626463] Lustre: 2348:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 82 previous similar messages [ 4719.632650] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 192.168.204.111@tcp) was lost; in progress operations using this service will fail [ 4728.814398] Lustre: Evicted from MGS (at 192.168.204.111@tcp) after server handle changed from 0x4d25ce6b39098c92 to 0x4d25ce6b390c4455 [ 4728.833538] Lustre: MGC192.168.204.111@tcp: Connection restored to 192.168.204.111@tcp (at 192.168.204.111@tcp) [ 4728.845677] Lustre: Skipped 11 previous similar messages [ 4889.544851] Lustre: DEBUG MARKER: == recovery-small test 61: Verify to not reuse orphan objects - bug 17025 ========================================================== 19:24:46 (1787873086) [ 4894.895763] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4912.112828] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 192.168.204.111@tcp) was lost; in progress operations using this service will fail [ 4912.142306] Lustre: Evicted from MGS (at 192.168.204.111@tcp) after server handle changed from 0x4d25ce6b390c4455 to 0x4d25ce6b39110aca [ 4912.232889] LustreError: lustre-MDT0000-mdc-ffff936e85a72800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 4927.446991] Lustre: DEBUG MARKER: == recovery-small test 65: lock enqueue for destroyed export ========================================================== 19:25:24 (1787873124) [ 4928.057056] Lustre: Mounted lustre-client - version 2.17.57_103_gb165317 [ 4935.739207] LustreError: lustre-OST0000-osc-ffff936e85a72800: operation ldlm_enqueue to node 192.168.204.111@tcp failed: rc = -107 [ 4935.776756] LustreError: lustre-OST0000-osc-ffff936e85a72800: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 4949.156094] Lustre: Unmounted lustre-client [ 4959.187286] Lustre: DEBUG MARKER: == recovery-small test 66: lock enqueue re-send vs client eviction ========================================================== 19:25:55 (1787873155) [ 4966.181103] LustreError: lustre-MDT0000-mdc-ffff936e85a72800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 4966.192484] LustreError: 60862:0:(file.c:6184:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -5 [ 4974.820396] Lustre: DEBUG MARKER: == recovery-small test 67: connect vs import invalidate race ========================================================== 19:26:11 (1787873171) [ 4975.460221] LustreError: 61566:0:(recover.c:329:ptlrpc_recover_import()) cfs_race id 531 sleeping [ 4980.263900] LustreError: lustre-MDT0000-mdc-ffff936e85a72800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 4980.282759] LustreError: 61583:0:(import.c:293:ptlrpc_invalidate_import()) cfs_fail_race id 531 waking [ 4980.306504] LustreError: 61566:0:(recover.c:329:ptlrpc_recover_import()) cfs_fail_race id 531 awake: rc=170 [ 4980.321366] LustreError: 61566:0:(import.c:717:ptlrpc_connect_import_locked()) already connecting [ 4980.358253] LustreError: 61588:0:(file.c:6184:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 4981.476396] LustreError: 61594:0:(file.c:6184:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 4981.497186] LustreError: 61594:0:(file.c:6184:ll_inode_revalidate_fini()) Skipped 5 previous similar messages [ 4983.849650] LustreError: 61616:0:(file.c:6184:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 4983.870875] LustreError: 61616:0:(file.c:6184:ll_inode_revalidate_fini()) Skipped 13 previous similar messages [ 4988.797961] LustreError: 61661:0:(file.c:6184:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 4988.829082] LustreError: 61661:0:(file.c:6184:ll_inode_revalidate_fini()) Skipped 27 previous similar messages [ 5000.442467] Lustre: DEBUG MARKER: == recovery-small test 100: IR: Make sure normal recovery still works w/o IR ========================================================== 19:26:37 (1787873197) [ 5045.271172] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 5047.314532] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 5060.015448] Lustre: DEBUG MARKER: == recovery-small test 101a: IR: Make sure IR works w/o normal recovery ========================================================== 19:27:36 (1787873256) [ 5104.089623] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 5106.359676] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 5120.026874] Lustre: DEBUG MARKER: == recovery-small test 101b: IR: Make sure IR works w/o normal recovery and proceed EAGAIN ========================================================== 19:28:36 (1787873316) [ 5189.479846] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 5191.566490] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 5200.921691] Lustre: DEBUG MARKER: == recovery-small test 102: IR: New client gets updated nidtbl after MGS restart ========================================================== 19:29:57 (1787873397) [ 5240.492828] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 5242.093237] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 5249.561122] Lustre: Unmounted lustre-client [ 5308.993790] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 5312.385644] Lustre: Mounted lustre-client - version 2.17.57_103_gb165317 [ 5320.308254] Lustre: DEBUG MARKER: == recovery-small test 103: IR: MDS can start w/o MGS and get updated nidtbl later ========================================================== 19:31:56 (1787873516) [ 5323.141152] Lustre: DEBUG MARKER: SKIP: recovery-small test_103 needs separate mgs and mds [ 5325.217418] Lustre: DEBUG MARKER: == recovery-small test 104: IR: ost can disable IR voluntarily ========================================================== 19:32:01 (1787873521) [ 5360.139050] Lustre: DEBUG MARKER: == recovery-small test 105: IR: NON IR clients support === 19:32:36 (1787873556) [ 5362.212372] Lustre: DEBUG MARKER: SKIP: recovery-small test_105 Needs multiple clients [ 5364.113049] Lustre: DEBUG MARKER: == recovery-small test 106: lightweight connection support ========================================================== 19:32:40 (1787873560) [ 5365.768430] Lustre: *** cfs_fail_loc=805, val=0*** [ 5365.819261] Lustre: Mounted lustre-client - version 2.17.57_103_gb165317 [ 5371.395586] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5392.353866] Lustre: 2349:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787873574/real 1787873574] req@ffff936e922c4780 x1874715766452736/t0(0) o400->lustre-MDT0000-mdc-ffff936e862db000@192.168.204.111@tcp:12/10 lens 224/224 e 0 to 1 dl 1787873590 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5392.356563] Lustre: lustre-MDT0000-mdc-ffff936e8902f000: Connection to lustre-MDT0000 (at 192.168.204.111@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 5392.395170] Lustre: 2349:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 5392.442165] Lustre: Skipped 13 previous similar messages [ 5392.452681] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 192.168.204.111@tcp) was lost; in progress operations using this service will fail [ 5402.598536] Lustre: Evicted from MGS (at 192.168.204.111@tcp) after server handle changed from 0x4d25ce6b391114be to 0x4d25ce6b39111868 [ 5402.623616] LustreError: 2345:0:(ldlm_resource.c:1207:ldlm_resource_complain()) lustre-MDT0000-mdc-ffff936e862db000: namespace resource [0x200000007:0x1:0x0].0x0 (ffff936e98196600) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 5402.635512] Lustre: MGC192.168.204.111@tcp: Connection restored to 192.168.204.111@tcp (at 192.168.204.111@tcp) [ 5402.673190] Lustre: Skipped 13 previous similar messages [ 5406.832990] Lustre: Unmounted lustre-client [ 5416.443158] Lustre: DEBUG MARKER: == recovery-small test 107: drop reint reply, then restart MDT ========================================================== 19:33:33 (1787873613) [ 5450.602463] Lustre: 68238:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.204.111@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 5458.427145] LustreError: 2345:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff936e86b80b40 x1874715766464128/t94489280516(94489280516) o101->lustre-MDT0000-mdc-ffff936e8902f000@192.168.204.111@tcp:12/10 lens 648/608 e 0 to 0 dl 1787873672 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'multiop.0' uid:0 gid:0 projid:0 [ 5468.562363] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5470.755902] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5482.454038] Lustre: DEBUG MARKER: == recovery-small test 108: client eviction don't crash == 19:34:38 (1787873678) [ 5484.069146] LustreError: lustre-OST0000-osc-ffff936e8902f000: operation ost_write to node 192.168.204.111@tcp failed: rc = -107 [ 5484.078208] LustreError: Skipped 2 previous similar messages [ 5484.091413] LustreError: lustre-OST0000-osc-ffff936e8902f000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 5484.102962] Lustre: 2347:0:(llite_lib.c:4352:ll_dirty_page_discard_warn()) lustre: dirty page discard: 192.168.204.111@tcp:/lustre/fid: [0x20000a042:0x6:0x0]// may get corrupted (rc -5) [ 5484.124470] LustreError: 72779:0:(ldlm_resource.c:1207:ldlm_resource_complain()) lustre-OST0000-osc-ffff936e8902f000: namespace resource [0x240000400:0x3ce2:0x0].0x0 (ffff936e88e2ee00) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 5484.136289] LustreError: 72779:0:(ldlm_resource.c:1207:ldlm_resource_complain()) Skipped 1 previous similar message [ 5492.644262] Lustre: DEBUG MARKER: == recovery-small test 110a: create remote directory: drop client req ========================================================== 19:34:49 (1787873689) [ 5494.268102] Lustre: DEBUG MARKER: SKIP: recovery-small test_110a needs >= 2 MDTs [ 5495.952698] Lustre: DEBUG MARKER: == recovery-small test 110b: create remote directory: drop Master rep ========================================================== 19:34:52 (1787873692) [ 5497.662248] Lustre: DEBUG MARKER: SKIP: recovery-small test_110b needs >= 2 MDTs [ 5500.054912] Lustre: DEBUG MARKER: == recovery-small test 110c: create remote directory: drop update rep on slave MDT ========================================================== 19:34:56 (1787873696) [ 5501.745636] Lustre: DEBUG MARKER: SKIP: recovery-small test_110c needs >= 2 MDTs [ 5504.146705] Lustre: DEBUG MARKER: == recovery-small test 110d: remove remote directory: drop client req ========================================================== 19:35:00 (1787873700) [ 5506.248483] Lustre: DEBUG MARKER: SKIP: recovery-small test_110d needs >= 2 MDTs [ 5508.357782] Lustre: DEBUG MARKER: == recovery-small test 110e: remove remote directory: drop master rep ========================================================== 19:35:04 (1787873704) [ 5510.338538] Lustre: DEBUG MARKER: SKIP: recovery-small test_110e needs >= 2 MDTs [ 5512.710606] Lustre: DEBUG MARKER: == recovery-small test 110f: remove remote directory: drop slave rep ========================================================== 19:35:09 (1787873709) [ 5514.305039] Lustre: DEBUG MARKER: SKIP: recovery-small test_110f needs >= 2 MDTs [ 5516.497895] Lustre: DEBUG MARKER: == recovery-small test 110g: drop reply during migration ========================================================== 19:35:13 (1787873713) [ 5518.425279] Lustre: DEBUG MARKER: SKIP: recovery-small test_110g needs >= 2 MDTs [ 5520.401883] Lustre: DEBUG MARKER: == recovery-small test 110h: drop update reply during cross-MDT file rename ========================================================== 19:35:17 (1787873717) [ 5522.848909] Lustre: DEBUG MARKER: SKIP: recovery-small test_110h needs >= 2 MDTs [ 5525.058906] Lustre: DEBUG MARKER: == recovery-small test 110i: drop update reply during cross-MDT dir rename ========================================================== 19:35:21 (1787873721) [ 5527.499429] Lustre: DEBUG MARKER: SKIP: recovery-small test_110i needs >= 2 MDTs [ 5530.166994] Lustre: DEBUG MARKER: == recovery-small test 110j: drop update reply during cross-MDT ln ========================================================== 19:35:26 (1787873726) [ 5532.414657] Lustre: DEBUG MARKER: SKIP: recovery-small test_110j needs >= 2 MDTs [ 5534.379442] Lustre: DEBUG MARKER: == recovery-small test 110k: FID_QUERY failed during recovery ========================================================== 19:35:31 (1787873731) [ 5536.650556] Lustre: DEBUG MARKER: SKIP: recovery-small test_110k needs >= 2 MDTS [ 5539.507433] Lustre: DEBUG MARKER: == recovery-small test 110m: update resent vs original RPC race ========================================================== 19:35:35 (1787873735) [ 5542.745685] Lustre: DEBUG MARKER: SKIP: recovery-small test_110m needs at least 2 MDTs [ 5544.674558] Lustre: DEBUG MARKER: == recovery-small test 111: mdd setup fail should not cause umount oops ========================================================== 19:35:41 (1787873741) [ 5579.780731] Lustre: DEBUG MARKER: == recovery-small test 112a: bulk resend while orignal request is in progress ========================================================== 19:36:16 (1787873776) [ 5609.565944] Lustre: DEBUG MARKER: == recovery-small test 115a: read: late REQ MDunlink and no bulk ========================================================== 19:36:46 (1787873806) [ 5610.261627] Lustre: *** cfs_fail_loc=51b, val=3*** [ 5620.816115] Lustre: DEBUG MARKER: == recovery-small test 115b: write: late REQ MDunlink and no bulk ========================================================== 19:36:57 (1787873817) [ 5621.240769] Lustre: *** cfs_fail_loc=51b, val=4*** [ 5633.496834] Lustre: DEBUG MARKER: == recovery-small test 115c: read: late Reply MDunlink and no bulk ========================================================== 19:37:09 (1787873829) [ 5633.796960] Lustre: *** cfs_fail_loc=50f, val=3*** [ 5643.988434] Lustre: DEBUG MARKER: == recovery-small test 115d: write: late Reply MDunlink and no bulk ========================================================== 19:37:20 (1787873840) [ 5644.318048] Lustre: *** cfs_fail_loc=50f, val=4*** [ 5655.039638] Lustre: DEBUG MARKER: == recovery-small test 115e: read: late Bulk MDunlink and no reply ========================================================== 19:37:31 (1787873851) [ 5655.294471] Lustre: *** cfs_fail_loc=510, val=3*** [ 5667.018884] Lustre: DEBUG MARKER: == recovery-small test 115f: read: late REQ MDunlink and no reply ========================================================== 19:37:43 (1787873863) [ 5667.616134] Lustre: *** cfs_fail_loc=51b, val=3*** [ 5735.006105] Lustre: DEBUG MARKER: == recovery-small test 115g: read: late REQ MDunlink and Reply MDunlink ========================================================== 19:38:51 (1787873931) [ 5735.563071] Lustre: *** cfs_fail_loc=51c, val=3*** [ 5801.644897] Lustre: DEBUG MARKER: == recovery-small test 120: flock race: completion vs. evict ========================================================== 19:39:58 (1787873998) [ 5802.044066] LustreError: 82997:0:(ldlm_flock.c:803:ldlm_flock_completion_ast()) cfs_fail_timeout id 320 sleeping for 4000ms [ 5805.058914] LustreError: lustre-MDT0000-mdc-ffff936e8902f000: operation ldlm_enqueue to node 192.168.204.111@tcp failed: rc = -107 [ 5805.095451] LustreError: lustre-MDT0000-mdc-ffff936e8902f000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5805.120453] LustreError: 83013:0:(file.c:251:ll_close_inode_openhandle()) lustre-clilmv-ffff936e8902f000: inode [0x20000a042:0xb:0x0] mdc close failed: rc = -108 [ 5805.159904] LustreError: 83013:0:(ldlm_resource.c:1207:ldlm_resource_complain()) lustre-MDT0000-mdc-ffff936e8902f000: namespace resource [0x20000a042:0x11:0x0].0xc (ffff936e84329400) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 5806.120469] LustreError: 82997:0:(ldlm_flock.c:803:ldlm_flock_completion_ast()) cfs_fail_timeout id 320 awake [ 5808.217070] LustreError: 83028:0:(ldlm_flock.c:803:ldlm_flock_completion_ast()) cfs_fail_timeout id 320 sleeping for 4000ms [ 5811.205277] LustreError: lustre-MDT0000-mdc-ffff936e8902f000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5811.228873] LustreError: 83042:0:(ldlm_resource.c:1207:ldlm_resource_complain()) lustre-MDT0000-mdc-ffff936e8902f000: namespace resource [0x200000007:0x1:0x0].0x0 (ffff936e98130600) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 5811.257291] LustreError: 83042:0:(ldlm_resource.c:1207:ldlm_resource_complain()) Skipped 1 previous similar message [ 5812.280235] LustreError: 83028:0:(ldlm_flock.c:803:ldlm_flock_completion_ast()) cfs_fail_timeout id 320 awake [ 5819.093815] LustreError: lustre-MDT0000-mdc-ffff936e8902f000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5819.604650] LustreError: 83084:0:(ldlm_flock.c:808:ldlm_flock_completion_ast()) cfs_fail_timeout id 321 sleeping for 4000ms [ 5822.573901] LustreError: lustre-MDT0000-mdc-ffff936e8902f000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5822.627704] LustreError: 83104:0:(file.c:6184:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 5822.632695] LustreError: 83104:0:(file.c:6184:ll_inode_revalidate_fini()) Skipped 13 previous similar messages [ 5823.672355] LustreError: 83084:0:(ldlm_flock.c:808:ldlm_flock_completion_ast()) cfs_fail_timeout id 321 awake [ 5823.683045] LustreError: 83110:0:(file.c:6184:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 5823.683533] LustreError: 83084:0:(file.c:251:ll_close_inode_openhandle()) lustre-clilmv-ffff936e8902f000: inode [0x20000a042:0x11:0x0] mdc close failed: rc = -108 [ 5823.688352] LustreError: 83110:0:(file.c:6184:ll_inode_revalidate_fini()) Skipped 5 previous similar messages [ 5825.882145] LustreError: 83132:0:(file.c:6184:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 5825.888627] LustreError: 83132:0:(file.c:6184:ll_inode_revalidate_fini()) Skipped 13 previous similar messages [ 5829.407585] LustreError: 83159:0:(ldlm_flock.c:808:ldlm_flock_completion_ast()) cfs_fail_timeout id 321 sleeping for 4000ms [ 5832.447627] LustreError: lustre-MDT0000-mdc-ffff936e8902f000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5832.469372] LustreError: 83174:0:(ldlm_resource.c:1207:ldlm_resource_complain()) lustre-MDT0000-mdc-ffff936e8902f000: namespace resource [0x20000a042:0x11:0x0].0xc (ffff936e98130200) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 5832.504216] LustreError: 83174:0:(ldlm_resource.c:1207:ldlm_resource_complain()) Skipped 2 previous similar messages [ 5833.480145] LustreError: 83159:0:(ldlm_flock.c:808:ldlm_flock_completion_ast()) cfs_fail_timeout id 321 awake [ 5840.477634] LustreError: lustre-MDT0000-mdc-ffff936e8902f000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5840.848146] LustreError: 83215:0:(ldlm_flock.c:857:ldlm_flock_completion_ast()) cfs_fail_timeout id 322 sleeping for 4000ms [ 5843.942373] LustreError: lustre-MDT0000-mdc-ffff936e8902f000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5843.955555] LustreError: 83230:0:(ldlm_resource.c:1207:ldlm_resource_complain()) lustre-MDT0000-mdc-ffff936e8902f000: namespace resource [0x20000a042:0x11:0x0].0xc (ffff936e98130c00) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 5843.977967] LustreError: 83230:0:(ldlm_resource.c:1207:ldlm_resource_complain()) Skipped 1 previous similar message [ 5844.936124] LustreError: 83215:0:(ldlm_flock.c:857:ldlm_flock_completion_ast()) cfs_fail_timeout id 322 awake [ 5848.102549] LustreError: lustre-MDT0000-mdc-ffff936e8902f000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5848.213651] LustreError: 83263:0:(file.c:6184:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 5848.223290] LustreError: 83263:0:(file.c:6184:ll_inode_revalidate_fini()) Skipped 6 previous similar messages [ 5849.224905] LustreError: 83243:0:(file.c:251:ll_close_inode_openhandle()) lustre-clilmv-ffff936e8902f000: inode [0x20000a042:0x11:0x0] mdc close failed: rc = -108 [ 5857.331326] LustreError: 83315:0:(ldlm_flock.c:803:ldlm_flock_completion_ast()) cfs_fail_timeout id 320 sleeping for 4000ms [ 5857.346952] LustreError: 83315:0:(ldlm_flock.c:803:ldlm_flock_completion_ast()) Skipped 1 previous similar message [ 5861.052452] LustreError: lustre-MDT0000-mdc-ffff936e8902f000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5861.116259] LustreError: 83337:0:(file.c:6184:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 5861.125689] LustreError: 83337:0:(file.c:6184:ll_inode_revalidate_fini()) Skipped 26 previous similar messages [ 5861.424984] LustreError: 83315:0:(ldlm_flock.c:803:ldlm_flock_completion_ast()) cfs_fail_timeout id 320 awake [ 5861.436389] LustreError: 83315:0:(ldlm_flock.c:803:ldlm_flock_completion_ast()) Skipped 1 previous similar message [ 5861.455458] LustreError: 83315:0:(file.c:251:ll_close_inode_openhandle()) lustre-clilmv-ffff936e8902f000: inode [0x20000a042:0x11:0x0] mdc close failed: rc = -108 [ 5873.258422] Lustre: DEBUG MARKER: == recovery-small test 113: ldlm enqueue dropped reply should not cause deadlocks ========================================================== 19:41:09 (1787874069) [ 5892.758648] LustreError: 68235:0:(ldlm_lockd.c:2890:ldlm_bl_thread_blwi()) cfs_fail_timeout id 31f sleeping for 4000ms [ 5892.765439] LustreError: 68235:0:(ldlm_lockd.c:2890:ldlm_bl_thread_blwi()) Skipped 1 previous similar message [ 5896.824628] LustreError: 68235:0:(ldlm_lockd.c:2890:ldlm_bl_thread_blwi()) cfs_fail_timeout id 31f awake [ 5896.838447] LustreError: 68235:0:(ldlm_lockd.c:2890:ldlm_bl_thread_blwi()) Skipped 1 previous similar message [ 5903.873388] Lustre: DEBUG MARKER: == recovery-small test 130a: enqueue resend on not existing file ========================================================== 19:41:41 (1787874101) [ 5956.622750] Lustre: DEBUG MARKER: == recovery-small test 130b: enqueue resend on a stale inode ========================================================== 19:42:33 (1787874153) [ 6014.946575] Lustre: 85494:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787874157/real 1787874157] req@ffff936e86b82580 x1874715766594560/t0(0) o101->lustre-MDT0000-mdc-ffff936e8902f000@192.168.204.111@tcp:12/10 lens 576/1152 e 0 to 1 dl 1787874213 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'stat.0' uid:0 gid:0 projid:0 [ 6014.971090] Lustre: 85494:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 18 previous similar messages [ 6014.977540] Lustre: lustre-MDT0000-mdc-ffff936e8902f000: Connection to lustre-MDT0000 (at 192.168.204.111@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 6014.987867] Lustre: Skipped 16 previous similar messages [ 6014.997463] Lustre: lustre-MDT0000-mdc-ffff936e8902f000: Connection restored to 192.168.204.111@tcp (at 192.168.204.111@tcp) [ 6015.008124] Lustre: Skipped 16 previous similar messages [ 6021.766630] Lustre: DEBUG MARKER: == recovery-small test 130c: layout intent resend on a stale inode ========================================================== 19:43:38 (1787874218) [ 6055.837395] Lustre: DEBUG MARKER: == recovery-small test 132: long punch =================== 19:44:12 (1787874252) [ 6056.175281] Lustre: Mounted lustre-client - version 2.17.57_103_gb165317 [ 6180.264143] Lustre: Unmounted lustre-client [ 6188.525840] Lustre: DEBUG MARKER: == recovery-small test 131: IO vs evict results to IO under staled lock ========================================================== 19:46:25 (1787874385) [ 6189.189506] LustreError: 87650:0:(osc_request.c:3192:osc_build_rpc()) cfs_fail_timeout id 414 sleeping for 10000ms [ 6192.060387] LustreError: lustre-OST0000-osc-ffff936e8902f000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 6192.085225] LustreError: 87737:0:(ldlm_resource.c:1207:ldlm_resource_complain()) lustre-OST0000-osc-ffff936e8902f000: namespace resource [0x240000400:0x3d0d:0x0].0x0 (ffff936e84329a00) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 6192.110733] LustreError: 87737:0:(ldlm_resource.c:1207:ldlm_resource_complain()) Skipped 1 previous similar message [ 6192.360222] LustreError: 87650:0:(osc_request.c:3192:osc_build_rpc()) cfs_fail_timeout interrupted [ 6192.377991] Lustre: 2349:0:(llite_lib.c:4352:ll_dirty_page_discard_warn()) lustre: dirty page discard: 192.168.204.111@tcp:/lustre/fid: [0x20000bf89:0x9:0x0]// may get corrupted (rc -108) [ 6199.280743] Lustre: DEBUG MARKER: == recovery-small test 133: don't fail on flock resend === 19:46:35 (1787874395) [ 6266.487443] Lustre: DEBUG MARKER: == recovery-small test 134: race between failover and search for reply data free slot ========================================================== 19:47:43 (1787874463) [ 6268.135893] Lustre: DEBUG MARKER: SKIP: recovery-small test_134 Need 2+ clients, have 1 [ 6269.984247] Lustre: DEBUG MARKER: == recovery-small test 135: DOM: open/create resend to return size ========================================================== 19:47:46 (1787874466) [ 6334.999606] Lustre: DEBUG MARKER: SKIP: recovery-small test_136 skipping excluded test 136 [ 6336.833539] Lustre: DEBUG MARKER: == recovery-small test 137: late resend must be skipped if already applied ========================================================== 19:48:53 (1787874533) [ 6395.588838] Lustre: DEBUG MARKER: == recovery-small test 138: Umount MDT during recovery === 19:49:52 (1787874592) [ 6398.096750] Lustre: DEBUG MARKER: SKIP: recovery-small test_138 needs >= 2 MDTs [ 6400.184315] Lustre: DEBUG MARKER: == recovery-small test 139: corrupted catid won't cause crash ========================================================== 19:49:56 (1787874596) [ 6401.774653] Lustre: DEBUG MARKER: SKIP: recovery-small test_139 needs >= 2 MDTs [ 6403.729736] Lustre: DEBUG MARKER: == recovery-small test 140a: local mount is flagged properly ========================================================== 19:50:00 (1787874600) [ 6444.717600] Lustre: DEBUG MARKER: == recovery-small test 140b: local mount is excluded from recovery ========================================================== 19:50:41 (1787874641) [ 6458.420884] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 6485.989597] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 192.168.204.111@tcp) was lost; in progress operations using this service will fail [ 6486.011256] LustreError: Skipped 2 previous similar messages [ 6496.297101] Lustre: Evicted from MGS (at 192.168.204.111@tcp) after server handle changed from 0x4d25ce6b391122fd to 0x4d25ce6b39113dd7 [ 6496.320715] Lustre: Skipped 2 previous similar messages [ 6502.039845] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6503.749217] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6515.887831] Lustre: DEBUG MARKER: == recovery-small test 141: do not lose locks on MGS restart ========================================================== 19:51:52 (1787874712) [ 6518.938283] Lustre: DEBUG MARKER: SKIP: recovery-small test_141 cannot run in local mode or from build tree [ 6521.068661] Lustre: DEBUG MARKER: == recovery-small test 142: orphan name stub can be cleaned up in startup ========================================================== 19:51:57 (1787874717) [ 6537.194679] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 192.168.204.111@tcp) was lost; in progress operations using this service will fail [ 6537.251189] Lustre: Evicted from MGS (at 192.168.204.111@tcp) after server handle changed from 0x4d25ce6b39113dd7 to 0x4d25ce6b39113fe4 [ 6550.706500] Lustre: DEBUG MARKER: == recovery-small test 143: orphan cleanup thread shouldn't be blocked even delete failed ========================================================== 19:52:27 (1787874747) [ 6605.872448] Lustre: DEBUG MARKER: == recovery-small test 144a: MDT failover should stop precreation threads ========================================================== 19:53:22 (1787874802) [ 6614.794577] LustreError: lustre-OST0000-osc-ffff936e8902f000: operation ost_setattr to node 192.168.204.111@tcp failed: rc = -107 [ 6614.807967] LustreError: Skipped 9 previous similar messages [ 6667.219840] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 6671.662916] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 6757.346258] Lustre: 2348:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787874939/real 1787874939] req@ffff936ea7849e00 x1874715773161216/t0(0) o400->MGC192.168.204.111@tcp@192.168.204.111@tcp:26/25 lens 224/224 e 0 to 1 dl 1787874955 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6757.389664] Lustre: 2348:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 15 previous similar messages [ 6757.400336] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 192.168.204.111@tcp) was lost; in progress operations using this service will fail [ 6757.409106] LustreError: Skipped 1 previous similar message [ 6757.428072] Lustre: lustre-MDT0000-mdc-ffff936e8902f000: Connection to lustre-MDT0000 (at 192.168.204.111@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 6757.429917] Lustre: Evicted from MGS (at 192.168.204.111@tcp) after server handle changed from 0x4d25ce6b391142df to 0x4d25ce6b39115053 [ 6757.441354] Lustre: Skipped 8 previous similar messages [ 6757.449406] Lustre: Skipped 1 previous similar message [ 6757.458818] Lustre: MGC192.168.204.111@tcp: Connection restored to 192.168.204.111@tcp (at 192.168.204.111@tcp) [ 6757.465833] Lustre: Skipped 10 previous similar messages [ 6770.755585] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6772.419904] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6874.199797] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6875.408446] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7003.339716] Lustre: DEBUG MARKER: == recovery-small test 144b: orphan cleanup shouldn't be blocked for no objects+failover situation ========================================================== 20:00:00 (1787875200) [ 7073.710052] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 7091.441904] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 7347.519219] Lustre: DEBUG MARKER: == recovery-small test 144c: reconnection during orphan cleanup shouldn't lose LAST_ID synchronization ========================================================== 20:05:44 (1787875544) [ 7514.085299] Lustre: lustre-MDT0000-mdc-ffff936e8902f000: Connection to lustre-MDT0000 (at 192.168.204.111@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 7514.100082] Lustre: Skipped 2 previous similar messages [ 7529.446640] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 192.168.204.111@tcp) was lost; in progress operations using this service will fail [ 7529.462905] LustreError: Skipped 1 previous similar message [ 7529.483184] Lustre: Evicted from MGS (at 192.168.204.111@tcp) after server handle changed from 0x4d25ce6b3911544a to 0x4d25ce6b3920c123 [ 7529.492045] Lustre: Skipped 1 previous similar message [ 7529.499631] Lustre: MGC192.168.204.111@tcp: Connection restored to 192.168.204.111@tcp (at 192.168.204.111@tcp) [ 7529.506192] Lustre: Skipped 3 previous similar messages [ 7560.312505] Lustre: DEBUG MARKER: == recovery-small test 145: connect mdtlovs and process update logs after recovery expire ========================================================== 20:09:17 (1787875757) [ 7561.848212] Lustre: DEBUG MARKER: SKIP: recovery-small test_145 needs >= 3 MDTs [ 7563.679132] Lustre: DEBUG MARKER: == recovery-small test 146: test eviction is counted properly ========================================================== 20:09:20 (1787875760) [ 7565.585397] LustreError: lustre-MDT0000-mdc-ffff936e8902f000: operation ldlm_enqueue to node 192.168.204.111@tcp failed: rc = -107 [ 7565.594680] LustreError: Skipped 66 previous similar messages [ 7565.610971] LustreError: lustre-MDT0000-mdc-ffff936e8902f000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 7572.617370] Lustre: DEBUG MARKER: == recovery-small test 147: Check client reconnect ======= 20:09:29 (1787875769) [ 7739.889288] Lustre: Evicted from lustre-OST0000_UUID (at 192.168.204.111@tcp) after server handle changed from 0x4d25ce6b3920c9f1 to 0x4d25ce6b3920cafb [ 7739.903084] LustreError: lustre-OST0000-osc-ffff936e8902f000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 7743.101973] Lustre: DEBUG MARKER: == recovery-small test 148: data corruption through resend ========================================================== 20:12:19 (1787875939) [ 7773.664257] Lustre: 2347:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787875951/real 1787875951] req@ffff936e8a138780 x1874715784095232/t0(0) o4->lustre-OST0000-osc-ffff936e8902f000@192.168.204.111@tcp:6/4 lens 4584/448 e 0 to 1 dl 1787875971 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'dd.0' uid:0 gid:0 projid:0 [ 7773.707557] Lustre: 2347:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 13 previous similar messages [ 7791.786077] Lustre: DEBUG MARKER: == recovery-small test 149: skip orphan removal at umount ========================================================== 20:13:08 (1787875988) [ 7793.707596] Lustre: DEBUG MARKER: SKIP: recovery-small test_149 needs >= 2 MDTs [ 7795.408596] Lustre: DEBUG MARKER: == recovery-small test 150: statfs when MDT0 offline with lazystatfs option ========================================================== 20:13:12 (1787875992) [ 7797.190321] Lustre: DEBUG MARKER: SKIP: recovery-small test_150 needs >= 2 MDTs [ 7799.045948] Lustre: DEBUG MARKER: == recovery-small test 152: QoS object allocation could be awakened in case of OST failover ========================================================== 20:13:15 (1787875995) [ 7841.018675] Lustre: DEBUG MARKER: == recovery-small test 153: evict vs reconnect race ====== 20:13:57 (1787876037) [ 7881.208098] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 192.168.204.111@tcp) was lost; in progress operations using this service will fail [ 7881.256215] Lustre: Evicted from MGS (at 192.168.204.111@tcp) after server handle changed from 0x4d25ce6b3920c123 to 0x4d25ce6b3920ee48 [ 7898.009535] Lustre: DEBUG MARKER: == recovery-small test 154a: corruption update llog can be skipped ========================================================== 20:14:54 (1787876094) [ 7899.567614] Lustre: DEBUG MARKER: SKIP: recovery-small test_154a needs >= 2 MDTs [ 7901.407661] Lustre: DEBUG MARKER: == recovery-small test 154b: restore update llog after failed recovery ========================================================== 20:14:58 (1787876098) [ 7903.016399] Lustre: DEBUG MARKER: SKIP: recovery-small test_154b needs >= 2 MDTs [ 7904.472583] Lustre: DEBUG MARKER: == recovery-small test 155: failover after client remount ========================================================== 20:15:01 (1787876101) [ 7915.040855] Lustre: Unmounted lustre-client [ 7916.994076] Lustre: Mounted lustre-client - version 2.17.57_103_gb165317 [ 7919.805678] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 7938.528540] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 192.168.204.111@tcp) was lost; in progress operations using this service will fail [ 7947.756318] Lustre: Evicted from MGS (at 192.168.204.111@tcp) after server handle changed from 0x4d25ce6b3920f820 to 0x4d25ce6b3920f874 [ 7949.105515] Lustre: 106799:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.204.111@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 7965.078596] Lustre: DEBUG MARKER: == recovery-small test 156: tot_granted miscount after client eviction ========================================================== 20:16:02 (1787876162) [ 7971.611881] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-OST0000 [ 7993.877303] LustreError: 2345:0:(client.c:3533:ptlrpc_replay_req()) cfs_fail_timeout id 536 sleeping for 45000ms [ 8038.936250] LustreError: 2345:0:(client.c:3533:ptlrpc_replay_req()) cfs_fail_timeout id 536 awake [ 8038.966717] LustreError: lustre-OST0000-osc-ffff936e85a77000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 8045.166890] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 8047.319856] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 8061.576500] Lustre: DEBUG MARKER: == recovery-small test 157: eviction during mmaped i/o === 20:17:38 (1787876258) [ 8062.616344] LustreError: 109189:0:(vvp_io.c:1530:vvp_io_fault_start()) cfs_fail_timeout id 1432 sleeping for 3000ms [ 8065.664142] LustreError: 109189:0:(vvp_io.c:1530:vvp_io_fault_start()) cfs_fail_timeout id 1432 awake [ 8065.712816] LustreError: lustre-OST0000-osc-ffff936e85a77000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 8065.756271] LustreError: 109203:0:(ldlm_resource.c:1207:ldlm_resource_complain()) lustre-OST0000-osc-ffff936e85a77000: namespace resource [0x240000401:0x2303:0x0].0x0 (ffff936e87d27f00) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 8073.105908] Lustre: DEBUG MARKER: == recovery-small test 158a: connect without access right ========================================================== 20:17:50 (1787876270) [ 8075.026452] Lustre: DEBUG MARKER: SKIP: recovery-small test_158a needs >= 2 MDTS [ 8076.955592] Lustre: DEBUG MARKER: == recovery-small test 160: MDT destroys are blocked by grouplocks ========================================================== 20:17:53 (1787876273) [ 8080.497643] LustreError: lustre-MDT0000-mdc-ffff936e85a77000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 8132.678285] Lustre: DEBUG MARKER: == recovery-small test 161: evict osp by ping evictor ==== 20:18:49 (1787876329) [ 8134.169323] Lustre: DEBUG MARKER: SKIP: recovery-small test_161 needs >= 2 MDTs [ 8135.772855] Lustre: DEBUG MARKER: == recovery-small test 162: File attributes should be persisted after MDS failover ========================================================== 20:18:52 (1787876332) [ 8148.457135] Lustre: lustre-MDT0000-mdc-ffff936e85a77000: Connection to lustre-MDT0000 (at 192.168.204.111@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 8148.478208] Lustre: Skipped 8 previous similar messages [ 8148.511112] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 192.168.204.111@tcp) was lost; in progress operations using this service will fail [ 8148.540684] Lustre: Evicted from MGS (at 192.168.204.111@tcp) after server handle changed from 0x4d25ce6b3920f874 to 0x4d25ce6b39210d90 [ 8148.561575] Lustre: MGC192.168.204.111@tcp: Connection restored to 192.168.204.111@tcp (at 192.168.204.111@tcp) [ 8148.569979] LustreError: 2345:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff936e980fda40 x1874715784375424/t137438953528(137438953528) o101->lustre-MDT0000-mdc-ffff936e85a77000@192.168.204.111@tcp:12/10 lens 576/608 e 0 to 0 dl 1787876386 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'chattr.0' uid:0 gid:0 projid:0 [ 8148.571126] Lustre: Skipped 9 previous similar messages [ 8165.565723] Lustre: DEBUG MARKER: == recovery-small test 163: changelog check for fail write and processing records ========================================================== 20:19:22 (1787876362) [ 8184.091492] Lustre: DEBUG MARKER: == recovery-small test 170: Reconnect after REPLAY_LOCKS hangs (LU-18154) ========================================================== 20:19:40 (1787876380) [ 8188.349616] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-OST0000 [ 8222.436573] Lustre: *** cfs_fail_loc=537, val=0*** [ 8225.524204] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 60 0 [ 8227.509527] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 8235.806349] Lustre: DEBUG MARKER: == recovery-small test complete, duration 7998 sec ======= 20:20:32 (1787876432) [ 8237.689256] Lustre: DEBUG MARKER: === recovery-small: start cleanup 20:20:34 (1787876434) === [ 8562.899397] Lustre: DEBUG MARKER: === recovery-small: finish cleanup 20:25:59 (1787876759) === [ 8581.601195] Lustre: 2347:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787876763/real 1787876763] req@ffff936e8ac212c0 x1874715788167296/t0(0) o400->MGC192.168.204.111@tcp@192.168.204.111@tcp:26/25 lens 224/224 e 0 to 1 dl 1787876779 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 8581.623079] Lustre: 2347:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 11 previous similar messages [ 8581.631468] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 192.168.204.111@tcp) was lost; in progress operations using this service will fail [ 8590.951987] Lustre: Evicted from MGS (at 192.168.204.111@tcp) after server handle changed from 0x4d25ce6b39210d90 to 0x4d25ce6b392a2cb1 [ 8600.570443] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 8602.138683] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8605.878073] Lustre: Unmounted lustre-client [ 8643.691488] Key type lgssc unregistered [ 8644.006918] LNet: 115871:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 8644.017478] LNetError: 115871:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 8644.040809] LNet: Removed LNI 192.168.204.11@tcp [ 8644.666527] Key type .llcrypt unregistered [ 8644.668982] Key type ._llcrypt unregistered