[ 0.000000] Linux version 4.18.0rh8.10-debug (green@maintenance) (gcc version 8.5.0 20210514 (Red Hat 8.5.0-26) (GCC)) #2 SMP Mon Jul 14 01:24:22 EDT 2025 [ 0.000000] Command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers' [ 0.000000] x86/fpu: xstate_offset[2]: 576, xstate_sizes[2]: 256 [ 0.000000] x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'standard' format. [ 0.000000] signal: max sigframe size: 1776 [ 0.000000] BIOS-provided physical RAM map: [ 0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable [ 0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000000100000-0x00000000bffd9fff] usable [ 0.000000] BIOS-e820: [mem 0x00000000bffda000-0x00000000bfffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000100000000-0x0000000146dfffff] usable [ 0.000000] NX (Execute Disable) protection: active [ 0.000000] SMBIOS 2.8 present. [ 0.000000] DMI: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.16.2-1.fc38 04/01/2014 [ 0.000000] Hypervisor detected: KVM [ 0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00 [ 0.000000] kvm-clock: using sched offset of 451787452 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2399.998 MHz processor [ 0.000000] last_pfn = 0x146e00 max_arch_pfn = 0x400000000 [ 0.000000] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT [ 0.000000] last_pfn = 0xbffda max_arch_pfn = 0x400000000 [ 0.000000] found SMP MP-table at [mem 0x000f5b50-0x000f5b5f] [ 0.000000] RAMDISK: [mem 0xbcc64000-0xbffcffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F5970 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE1BB7 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE1A53 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 001A13 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE1AC7 000090 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE1B57 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE1B8F 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe1a53-0xbffe1ac6] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe1a52] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe1ac7-0xbffe1b56] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe1b57-0xbffe1b8e] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe1b8f-0xbffe1bb6] [ 0.000000] No NUMA configuration found [ 0.000000] Faking a node at [mem 0x0000000000000000-0x0000000146dfffff] [ 0.000000] NODE_DATA(0) allocated [mem 0x1465a3000-0x1465cdfff] [ 0.000000] Reserving 256MB of memory at 2752MB for crashkernel (System RAM: 4205MB) [ 0.000000] Zone ranges: [ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.000000] DMA32 [mem 0x0000000001000000-0x00000000ffffffff] [ 0.000000] Normal [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Device empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff] [ 0.000000] node 0: [mem 0x0000000000100000-0x00000000bffd9fff] [ 0.000000] node 0: [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Zeroed struct page in unavailable ranges: 4744 pages [ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x0000000146dfffff] [ 0.000000] ACPI: PM-Timer IO Port: 0x608 [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) [ 0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) [ 0.000000] Using ACPI (MADT) for SMP configuration information [ 0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000] TSC deadline timer available [ 0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs [ 0.000000] kvm-guest: KVM setup pv remote TLB flush [ 0.000000] kvm-guest: setup PV sched yield [ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff] [ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff] [ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff] [ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff] [ 0.000000] PM: Registered nosave memory: [mem 0xbffda000-0xbfffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xc0000000-0xfeffbfff] [ 0.000000] PM: Registered nosave memory: [mem 0xfeffc000-0xfeffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xff000000-0xfffbffff] [ 0.000000] PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff] [ 0.000000] [mem 0xc0000000-0xfeffbfff] available for PCI devices [ 0.000000] Booting paravirtualized kernel on KVM [ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns [ 0.000000] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1 [ 0.000000] percpu: Embedded 63 pages/cpu s221184 r8192 d28672 u524288 [ 0.000000] kvm-guest: PV spinlocks enabled [ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1059618 [ 0.000000] Policy zone: Normal [ 0.000000] Kernel command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] Specific versions of hardware are certified with Red Hat Enterprise Linux 8. Please see the list of hardware certified with Red Hat Enterprise Linux 8 at https://catalog.redhat.com. [ 0.000000] audit: disabled (until reboot) [ 0.000000] software IO TLB: area num 4. [ 0.000000] Memory: 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.001010] APIC: Switch to symmetric I/O mode setup [ 0.002319] x2apic enabled [ 0.003000] Switched APIC routing to physical x2apic. [ 0.003013] kvm-guest: setup PV IPIs [ 0.005000] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.005000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.005029] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.006020] pid_max: default: 32768 minimum: 301 [ 0.007181] LSM: Security Framework initializing [ 0.008098] Yama: becoming mindful. [ 0.010031] SELinux: Initializing. [ 0.011088] *** VALIDATE selinux *** [ 0.019752] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.024000] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.024195] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.026078] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.028115] *** VALIDATE tmpfs *** [ 0.029517] *** VALIDATE proc *** [ 0.030334] *** VALIDATE cgroup *** [ 0.031000] *** VALIDATE cgroup2 *** [ 0.031338] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.032193] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.033015] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.034043] Spectre V2 : User space: Vulnerable [ 0.035015] Speculative Store Bypass: Vulnerable [ 0.038249] debug: unmapping init [mem 0xffffffffaf459000-0xffffffffaf460fff] [ 0.040195] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.041845] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.042031] ... version: 2 [ 0.043019] ... bit width: 48 [ 0.044023] ... generic registers: 4 [ 0.045023] ... value mask: 0000ffffffffffff [ 0.046025] ... max period: 00007fffffffffff [ 0.047028] ... fixed-purpose events: 3 [ 0.048022] ... event mask: 000000070000000f [ 0.049401] rcu: Hierarchical SRCU implementation. [ 0.051863] smp: Bringing up secondary CPUs ... [ 0.052762] x86: Booting SMP configuration: [ 0.053049] .... node #0, CPUs: #1 #2 #3 [ 0.062275] smp: Brought up 1 node, 4 CPUs [ 0.064018] smpboot: Max logical packages: 1 [ 0.065015] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.228947] node 0 deferred pages initialised in 160ms [ 0.230281] devtmpfs: initialized [ 0.231465] x86/mm: Memory block size: 128MB [ 0.234000] gcov: version magic: 0x41383552 [ 0.237344] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.238098] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.239000] pinctrl core: initialized pinctrl subsystem [ 0.239000] [ 0.239000] ************************************************************* [ 0.243026] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.244011] ** ** [ 0.246016] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.248013] ** ** [ 0.250016] ** This means that this kernel is built to expose internal ** [ 0.251012] ** IOMMU data structures, which may compromise security on ** [ 0.253015] ** your system. ** [ 0.254014] ** ** [ 0.256018] ** If you see this message and you are not debugging the ** [ 0.258016] ** kernel, report this immediately to your vendor! ** [ 0.261022] ** ** [ 0.263015] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.265019] ************************************************************* [ 0.267843] NET: Registered protocol family 16 [ 0.269569] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.271087] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.273079] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.276149] cpuidle: using governor menu [ 0.279000] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.281647] PCI: Using configuration type 1 for base access [ 0.284153] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.294158] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.297068] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.302037] cryptd: max_cpu_qlen set to 1000 [ 0.304260] ACPI: Added _OSI(Module Device) [ 0.306020] ACPI: Added _OSI(Processor Device) [ 0.307000] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.307000] ACPI: Added _OSI(Processor Aggregator Device) [ 0.311344] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.316082] ACPI: Interpreter enabled [ 0.317061] ACPI: PM: (supports S0 S3 S4 S5) [ 0.319021] ACPI: Using IOAPIC for interrupt routing [ 0.321128] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.324500] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.332979] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.333062] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.334035] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.338145] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.344315] acpiphp: Slot [2] registered [ 0.345185] acpiphp: Slot [3] registered [ 0.346139] acpiphp: Slot [4] registered [ 0.350235] acpiphp: Slot [5] registered [ 0.351000] acpiphp: Slot [6] registered [ 0.351000] acpiphp: Slot [7] registered [ 0.353143] acpiphp: Slot [8] registered [ 0.354118] acpiphp: Slot [9] registered [ 0.356179] acpiphp: Slot [10] registered [ 0.358175] acpiphp: Slot [11] registered [ 0.360120] acpiphp: Slot [12] registered [ 0.362149] acpiphp: Slot [13] registered [ 0.363143] acpiphp: Slot [14] registered [ 0.365115] acpiphp: Slot [15] registered [ 0.366107] acpiphp: Slot [16] registered [ 0.367160] acpiphp: Slot [17] registered [ 0.369115] acpiphp: Slot [18] registered [ 0.370103] acpiphp: Slot [19] registered [ 0.371089] acpiphp: Slot [20] registered [ 0.372094] acpiphp: Slot [21] registered [ 0.373084] acpiphp: Slot [22] registered [ 0.374089] acpiphp: Slot [23] registered [ 0.375107] acpiphp: Slot [24] registered [ 0.376098] acpiphp: Slot [25] registered [ 0.377100] acpiphp: Slot [26] registered [ 0.379109] acpiphp: Slot [27] registered [ 0.380076] acpiphp: Slot [28] registered [ 0.381077] acpiphp: Slot [29] registered [ 0.382110] acpiphp: Slot [30] registered [ 0.383000] acpiphp: Slot [31] registered [ 0.383000] PCI host bridge to bus 0000:00 [ 0.384019] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.385020] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.387022] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.388020] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.391041] pci_bus 0000:00: root bus resource [mem 0x180000000-0x1ffffffff window] [ 0.394073] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.395230] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.399383] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.404858] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.412022] pci 0000:00:01.1: reg 0x20: [io 0xc120-0xc12f] [ 0.415803] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.419029] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.421024] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.424020] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.426536] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.428797] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.435055] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.438729] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.443993] pci 0000:00:02.0: reg 0x10: [io 0xc100-0xc11f] [ 0.456026] pci 0000:00:02.0: reg 0x20: [mem 0xfebf4000-0xfebf7fff 64bit pref] [ 0.460625] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.464932] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.473018] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.475000] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.493030] pci 0000:00:05.0: reg 0x20: [mem 0xfebf8000-0xfebfbfff 64bit pref] [ 0.504086] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.509020] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.515022] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.532019] pci 0000:00:06.0: reg 0x20: [mem 0xfebfc000-0xfebfffff 64bit pref] [ 0.547172] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.549442] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.551380] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.554428] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.556314] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.562062] iommu: Default domain type: Passthrough [ 0.563474] SCSI subsystem initialized [ 0.565214] ACPI: bus type USB registered [ 0.566135] usbcore: registered new interface driver usbfs [ 0.568131] usbcore: registered new interface driver hub [ 0.571155] usbcore: registered new device driver usb [ 0.574218] pps_core: LinuxPPS API ver. 1 registered [ 0.576014] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.579101] PTP clock support registered [ 0.581406] EDAC MC: Ver: 3.0.0 [ 0.583136] PCI: Using ACPI for IRQ routing [ 0.587900] NetLabel: Initializing [ 0.591017] NetLabel: domain hash size = 128 [ 0.593012] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.595113] NetLabel: unlabeled traffic allowed by default [ 0.599159] vgaarb: loaded [ 0.601370] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.603019] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.608988] clocksource: Switched to clocksource kvm-clock [ 0.744255] VFS: Disk quotas dquot_6.6.0 [ 0.746340] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.749146] *** VALIDATE ramfs *** [ 0.750678] *** VALIDATE hugetlbfs *** [ 0.752225] pnp: PnP ACPI init [ 0.755696] pnp: PnP ACPI: found 6 devices [ 0.775419] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.778605] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.781877] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.784540] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.787173] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.789849] pci_bus 0000:00: resource 8 [mem 0x180000000-0x1ffffffff window] [ 0.792847] NET: Registered protocol family 2 [ 0.795499] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.800647] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.804746] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.809703] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.812624] TCP: Hash tables configured (established 65536 bind 65536) [ 0.815614] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.818640] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.821496] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.824455] NET: Registered protocol family 1 [ 0.827531] RPC: Registered named UNIX socket transport module. [ 0.829696] RPC: Registered udp transport module. [ 0.832804] RPC: Registered tcp transport module. [ 0.836520] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.840476] NET: Registered protocol family 44 [ 0.842685] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.845388] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.847193] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.849880] PCI: CLS 0 bytes, default 64 [ 0.853087] Unpacking initramfs... [ 2.585918] debug: unmapping init [mem 0xffff8bab7cc64000-0xffff8bab7ffcffff] [ 2.590739] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.593284] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.596926] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 3.177102] Initialise system trusted keyrings [ 3.179091] Key type blacklist registered [ 3.181263] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 3.194648] zbud: loaded [ 3.198692] *** VALIDATE nfs *** [ 3.199935] *** VALIDATE nfs4 *** [ 3.201306] pstore: using deflate compression [ 3.204807] Platform Keyring initialized [ 3.384329] NET: Registered protocol family 38 [ 3.386130] Key type asymmetric registered [ 3.390575] Asymmetric key parser 'x509' registered [ 3.394992] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 3.403920] io scheduler mq-deadline registered [ 3.408190] io scheduler kyber registered [ 3.411782] io scheduler bfq registered [ 3.414263] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 3.417505] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 3.421234] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 3.424840] ACPI: Power Button [PWRF] [ 3.545402] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 3.650888] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 3.757519] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 3.786098] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.824310] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.829832] Non-volatile memory driver v1.3 [ 3.831183] Linux agpgart interface v0.103 [ 3.864886] virtio_blk virtio1: [vda] 67984 512-byte logical blocks (34.8 MB/33.2 MiB) [ 3.867782] vda: detected capacity change from 0 to 34807808 [ 3.884833] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.888260] vdb: detected capacity change from 0 to 1073741824 [ 3.901523] libphy: Fixed MDIO Bus: probed [ 3.912629] usbcore: registered new interface driver usbserial_generic [ 3.914434] usbserial: USB Serial support registered for generic [ 3.916320] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.920607] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.922175] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.924171] mousedev: PS/2 mouse device common for all mice [ 3.926259] rtc_cmos 00:05: RTC can wake from S4 [ 3.929728] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.931422] rtc_cmos 00:05: registered as rtc0 [ 3.935567] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.938971] intel_pstate: CPU model not supported [ 3.941882] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.946267] hid: raw HID events driver (C) Jiri Kosina [ 3.950194] usbcore: registered new interface driver usbhid [ 3.952565] usbhid: USB HID core driver [ 3.954361] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.956080] drop_monitor: Initializing network drop monitor service [ 3.965310] Initializing XFRM netlink socket [ 3.967609] NET: Registered protocol family 10 [ 3.972545] Segment Routing with IPv6 [ 3.973729] NET: Registered protocol family 17 [ 3.977337] mpls_gso: MPLS GSO support [ 3.983500] RAS: Correctable Errors collector initialized. [ 3.985211] AVX version of gcm_enc/dec engaged. [ 3.986580] AES CTR mode by8 optimization enabled [ 4.144522] sched_clock: Marking stable (4144276693, 0)->(5072902387, -928625694) [ 4.150291] registered taskstats version 1 [ 4.152822] Loading compiled-in X.509 certificates [ 4.156512] zswap: loaded using pool lzo/zbud [ 4.204452] Key type big_key registered [ 4.236601] Key type encrypted registered [ 4.238478] ima: No TPM chip found, activating TPM-bypass! [ 4.241691] ima: Allocated hash algorithm: sha1 [ 4.243564] ima: No architecture policies found [ 4.245562] evm: Initialising EVM extended attributes: [ 4.248393] evm: security.selinux [ 4.250652] evm: security.ima [ 4.252246] evm: security.capability [ 4.255232] evm: HMAC attrs: 0x1 [ 4.260504] rtc_cmos 00:05: setting system clock to 2025-10-24 13:08:12 UTC (1761311292) [ 4.268680] debug: unmapping init [mem 0xffffffffb0403000-0xffffffffb05fffff] [ 4.272898] debug: unmapping init [mem 0xffffffffaf182000-0xffffffffaf458fff] [ 4.282947] Write protecting the kernel read-only data: 28672k [ 4.287575] debug: unmapping init [mem 0xffffffffad803000-0xffffffffad9fffff] [ 4.291048] debug: unmapping init [mem 0xffffffffae114000-0xffffffffae1fffff] [ 4.353692] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 4.366595] systemd[1]: Detected virtualization kvm. [ 4.369299] systemd[1]: Detected architecture x86-64. [ 4.372514] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 4.413901] systemd[1]: No hostname configured. [ 4.417114] systemd[1]: Set hostname to . [ 4.420708] random: systemd: uninitialized urandom read (16 bytes read) [ 4.425312] systemd[1]: Initializing machine ID from random generator. [ 4.544205] random: ln: uninitialized urandom read (6 bytes read) [ 4.746558] random: systemd: uninitialized urandom read (16 bytes read) [ 4.749185] systemd[1]: Reached target Timers. [ OK ] Reached target Timers. [ 4.764713] systemd[1]: Listening on udev Kernel Socket. [ OK ] Listening on udev Kernel Socket. [ 4.773058] systemd[1]: Reached target Local File Systems. [ OK ] Reached target Local File Systems. [ OK ] Reached target Slices. [ OK ] Reached target Swap. [ OK ] Listening on Journal Socket. [ OK ] Started Memstrack Anylazing Service. Starting Create list of required st…ce nodes for the current kernel... Starting Setup Virtual Console... [ OK ] Reached target Initrd Root Device. Starting Apply Kernel Variables... [ OK ] Listening on Journal Socket (/dev/log). Starting Journal Service... Starting Create Volatile Files and Directories... [ OK ] Listening on udev Control Socket. [ OK ] Reached target Sockets. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Paths. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Setup Virtual Console. [ OK ] Started Apply Kernel Variables. [ OK ] Started Create Volatile Files and Directories. Starting dracut cmdline hook... Starting Create Static Device Nodes in /dev... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started Journal Service. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 6.003769] device-mapper: uevent: version 1.0.3 [ 6.011938] device-mapper: ioctl: 4.46.0-ioctl (2022-02-22) initialised: dm-devel@redhat.com [ OK ] Started dracut pre-udev hook. Starting udev Kernel Device Manager... [ OK ] Started udev Kernel Device Manager. Starting dracut pre-trigger hook... [ OK ] Started dracut pre-trigger hook. Starting udev Coldplug all Devices... Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. [ OK ] Reached target System Initialization. [ 7.306361] virtio_net virtio0 ens2: renamed from eth0 [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting dracut initqueue hook... [ 8.288312] scsi host0: ata_piix [ 8.665818] scsi host1: ata_piix [ 8.671821] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc120 irq 14 [ 8.687624] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc128 irq 15 [ 12.681697] random: fast init done [ 13.774833] random: crng init done [ 13.776066] random: 7 urandom warning(s) missed due to ratelimiting [ 15.867752] dracut-initqueue[593]: RTNETLINK answers: File exists 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. [ 16.812798] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Timers. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Paths. [ OK ] Stopped target Sockets. [ OK ] Stopped target Slices. [ OK ] Stopped target System Initialization. [ OK ] Stopped target Swap. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. Stopping udev Kernel Device Manager... [ OK ] Stopped target Local File Systems. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Closed udev Kernel Socket. [ OK ] Closed udev Control Socket. Starting Cleanup udevd DB... [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 18.549690] printk: systemd: 26 output lines suppressed due to ratelimiting [ 18.893681] SELinux: Disabled at runtime. [ 18.979374] 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) [ 19.005547] systemd[1]: Detected virtualization kvm. [ 19.007474] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 19.921809] systemd[1]: initrd-switch-root.service: Succeeded. [ 19.925795] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 19.939823] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 19.943654] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 19.947068] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 19.982028] systemd[1]: Starting Journal Service... Starting Journal Service... [ 19.990290] systemd[1]: Created slice system-sshd\x2dkeygen.slice. [ OK ] Created slice system-sshd\x2dkeygen.slice. Mounting Kernel Debug File System... [ OK ] Reached target rpc_pipefs.target. [ OK ] Created slice system-getty.slice. Starting Remount Root and Kernel File Systems... [ OK ] Listening on initctl Compatibility Named Pipe. [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. Activating swap /dev/disk/by-label/SWAP... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Reached target Paths. [ OK ] Reached target Local Encrypted Volumes. [ 20.364322] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS [ OK ] Listening on udev Control Socket. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Listening on udev Kernel Socket. Starting udev Coldplug all Devices... [ OK ] Created slice system-serial\x2dgetty.slice. Mounting POSIX Message Queue File System... [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Reached target RPC Port Mapper. [ OK ] Listening on Process Core Dump Socket. [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd File Systems. [ OK ] Stopped target Initrd Root File System. Starting Apply Kernel Variables... Mounting Huge Pages File System... [ OK ] Created slice User and Session Slice. [ OK ] Reached target Slices. [ OK ] Started Journal Service. [ OK ] Mounted Kernel Debug File System. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Started Apply Kernel Variables. [ OK ] Mounted Huge Pages File System. [ OK ] Reached target Swap. Starting Create Static Device Nodes in /dev... Starting Configure read-only root support... Starting Flush Journal to Persistent Storage... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. 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. [ OK ] Mounted /mnt. [ 21.435620] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 22.207346] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 22.324107] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 23.275494] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 23.364862] EDAC sbridge: Ver: 1.1.2 [ 25.484701] Key type dns_resolver registered [ 25.847712] NFS: Registering the id_resolver key type [ 25.849897] Key type id_resolver registered [ 25.852572] 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 Update UTMP about System Boot/Shutdown... Starting RPC Bind... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Started dnf makecache --timer. [ OK ] Reached target Timers. [ OK ] Reached target Basic System. [ OK ] Started D-Bus System Message Bus. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Reached target sshd-keygen.target. Starting Login Service... [ OK ] Started irqbalance daemon. Starting Network Manager... Starting Restore /run/initramfs on shutdown... [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Network Manager. [ OK ] Reached target Network. Starting Dynamic System Tuning Daemon... Starting GSSAPI Proxy Daemon... Starting OpenSSH server daemon... Starting Network Manager Wait Online... Starting Hostname Service... [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Started Login Service. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... [ OK ] Started OpenSSH server daemon. [ OK ] Started Permit User Sessions. [ OK ] Started Getty on tty1. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Command Scheduler. [ 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 Crash recovery kernel arming... Starting Notify NFS peers of a restart... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg324-client login: [ 50.754085] hrtimer: interrupt took 3097607 ns [ 66.167204] libcfs: loading out-of-tree module taints kernel. [ 66.316062] alg: No test for adler32 (adler32-zlib) [ 67.068391] Key type ._llcrypt registered [ 67.069755] Key type .llcrypt registered [ 67.309211] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [ 67.656609] Lustre: Lustre: Build Version: 2.15.7_13_gae8ad20 [ 68.125115] LNet: Added LNI 192.168.203.24@tcp [8/256/0/180] [ 68.127787] LNet: Accept secure, port 988 [ 69.783195] Key type lgssc registered [ 70.786533] Lustre: Echo OBD driver; http://www.lustre.org/ [ 223.997449] Lustre: Mounted lustre-client [ 228.646909] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 243.027917] Lustre: DEBUG MARKER: oleg324-client.virtnet: executing check_logdir /tmp/testlogs/ [ 249.186965] Lustre: DEBUG MARKER: oleg324-client.virtnet: executing yml_node [ 249.825109] Lustre: lustre-OST0000-osc-ffff8babd0922800: disconnect after 24s idle [ 253.363627] Lustre: DEBUG MARKER: Client: 2.15.7.13 [ 256.388574] Lustre: DEBUG MARKER: MDS: 2.15.7.13 [ 259.111477] Lustre: DEBUG MARKER: OSS: 2.15.7.13 [ 261.131460] Lustre: DEBUG MARKER: -----============= acceptance-small: recovery-small ============----- Fri Oct 24 09:12:27 EDT 2025 [ 269.064420] Lustre: DEBUG MARKER: excepting tests: 136 [ 274.591747] Lustre: DEBUG MARKER: oleg324-client.virtnet: executing check_config_client /mnt/lustre [ 292.591260] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 303.486644] Lustre: DEBUG MARKER: == recovery-small test 1: create, chmod, stat: drop req, drop rep ========================================================== 09:13:10 (1761311590) [ 315.873432] Lustre: 9749:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1761311592/real 1761311592] req@00000000ed4afb6f x1846868816435968/t0(0) o700->lustre-MDT0000-mdc-ffff8babd0922800@192.168.203.124@tcp:30/10 lens 264/248 e 0 to 1 dl 1761311604 ref 2 fl Rpc:XQr/0/ffffffff rc 0/-1 job:'mcreate.0' [ 315.895274] Lustre: lustre-MDT0000-mdc-ffff8babd0922800: Connection to lustre-MDT0000 (at 192.168.203.124@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 315.913870] Lustre: lustre-MDT0000-mdc-ffff8babd0922800: Connection restored to (at 192.168.203.124@tcp) [ 326.119603] Lustre: 9768:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1761311607/real 1761311607] req@000000004de6198d x1846868816436928/t0(0) o36->lustre-MDT0000-mdc-ffff8babd0922800@192.168.203.124@tcp:12/10 lens 520/448 e 0 to 1 dl 1761311614 ref 2 fl Rpc:XQr/0/ffffffff rc 0/-1 job:'mcreate.0' [ 326.158518] Lustre: lustre-MDT0000-mdc-ffff8babd0922800: Connection to lustre-MDT0000 (at 192.168.203.124@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 326.213579] Lustre: lustre-MDT0000-mdc-ffff8babd0922800: Connection restored to (at 192.168.203.124@tcp) [ 335.327154] Lustre: 9792:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1761311616/real 1761311616] req@00000000b461d7ba x1846868816437504/t0(0) o101->lustre-MDT0000-mdc-ffff8babd0922800@192.168.203.124@tcp:12/10 lens 576/1152 e 0 to 1 dl 1761311623 ref 2 fl Rpc:XQr/0/ffffffff rc 0/-1 job:'tchmod.0' [ 335.346450] Lustre: lustre-MDT0000-mdc-ffff8babd0922800: Connection to lustre-MDT0000 (at 192.168.203.124@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 335.382103] Lustre: lustre-MDT0000-mdc-ffff8babd0922800: Connection restored to (at 192.168.203.124@tcp) [ 344.543219] Lustre: 9810:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1761311625/real 1761311625] req@00000000bbedf105 x1846868816438528/t0(0) o36->lustre-MDT0000-mdc-ffff8babd0922800@192.168.203.124@tcp:12/10 lens 488/512 e 0 to 1 dl 1761311632 ref 2 fl Rpc:XQr/0/ffffffff rc 0/-1 job:'tchmod.0' [ 344.591679] Lustre: lustre-MDT0000-mdc-ffff8babd0922800: Connection to lustre-MDT0000 (at 192.168.203.124@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 344.652066] Lustre: lustre-MDT0000-mdc-ffff8babd0922800: Connection restored to (at 192.168.203.124@tcp) [ 353.759208] Lustre: 9834:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1761311634/real 1761311634] req@00000000bbedf105 x1846868816439040/t0(0) o34->lustre-MDT0000-mdc-ffff8babd0922800@192.168.203.124@tcp:12/10 lens 472/728 e 0 to 1 dl 1761311641 ref 2 fl Rpc:XQr/0/ffffffff rc 0/-1 job:'statone.0' [ 353.782247] Lustre: lustre-MDT0000-mdc-ffff8babd0922800: Connection to lustre-MDT0000 (at 192.168.203.124@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 353.833149] Lustre: lustre-MDT0000-mdc-ffff8babd0922800: Connection restored to (at 192.168.203.124@tcp) [ 362.464048] Lustre: 9852:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1761311643/real 1761311643] req@0000000066b28d36 x1846868816439552/t0(0) o34->lustre-MDT0000-mdc-ffff8babd0922800@192.168.203.124@tcp:12/10 lens 472/728 e 0 to 1 dl 1761311650 ref 2 fl Rpc:XQr/0/ffffffff rc 0/-1 job:'statone.0' [ 362.490404] Lustre: lustre-MDT0000-mdc-ffff8babd0922800: Connection to lustre-MDT0000 (at 192.168.203.124@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 362.539777] Lustre: lustre-MDT0000-mdc-ffff8babd0922800: Connection restored to (at 192.168.203.124@tcp) [ 369.619198] Lustre: DEBUG MARKER: == recovery-small test 4: open: drop req, drop rep ======= 09:14:16 (1761311656) [ 386.015264] Lustre: 10477:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1761311667/real 1761311667] req@00000000a3d68924 x1846868816441984/t0(0) o35->lustre-MDT0000-mdc-ffff8babd0922800@192.168.203.124@tcp:23/10 lens 392/624 e 0 to 1 dl 1761311674 ref 2 fl Rpc:XQr/0/ffffffff rc 0/-1 job:'cat.0' [ 386.034027] Lustre: 10477:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 386.045443] Lustre: lustre-MDT0000-mdc-ffff8babd0922800: Connection to lustre-MDT0000 (at 192.168.203.124@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 386.059710] Lustre: Skipped 1 previous similar message [ 386.098831] Lustre: lustre-MDT0000-mdc-ffff8babd0922800: Connection restored to (at 192.168.203.124@tcp) [ 386.104428] Lustre: Skipped 1 previous similar message [ 392.997391] Lustre: DEBUG MARKER: == recovery-small test 5: rename: drop req, drop rep ===== 09:14:39 (1761311679) [ 417.361666] Lustre: DEBUG MARKER: == recovery-small test 6: link, unlink: drop req, drop rep ========================================================== 09:15:04 (1761311704) [ 424.927220] Lustre: 11714:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1761311706/real 1761311706] req@0000000056d0595b x1846868816446400/t0(0) o36->lustre-MDT0000-mdc-ffff8babd0922800@192.168.203.124@tcp:12/10 lens 512/440 e 0 to 1 dl 1761311713 ref 2 fl Rpc:XQr/0/ffffffff rc 0/-1 job:'mlink.0' [ 424.956233] Lustre: 11714:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 424.962019] Lustre: lustre-MDT0000-mdc-ffff8babd0922800: Connection to lustre-MDT0000 (at 192.168.203.124@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 424.968644] Lustre: Skipped 2 previous similar messages [ 424.990798] Lustre: lustre-MDT0000-mdc-ffff8babd0922800: Connection restored to (at 192.168.203.124@tcp) [ 425.000547] Lustre: Skipped 2 previous similar messages [ 439.265336] Lustre: lustre-OST0001-osc-ffff8babd0922800: disconnect after 22s idle [ 439.272625] Lustre: Skipped 1 previous similar message [ 459.323226] Lustre: DEBUG MARKER: == recovery-small test 8: touch: drop rep (bug 1423) ===== 09:15:46 (1761311746) [ 474.370655] Lustre: DEBUG MARKER: == recovery-small test 9: pause bulk on OST (bug 1420) === 09:16:01 (1761311761) [ 490.800673] Lustre: DEBUG MARKER: == recovery-small test 10a: finish request on server after client eviction (bug 1521) ========================================================== 09:16:17 (1761311777) [ 491.130731] Lustre: *** cfs_fail_loc=305, val=0*** [ 502.465513] Lustre: *** cfs_fail_loc=305, val=0*** [ 502.467347] Lustre: Skipped 1 previous similar message [ 507.873224] Lustre: lustre-OST0001-osc-ffff8babd0922800: disconnect after 20s idle [ 513.753581] Lustre: *** cfs_fail_loc=305, val=0*** [ 513.755490] Lustre: Skipped 1 previous similar message [ 525.006775] Lustre: *** cfs_fail_loc=305, val=0*** [ 536.270937] Lustre: *** cfs_fail_loc=305, val=0*** [ 536.272663] Lustre: Skipped 1 previous similar message [ 547.548159] Lustre: *** cfs_fail_loc=305, val=0*** [ 547.558755] Lustre: Skipped 2 previous similar messages [ 570.029823] Lustre: *** cfs_fail_loc=305, val=0*** [ 570.037547] Lustre: Skipped 2 previous similar messages [ 592.844237] LustreError: 11-0: lustre-MDT0000-mdc-ffff8babd0922800: operation ldlm_enqueue to node 192.168.203.124@tcp failed: rc = -107 [ 592.858433] Lustre: lustre-MDT0000-mdc-ffff8babd0922800: Connection to lustre-MDT0000 (at 192.168.203.124@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 592.875312] Lustre: Skipped 4 previous similar messages [ 592.883824] LustreError: lustre-MDT0000-mdc-ffff8babd0922800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 592.897906] Lustre: lustre-MDT0000-mdc-ffff8babd0922800: Connection restored to (at 192.168.203.124@tcp) [ 592.912087] Lustre: Skipped 4 previous similar messages [ 598.345973] Lustre: DEBUG MARKER: == recovery-small test 10b: re-send BL AST =============== 09:18:05 (1761311885) [ 616.091780] Lustre: DEBUG MARKER: == recovery-small test 10c: re-send BL AST vs reconnect race (LU-5569) ========================================================== 09:18:23 (1761311903) [ 616.494057] Lustre: *** cfs_fail_loc=305, val=0*** [ 616.495789] Lustre: Skipped 3 previous similar messages [ 623.069798] Lustre: DEBUG MARKER: == recovery-small test 10d: test failed blocking ast ===== 09:18:30 (1761311910) [ 625.994081] Lustre: Unmounted lustre-client [ 626.440501] Lustre: Mounted lustre-client [ 627.935360] LustreError: 11-0: lustre-OST0000-osc-ffff8babc99f6000: operation ldlm_enqueue to node 192.168.203.124@tcp failed: rc = -107 [ 627.968340] LustreError: lustre-OST0000-osc-ffff8babc99f6000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 627.996587] Lustre: 2265:0:(llite_lib.c:3595:ll_dirty_page_discard_warn()) lustre: dirty page discard: 192.168.203.124@tcp:/lustre/fid: [0x200000404:0x1:0x0]// may get corrupted (rc -108) [ 630.477976] Lustre: Unmounted lustre-client [ 637.041722] Lustre: DEBUG MARKER: == recovery-small test 10e: re-send BL AST vs reconnect race 2 ========================================================== 09:18:43 (1761311923) [ 638.845728] Lustre: DEBUG MARKER: SKIP: recovery-small test_10e need two clients [ 640.818169] Lustre: DEBUG MARKER: == recovery-small test 11: wake up a thread waiting for completion after eviction (b=2460) ========================================================== 09:18:47 (1761311927) [ 660.788511] Lustre: DEBUG MARKER: == recovery-small test 12: recover from timed out resend in ptlrpcd (b=2494) ========================================================== 09:19:07 (1761311947) [ 661.032583] Lustre: DEBUG MARKER: multiop /mnt/lustre/f12.recovery-small OS_c [ 669.151150] Lustre: 17363:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1761311950/real 1761311950] req@000000009fd1a7a4 x1846868816484608/t0(0) o35->lustre-MDT0000-mdc-ffff8babc99f6000@192.168.203.124@tcp:23/10 lens 392/624 e 0 to 1 dl 1761311957 ref 2 fl Rpc:XQr/0/ffffffff rc 0/-1 job:'multiop.0' [ 669.176560] Lustre: 17363:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 4 previous similar messages [ 704.697819] Lustre: DEBUG MARKER: == recovery-small test 13: mdc_readpage restart test (bug 1138) ========================================================== 09:19:51 (1761311991) [ 718.720830] Lustre: DEBUG MARKER: == recovery-small test 14: mdc_readpage resend test (bug 1138) ========================================================== 09:20:05 (1761312005) [ 725.680816] Lustre: DEBUG MARKER: == recovery-small test 15: failed open (-ENOMEM) ========= 09:20:12 (1761312012) [ 732.842953] Lustre: DEBUG MARKER: == recovery-small test 16: timeout bulk put, don't evict client (2732) ========================================================== 09:20:19 (1761312019) [ 778.655240] Lustre: lustre-OST0001-osc-ffff8babc99f6000: Connection to lustre-OST0001 (at 192.168.203.124@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 778.674638] Lustre: Skipped 4 previous similar messages [ 806.464655] Lustre: DEBUG MARKER: == recovery-small test 17a: timeout bulk get, don't evict client (2732) ========================================================== 09:21:33 (1761312093) [ 857.707303] Lustre: DEBUG MARKER: == recovery-small test 17b: timeout bulk get, dont evict client (3582) ========================================================== 09:22:24 (1761312144) [ 858.639710] Lustre: DEBUG MARKER: SKIP: recovery-small test_17b Needs multiple clients [ 860.087621] Lustre: DEBUG MARKER: == recovery-small test 18a: manual ost invalidate clears page cache immediately ========================================================== 09:22:27 (1761312147) [ 860.827948] Lustre: setting import lustre-OST0001_UUID INACTIVE by administrator request [ 860.899168] LustreError: lustre-OST0001-osc-ffff8babc99f6000: This client was evicted by lustre-OST0001; in progress operations using this service will fail. [ 860.906574] Lustre: lustre-OST0001-osc-ffff8babc99f6000: Connection restored to 192.168.203.124@tcp (at 192.168.203.124@tcp) [ 860.913635] Lustre: Skipped 4 previous similar messages [ 865.965039] Lustre: DEBUG MARKER: == recovery-small test 18b: eviction and reconnect clears page cache (2766) ========================================================== 09:22:33 (1761312153) [ 870.894138] LustreError: lustre-OST0000-osc-ffff8babc99f6000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 895.216869] Lustre: DEBUG MARKER: == recovery-small test 18c: Dropped connect reply after eviction handing (14755) ========================================================== 09:23:02 (1761312182) [ 898.903980] LustreError: 11-0: lustre-OST0000-osc-ffff8babc99f6000: operation ost_statfs to node 192.168.203.124@tcp failed: rc = -107 [ 905.206420] Lustre: Evicted from lustre-OST0000_UUID (at 192.168.203.124@tcp) after server handle changed from 0x38552adf424ec1e to 0x38552adf424ed75 [ 905.219453] LustreError: lustre-OST0000-osc-ffff8babc99f6000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 912.990851] Lustre: DEBUG MARKER: == recovery-small test 19a: test expired_lock_main on mds (2867) ========================================================== 09:23:20 (1761312200) [ 913.543235] Lustre: Mounted lustre-client [ 913.544925] Lustre: Skipped 1 previous similar message [ 922.271155] Lustre: 2264:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1761312203/real 1761312203] req@00000000558164ec x1846868816516544/t0(0) o103->lustre-MDT0000-mdc-ffff8babc99f6000@192.168.203.124@tcp:17/18 lens 328/224 e 0 to 1 dl 1761312210 ref 1 fl Rpc:XQr/0/ffffffff rc 0/-1 job:'ldlm_bl_02.0' [ 922.312168] Lustre: 2264:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 1020.629789] LustreError: 11-0: lustre-MDT0000-mdc-ffff8babc99f6000: operation ldlm_enqueue to node 192.168.203.124@tcp failed: rc = -107 [ 1020.642405] LustreError: lustre-MDT0000-mdc-ffff8babc99f6000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 1020.655199] LustreError: 23649:0:(file.c:5205:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -5 [ 1020.659297] LustreError: 23650:0:(file.c:246:ll_close_inode_openhandle()) lustre-clilmv-ffff8babc99f6000: inode [0x200000404:0x1:0x0] mdc close failed: rc = -108 [ 1021.436112] Lustre: Unmounted lustre-client [ 1026.025116] Lustre: DEBUG MARKER: == recovery-small test 19b: test expired_lock_main on ost (2867) ========================================================== 09:25:13 (1761312313) [ 1026.493137] Lustre: Mounted lustre-client [ 1035.743600] Lustre: lustre-OST0000-osc-ffff8babc99f6000: Connection to lustre-OST0000 (at 192.168.203.124@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1035.767477] Lustre: Skipped 18 previous similar messages [ 1120.744407] Lustre: lustre-OST0000-osc-ffff8babc99f6000: Connection restored to (at 192.168.203.124@tcp) [ 1120.747205] Lustre: Skipped 27 previous similar messages [ 1129.561426] Lustre: Unmounted lustre-client [ 1129.712425] LustreError: 11-0: lustre-OST0000-osc-ffff8babc99f6000: operation ost_statfs to node 192.168.203.124@tcp failed: rc = -107 [ 1129.720985] LustreError: lustre-OST0000-osc-ffff8babc99f6000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 1133.556261] Lustre: DEBUG MARKER: == recovery-small test 19c: check reconnect and lock resend do not trigger expired_lock_main ========================================================== 09:27:00 (1761312420) [ 1133.829893] Lustre: Mounted lustre-client [ 1137.598865] Lustre: Unmounted lustre-client [ 1146.531992] Lustre: DEBUG MARKER: == recovery-small test 20a: ldlm_handle_enqueue error (should return error) ========================================================== 09:27:13 (1761312433) [ 1147.462858] LustreError: 11-0: lustre-OST0000-osc-ffff8babc99f6000: operation ldlm_enqueue to node 192.168.203.124@tcp failed: rc = -12 [ 1151.287950] Lustre: DEBUG MARKER: == recovery-small test 20b: ldlm_handle_enqueue error (should return error) ========================================================== 09:27:18 (1761312438) [ 1156.163391] Lustre: DEBUG MARKER: == recovery-small test 21a: drop close request while close and open are both in flight ========================================================== 09:27:23 (1761312443) [ 1171.043851] Lustre: DEBUG MARKER: == recovery-small test 21b: drop open request while close and open are both in flight ========================================================== 09:27:38 (1761312458) [ 1308.639228] Lustre: 27582:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1761312460/real 1761312460] req@00000000791c8993 x1846868816565440/t0(0) o36->lustre-MDT0000-mdc-ffff8babc99f6000@192.168.203.124@tcp:12/10 lens 504/448 e 0 to 1 dl 1761312596 ref 2 fl Rpc:XQr/0/ffffffff rc 0/-1 job:'mcreate.0' [ 1308.654521] Lustre: 27582:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 42 previous similar messages [ 1315.069536] Lustre: DEBUG MARKER: == recovery-small test 21c: drop both request while close and open are both in flight ========================================================== 09:30:02 (1761312602) [ 1461.646581] Lustre: DEBUG MARKER: == recovery-small test 21d: drop close reply while close and open are both in flight ========================================================== 09:32:28 (1761312748) [ 1476.837367] Lustre: DEBUG MARKER: == recovery-small test 21e: drop open reply while close and open are both in flight ========================================================== 09:32:44 (1761312764) [ 1614.815319] Lustre: lustre-MDT0000-mdc-ffff8babc99f6000: Connection to lustre-MDT0000 (at 192.168.203.124@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1614.822846] Lustre: Skipped 19 previous similar messages [ 1615.983201] Lustre: DEBUG MARKER: == recovery-small test 21f: drop both reply while close and open are both in flight ========================================================== 09:35:03 (1761312903) [ 1631.473532] Lustre: DEBUG MARKER: == recovery-small test 21g: drop open reply and close request while close and open are both in flight ========================================================== 09:35:18 (1761312918) [ 1639.914216] Lustre: lustre-MDT0000-mdc-ffff8babc99f6000: Connection restored to (at 192.168.203.124@tcp) [ 1639.919071] Lustre: Skipped 10 previous similar messages [ 1645.537783] Lustre: DEBUG MARKER: == recovery-small test 21h: drop open request and close reply while close and open are both in flight ========================================================== 09:35:32 (1761312932) [ 1684.925197] Lustre: DEBUG MARKER: == recovery-small test 22: drop close request and do mknod ========================================================== 09:36:12 (1761312972) [ 1734.723093] Lustre: DEBUG MARKER: == recovery-small test 23: client hang when close a file after mds crash ========================================================== 09:37:01 (1761313021) [ 1752.031235] LustreError: 166-1: MGC192.168.203.124@tcp: Connection to MGS (at 192.168.203.124@tcp) was lost; in progress operations using this service will fail [ 1769.446911] Lustre: Evicted from MGS (at 192.168.203.124@tcp) after server handle changed from 0x38552adf424e32d to 0x38552adf425074c [ 1779.344402] Lustre: DEBUG MARKER: oleg324-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1780.616495] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1787.315215] Lustre: DEBUG MARKER: == recovery-small test 24a: fsync error (should return error) ========================================================== 09:37:54 (1761313074) [ 1788.968617] LustreError: 11-0: lustre-OST0000-osc-ffff8babc99f6000: operation ost_write to node 192.168.203.124@tcp failed: rc = -107 [ 1788.976790] LustreError: Skipped 1 previous similar message [ 1788.986936] LustreError: lustre-OST0000-osc-ffff8babc99f6000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 1789.022272] Lustre: 2264:0:(llite_lib.c:3595:ll_dirty_page_discard_warn()) lustre: dirty page discard: 192.168.203.124@tcp:/lustre/fid: [0x240000402:0x19:0x0]// may get corrupted (rc -5) [ 1789.041838] LustreError: 34026:0:(ldlm_resource.c:1127:ldlm_resource_complain()) lustre-OST0000-osc-ffff8babc99f6000: namespace resource [0x280000400:0x8:0x0].0x0 (00000000fee37500) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 1794.450415] Lustre: DEBUG MARKER: == recovery-small test 24b: test dirty page discard due to client eviction ========================================================== 09:38:01 (1761313081) [ 1795.883789] LustreError: 11-0: lustre-OST0000-osc-ffff8babc99f6000: operation ost_sync to node 192.168.203.124@tcp failed: rc = -107 [ 1795.897813] LustreError: lustre-OST0000-osc-ffff8babc99f6000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 1795.914686] Lustre: 2265:0:(llite_lib.c:3595:ll_dirty_page_discard_warn()) lustre: dirty page discard: 192.168.203.124@tcp:/lustre/fid: [0x200000405:0x20:0x0]// may get corrupted (rc -108) [ 1800.009680] Lustre: DEBUG MARKER: == recovery-small test 26a: evict dead exports =========== 09:38:07 (1761313087) [ 1801.475997] Lustre: DEBUG MARKER: SKIP: recovery-small test_26a msg and ost1 are at the same node [ 1802.703922] Lustre: DEBUG MARKER: == recovery-small test 26b: evict dead exports =========== 09:38:09 (1761313089) [ 1804.075290] Lustre: DEBUG MARKER: SKIP: recovery-small test_26b msg and ost1 are at the same node [ 1805.462332] Lustre: DEBUG MARKER: == recovery-small test 27: fail LOV while using OSC's ==== 09:38:12 (1761313092) [ 1808.190975] LustreError: 11-0: lustre-MDT0000-mdc-ffff8babc99f6000: operation mds_reint to node 192.168.203.124@tcp failed: rc = -19 [ 1808.202271] LustreError: Skipped 1 previous similar message [ 1817.439230] LustreError: 166-1: MGC192.168.203.124@tcp: Connection to MGS (at 192.168.203.124@tcp) was lost; in progress operations using this service will fail [ 1833.963667] Lustre: Evicted from MGS (at 192.168.203.124@tcp) after server handle changed from 0x38552adf425074c to 0x38552adf4254201 [ 1922.953965] LustreError: 11-0: lustre-MDT0000-mdc-ffff8babc99f6000: operation mds_reint to node 192.168.203.124@tcp failed: rc = -19 [ 1933.279179] Lustre: 2265:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1761313214/real 1761313214] req@00000000ff7950aa x1846868818034624/t0(0) o400->MGC192.168.203.124@tcp@192.168.203.124@tcp:26/25 lens 224/224 e 0 to 1 dl 1761313221 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:2.0' [ 1933.295522] Lustre: 2265:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 13 previous similar messages [ 1933.308049] LustreError: 166-1: MGC192.168.203.124@tcp: Connection to MGS (at 192.168.203.124@tcp) was lost; in progress operations using this service will fail [ 1950.824092] Lustre: Evicted from MGS (at 192.168.203.124@tcp) after server handle changed from 0x38552adf4254201 to 0x38552adf42878ab [ 1952.229498] Lustre: DEBUG MARKER: == recovery-small test 28: handle error adding new clients (bug 6086) ========================================================== 09:40:39 (1761313239) [ 1952.555551] Lustre: *** cfs_fail_loc=305, val=0*** [ 1952.557566] Lustre: Skipped 2 previous similar messages [ 1977.823379] LustreError: 166-1: MGC192.168.203.124@tcp: Connection to MGS (at 192.168.203.124@tcp) was lost; in progress operations using this service will fail [ 1995.237694] Lustre: Evicted from MGS (at 192.168.203.124@tcp) after server handle changed from 0x38552adf42878ab to 0x38552adf4287992 [ 2005.794818] Lustre: DEBUG MARKER: oleg324-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2006.896179] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2013.379335] Lustre: DEBUG MARKER: == recovery-small test 29a: error adding new clients doesn't cause LBUG (bug 22273) ========================================================== 09:41:40 (1761313300) [ 2021.940774] LustreError: 166-1: MGC192.168.203.124@tcp: Connection to MGS (at 192.168.203.124@tcp) was lost; in progress operations using this service will fail [ 2021.956063] Lustre: Evicted from MGS (at 192.168.203.124@tcp) after server handle changed from 0x38552adf4287992 to 0x38552adf4287e46 [ 2054.369158] Lustre: DEBUG MARKER: == recovery-small test 29b: error adding new clients doesn't cause LBUG (bug 22273) ========================================================== 09:42:21 (1761313341) [ 2065.936733] LustreError: lustre-OST0000-osc-ffff8babc99f6000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 2086.692136] Lustre: DEBUG MARKER: == recovery-small test 50: failover MDS under load ======= 09:42:53 (1761313373) [ 2108.511132] LustreError: 166-1: MGC192.168.203.124@tcp: Connection to MGS (at 192.168.203.124@tcp) was lost; in progress operations using this service will fail [ 2125.292313] Lustre: Evicted from MGS (at 192.168.203.124@tcp) after server handle changed from 0x38552adf4287e46 to 0x38552adf429ded1 [ 2141.425580] Lustre: DEBUG MARKER: oleg324-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2143.480898] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2229.731964] LustreError: 166-1: MGC192.168.203.124@tcp: Connection to MGS (at 192.168.203.124@tcp) was lost; in progress operations using this service will fail [ 2229.759072] Lustre: Evicted from MGS (at 192.168.203.124@tcp) after server handle changed from 0x38552adf429ded1 to 0x38552adf42d6df0 [ 2241.682579] Lustre: DEBUG MARKER: oleg324-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2243.653433] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2308.630827] Lustre: lustre-MDT0000-mdc-ffff8babc99f6000: Connection to lustre-MDT0000 (at 192.168.203.124@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 2308.652042] Lustre: Skipped 17 previous similar messages [ 2314.913540] LustreError: 166-1: MGC192.168.203.124@tcp: Connection to MGS (at 192.168.203.124@tcp) was lost; in progress operations using this service will fail [ 2332.667051] Lustre: Evicted from MGS (at 192.168.203.124@tcp) after server handle changed from 0x38552adf42d6df0 to 0x38552adf430c78c [ 2332.687262] Lustre: MGC192.168.203.124@tcp: Connection restored to 192.168.203.124@tcp (at 192.168.203.124@tcp) [ 2332.690142] Lustre: Skipped 19 previous similar messages [ 2348.861973] Lustre: DEBUG MARKER: oleg324-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2350.433838] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2377.405085] Lustre: DEBUG MARKER: == recovery-small test 51: failover MDS during recovery == 09:47:44 (1761313664) [ 2380.503445] LustreError: 11-0: lustre-MDT0000-mdc-ffff8babc99f6000: operation mds_close to node 192.168.203.124@tcp failed: rc = -19 [ 2380.512649] LustreError: Skipped 4 previous similar messages [ 2391.010686] LustreError: 166-1: MGC192.168.203.124@tcp: Connection to MGS (at 192.168.203.124@tcp) was lost; in progress operations using this service will fail [ 2397.160249] Lustre: Evicted from MGS (at 192.168.203.124@tcp) after server handle changed from 0x38552adf430c78c to 0x38552adf4323369 [ 2411.516966] Lustre: DEBUG MARKER: test_51: failover in 1 sec [ 2414.323954] LustreError: 11-0: lustre-MDT0000-mdc-ffff8babc99f6000: operation mds_reint to node 192.168.203.124@tcp failed: rc = -19 [ 2446.608476] Lustre: DEBUG MARKER: test_51: failover in 5 sec [ 2475.477549] Lustre: DEBUG MARKER: test_51: failover in 10 sec [ 2487.948454] LustreError: 11-0: lustre-MDT0000-mdc-ffff8babc99f6000: operation mds_reint to node 192.168.203.124@tcp failed: rc = -19 [ 2487.953720] LustreError: Skipped 3 previous similar messages [ 2521.792676] Lustre: DEBUG MARKER: test_51: failover in 20 sec [ 2552.799147] Lustre: 2264:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1761313834/real 1761313834] req@00000000d5047ad3 x1846868822707200/t0(0) o400->MGC192.168.203.124@tcp@192.168.203.124@tcp:26/25 lens 224/224 e 0 to 1 dl 1761313841 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:1.0' [ 2552.823401] Lustre: 2264:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 7 previous similar messages [ 2552.828795] LustreError: 166-1: MGC192.168.203.124@tcp: Connection to MGS (at 192.168.203.124@tcp) was lost; in progress operations using this service will fail [ 2552.839720] LustreError: Skipped 3 previous similar messages [ 2570.226199] Lustre: Evicted from MGS (at 192.168.203.124@tcp) after server handle changed from 0x38552adf432fdeb to 0x38552adf433e03e [ 2570.232022] Lustre: Skipped 3 previous similar messages [ 2577.468994] Lustre: DEBUG MARKER: test_51: failover in 25 sec [ 2637.142148] Lustre: DEBUG MARKER: test_51: failover in 30 sec [ 2669.638479] LustreError: 11-0: lustre-MDT0000-mdc-ffff8babc99f6000: operation mds_close to node 192.168.203.124@tcp failed: rc = -19 [ 2669.657172] LustreError: Skipped 5 previous similar messages [ 2728.212741] Lustre: DEBUG MARKER: == recovery-small test 52: failover OST under load ======= 09:53:35 (1761314015) [ 2768.715833] Lustre: DEBUG MARKER: oleg324-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 2770.173423] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 3071.114211] LustreError: 11-0: lustre-OST0000-osc-ffff8babc99f6000: operation ldlm_enqueue to node 192.168.203.124@tcp failed: rc = -107 [ 3071.121547] LustreError: Skipped 2 previous similar messages [ 3071.129113] Lustre: lustre-OST0000-osc-ffff8babc99f6000: Connection to lustre-OST0000 (at 192.168.203.124@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 3071.141268] Lustre: Skipped 8 previous similar messages [ 3090.006146] Lustre: lustre-OST0000-osc-ffff8babc99f6000: Connection restored to 192.168.203.124@tcp (at 192.168.203.124@tcp) [ 3090.024294] Lustre: Skipped 16 previous similar messages [ 3103.586074] Lustre: DEBUG MARKER: oleg324-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 3105.494710] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 3434.761140] Lustre: DEBUG MARKER: oleg324-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 3436.213534] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 3695.387706] Lustre: DEBUG MARKER: == recovery-small test 53a: touch: drop rep ============== 10:09:42 (1761314982) [ 3740.639860] Lustre: 51142:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1761314984/real 1761314984] req@0000000050dcac16 x1846868837127616/t0(0) o101->lustre-MDT0000-mdc-ffff8babc99f6000@192.168.203.124@tcp:12/10 lens 648/66264 e 0 to 1 dl 1761315028 ref 2 fl Rpc:XPQr/0/ffffffff rc 0/-1 job:'openfile.0' [ 3740.678836] Lustre: 51142:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 3740.684686] Lustre: lustre-MDT0000-mdc-ffff8babc99f6000: Connection to lustre-MDT0000 (at 192.168.203.124@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 3740.691472] Lustre: Skipped 1 previous similar message [ 3740.720034] Lustre: lustre-MDT0000-mdc-ffff8babc99f6000: Connection restored to 192.168.203.124@tcp (at 192.168.203.124@tcp) [ 3740.724085] Lustre: Skipped 1 previous similar message [ 3747.206583] Lustre: DEBUG MARKER: == recovery-small test 53b: touch: drop rep ============== 10:10:34 (1761315034) [ 3800.001131] Lustre: DEBUG MARKER: == recovery-small test 53c: touch: drop rep ============== 10:11:27 (1761315087) [ 3814.193909] Lustre: DEBUG MARKER: == recovery-small test 54: back in time ================== 10:11:41 (1761315101) [ 3814.603781] Lustre: Mounted lustre-client [ 3837.407249] LustreError: 166-1: MGC192.168.203.124@tcp: Connection to MGS (at 192.168.203.124@tcp) was lost; in progress operations using this service will fail [ 3837.422312] LustreError: Skipped 2 previous similar messages [ 3843.563379] Lustre: Evicted from MGS (at 192.168.203.124@tcp) after server handle changed from 0x38552adf43574c4 to 0x38552adf4571e57 [ 3843.570056] Lustre: Skipped 2 previous similar messages [ 3855.247486] Lustre: DEBUG MARKER: oleg324-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3856.333369] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3857.988126] Lustre: Unmounted lustre-client [ 3861.726235] Lustre: DEBUG MARKER: == recovery-small test 55: ost_brw_read/write drops timed-out read/write request ========================================================== 10:12:29 (1761315149) [ 3958.269652] Lustre: DEBUG MARKER: == recovery-small test 56: do not fail on getattr resend ========================================================== 10:14:05 (1761315245) [ 4004.909197] Lustre: DEBUG MARKER: == recovery-small test 57: read procfs entries causes kernel crash ========================================================== 10:14:52 (1761315292) [ 4006.968335] Lustre: Unmounted lustre-client [ 4032.310258] Lustre: Mounted lustre-client [ 4037.516209] Lustre: DEBUG MARKER: == recovery-small test 58: Eviction in the middle of open RPC reply processing ========================================================== 10:15:24 (1761315324) [ 4037.964898] LustreError: 57035:0:(fail.c:138:__cfs_fail_timeout_set()) cfs_fail_timeout id 801 sleeping for 20000ms [ 4039.016548] LustreError: 57035:0:(fail.c:144:__cfs_fail_timeout_set()) cfs_fail_timeout interrupted [ 4039.148015] Lustre: *** cfs_fail_loc=305, val=0*** [ 4055.821606] Lustre: DEBUG MARKER: == recovery-small test 59: Read cancel race on client eviction ========================================================== 10:15:43 (1761315343) [ 4056.304291] Lustre: Mounted lustre-client [ 4057.835726] Lustre: setting import lustre-MDT0000_UUID INACTIVE by administrator request [ 4068.190815] Lustre: Unmounted lustre-client [ 4072.812165] Lustre: DEBUG MARKER: == recovery-small test 60: Add Changelog entries during MDS failover ========================================================== 10:16:00 (1761315360) [ 4150.159970] LustreError: 11-0: lustre-MDT0000-mdc-ffff8babe0528000: operation mds_reint to node 192.168.203.124@tcp failed: rc = -107 [ 4150.170681] LustreError: Skipped 1 previous similar message [ 4161.953443] LustreError: 166-1: MGC192.168.203.124@tcp: Connection to MGS (at 192.168.203.124@tcp) was lost; in progress operations using this service will fail [ 4179.439295] Lustre: Evicted from MGS (at 192.168.203.124@tcp) after server handle changed from 0x38552adf457284b to 0x38552adf459e2ae [ 4271.928202] Lustre: DEBUG MARKER: == recovery-small test 61: Verify to not reuse orphan objects - bug 17025 ========================================================== 10:19:18 (1761315558) [ 4280.038661] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4294.111784] LustreError: 166-1: MGC192.168.203.124@tcp: Connection to MGS (at 192.168.203.124@tcp) was lost; in progress operations using this service will fail [ 4294.137044] Lustre: Evicted from MGS (at 192.168.203.124@tcp) after server handle changed from 0x38552adf459e2ae to 0x38552adf45d9782 [ 4294.155032] LustreError: lustre-MDT0000-mdc-ffff8babe0528000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 4312.655985] Lustre: DEBUG MARKER: == recovery-small test 65: lock enqueue for destroyed export ========================================================== 10:19:59 (1761315599) [ 4313.021393] Lustre: Mounted lustre-client [ 4320.109273] LustreError: lustre-OST0000-osc-ffff8babe0528000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 4327.698096] Lustre: Unmounted lustre-client [ 4334.042854] Lustre: DEBUG MARKER: == recovery-small test 66: lock enqueue re-send vs client eviction ========================================================== 10:20:21 (1761315621) [ 4341.736073] Lustre: lustre-MDT0000-mdc-ffff8babe0528000: Connection to lustre-MDT0000 (at 192.168.203.124@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 4341.742494] Lustre: Skipped 20 previous similar messages [ 4341.756860] LustreError: lustre-MDT0000-mdc-ffff8babe0528000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 4341.786363] Lustre: lustre-MDT0000-mdc-ffff8babe0528000: Connection restored to 192.168.203.124@tcp (at 192.168.203.124@tcp) [ 4341.792036] Lustre: Skipped 22 previous similar messages [ 4347.293375] Lustre: DEBUG MARKER: == recovery-small test 67: connect vs import invalidate race ========================================================== 10:20:34 (1761315634) [ 4347.447686] LustreError: 62386:0:(libcfs_fail.h:169:cfs_race()) cfs_race id 531 sleeping [ 4351.976050] LustreError: lustre-MDT0000-mdc-ffff8babe0528000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 4351.984273] LustreError: 62405:0:(libcfs_fail.h:180:cfs_race()) cfs_fail_race id 531 waking [ 4351.988711] LustreError: 62386:0:(libcfs_fail.h:178:cfs_race()) cfs_fail_race id 531 awake: rc=462 [ 4351.991252] LustreError: 62386:0:(import.c:702:ptlrpc_connect_import_locked()) already connecting [ 4352.021987] LustreError: 62410:0:(file.c:5205:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 4353.141977] LustreError: 62422:0:(file.c:5205:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 4354.272498] LustreError: 62433:0:(file.c:5205:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 4356.510253] LustreError: 62455:0:(file.c:5205:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 4356.513438] LustreError: 62455:0:(file.c:5205:ll_inode_revalidate_fini()) Skipped 1 previous similar message [ 4361.002607] LustreError: 62500:0:(file.c:5205:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 4361.008224] LustreError: 62500:0:(file.c:5205:ll_inode_revalidate_fini()) Skipped 3 previous similar messages [ 4368.377926] Lustre: DEBUG MARKER: == recovery-small test 100: IR: Make sure normal recovery still works w/o IR ========================================================== 10:20:55 (1761315655) [ 4401.597153] Lustre: DEBUG MARKER: oleg324-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 4402.951903] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4411.930352] Lustre: DEBUG MARKER: == recovery-small test 101a: IR: Make sure IR works w/o normal recovery ========================================================== 10:21:38 (1761315698) [ 4444.330078] Lustre: DEBUG MARKER: oleg324-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 4445.728407] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4454.940225] Lustre: DEBUG MARKER: == recovery-small test 101b: IR: Make sure IR works w/o normal recovery and proceed EAGAIN ========================================================== 10:22:22 (1761315742) [ 4512.760677] Lustre: DEBUG MARKER: oleg324-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 4514.512650] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4521.445542] Lustre: DEBUG MARKER: == recovery-small test 102: IR: New client gets updated nidtbl after MGS restart ========================================================== 10:23:28 (1761315808) [ 4552.755680] Lustre: DEBUG MARKER: oleg324-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 4554.199216] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4558.835029] Lustre: Unmounted lustre-client [ 4603.027983] Lustre: DEBUG MARKER: oleg324-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 4605.135296] Lustre: Mounted lustre-client [ 4610.912315] Lustre: DEBUG MARKER: == recovery-small test 103: IR: MDS can start w/o MGS and get updated nidtbl later ========================================================== 10:24:57 (1761315897) [ 4612.992400] Lustre: DEBUG MARKER: SKIP: recovery-small test_103 needs separate mgs and mds [ 4614.457337] Lustre: DEBUG MARKER: == recovery-small test 104: IR: ost can disable IR voluntarily ========================================================== 10:25:01 (1761315901) [ 4636.542552] Lustre: DEBUG MARKER: == recovery-small test 105: IR: NON IR clients support === 10:25:23 (1761315923) [ 4637.578059] Lustre: DEBUG MARKER: SKIP: recovery-small test_105 Needs multiple clients [ 4638.931065] Lustre: DEBUG MARKER: == recovery-small test 106: lightweight connection support ========================================================== 10:25:26 (1761315926) [ 4640.252427] Lustre: *** cfs_fail_loc=805, val=0*** [ 4640.308592] Lustre: Mounted lustre-client [ 4646.672668] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4657.631158] Lustre: 2265:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1761315938/real 1761315938] req@00000000c57eb505 x1846868839349184/t0(0) o400->MGC192.168.203.124@tcp@192.168.203.124@tcp:26/25 lens 224/224 e 0 to 1 dl 1761315945 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:3.0' [ 4657.649554] Lustre: 2265:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 70 previous similar messages [ 4657.657513] LustreError: 166-1: MGC192.168.203.124@tcp: Connection to MGS (at 192.168.203.124@tcp) was lost; in progress operations using this service will fail [ 4675.052977] Lustre: Evicted from MGS (at 192.168.203.124@tcp) after server handle changed from 0x38552adf45dac0b to 0x38552adf45db12f [ 4681.192241] Lustre: Unmounted lustre-client [ 4687.591632] Lustre: DEBUG MARKER: == recovery-small test 107: drop reint reply, then restart MDT ========================================================== 10:26:14 (1761315974) [ 4719.141635] LustreError: 2262:0:(client.c:3161:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@000000003368eb38 x1846868839356736/t94489280515(94489280515) o101->lustre-MDT0000-mdc-ffff8babd83c5000@192.168.203.124@tcp:12/10 lens 664/600 e 0 to 0 dl 1761316063 ref 2 fl Interpret:RPQU/4/0 rc 301/301 job:'multiop.0' [ 4730.866952] Lustre: DEBUG MARKER: oleg324-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4732.340177] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4740.101731] Lustre: DEBUG MARKER: == recovery-small test 108: client eviction don't crash == 10:27:07 (1761316027) [ 4744.705194] LustreError: 2262:0:(osc_request.c:1037:osc_init_grant()) lustre-OST0000-osc-ffff8babd83c5000: granted 8437760 but already consumed 16801792 [ 4744.720203] LustreError: lustre-OST0000-osc-ffff8babd83c5000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 4744.733898] Lustre: 2266:0:(llite_lib.c:3595:ll_dirty_page_discard_warn()) lustre: dirty page discard: 192.168.203.124@tcp:/lustre/fid: [0x20000a042:0x6:0x0]// may get corrupted (rc -5) [ 4744.933590] LustreError: 73940:0:(ldlm_resource.c:1127:ldlm_resource_complain()) lustre-OST0000-osc-ffff8babd83c5000: namespace resource [0x4be2:0x0:0x0].0x0 (00000000be91d467) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 4751.644603] Lustre: DEBUG MARKER: == recovery-small test 110a: create remote directory: drop client req ========================================================== 10:27:18 (1761316038) [ 4817.290896] Lustre: DEBUG MARKER: == recovery-small test 110b: create remote directory: drop Master rep ========================================================== 10:28:24 (1761316104) [ 4880.487826] Lustre: DEBUG MARKER: == recovery-small test 110c: create remote directory: drop update rep on slave MDT ========================================================== 10:29:27 (1761316167) [ 4932.090540] Lustre: DEBUG MARKER: == recovery-small test 110d: remove remote directory: drop client req ========================================================== 10:30:19 (1761316219) [ 4998.111578] Lustre: lustre-MDT0000-mdc-ffff8babd83c5000: Connection to lustre-MDT0000 (at 192.168.203.124@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 4998.116354] Lustre: Skipped 12 previous similar messages [ 4998.127331] Lustre: lustre-MDT0000-mdc-ffff8babd83c5000: Connection restored to (at 192.168.203.124@tcp) [ 4998.131733] Lustre: Skipped 12 previous similar messages [ 5003.241341] Lustre: DEBUG MARKER: == recovery-small test 110e: remove remote directory: drop master rep ========================================================== 10:31:30 (1761316290) [ 5074.341802] Lustre: DEBUG MARKER: == recovery-small test 110f: remove remote directory: drop slave rep ========================================================== 10:32:41 (1761316361) [ 5124.810581] Lustre: DEBUG MARKER: == recovery-small test 110g: drop reply during migration ========================================================== 10:33:31 (1761316411) [ 5196.918342] Lustre: DEBUG MARKER: == recovery-small test 110h: drop update reply during cross-MDT file rename ========================================================== 10:34:44 (1761316484) [ 5247.913454] Lustre: DEBUG MARKER: == recovery-small test 110i: drop update reply during cross-MDT dir rename ========================================================== 10:35:35 (1761316535) [ 5300.000776] Lustre: DEBUG MARKER: == recovery-small test 110j: drop update reply during cross-MDT ln ========================================================== 10:36:27 (1761316587) [ 5348.749528] Lustre: DEBUG MARKER: == recovery-small test 110k: FID_QUERY failed during recovery ========================================================== 10:37:16 (1761316636) [ 5348.918748] Lustre: Unmounted lustre-client [ 5376.613722] LustreError: 11-0: lustre-MDT0001-mdc-ffff8babc4bd6000: operation mds_connect to node 192.168.203.124@tcp failed: rc = -16 [ 5376.620788] LustreError: Skipped 1 previous similar message [ 5376.625400] Lustre: Mounted lustre-client [ 5393.087708] Lustre: DEBUG MARKER: == recovery-small test 110m: update resent vs original RPC race ========================================================== 10:38:00 (1761316680) [ 5403.745398] Lustre: DEBUG MARKER: == recovery-small test 111: mdd setup fail should not cause umount oops ========================================================== 10:38:10 (1761316690) [ 5413.793457] Lustre: 2263:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1761316695/real 1761316695] req@000000009c054054 x1846868839431488/t0(0) o400->MGC192.168.203.124@tcp@192.168.203.124@tcp:26/25 lens 224/224 e 0 to 1 dl 1761316702 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:1.0' [ 5413.808397] Lustre: 2263:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 6 previous similar messages [ 5413.811623] LustreError: 166-1: MGC192.168.203.124@tcp: Connection to MGS (at 192.168.203.124@tcp) was lost; in progress operations using this service will fail [ 5413.818675] LustreError: Skipped 1 previous similar message [ 5420.013110] Lustre: Evicted from MGS (at 192.168.203.124@tcp) after server handle changed from 0x38552adf45dd1e3 to 0x38552adf45dd8e3 [ 5420.021619] Lustre: Skipped 1 previous similar message [ 5427.140832] Lustre: DEBUG MARKER: == recovery-small test 112a: bulk resend while orignal request is in progress ========================================================== 10:38:34 (1761316714) [ 5455.206506] Lustre: DEBUG MARKER: == recovery-small test 115a: read: late REQ MDunlink and no bulk ========================================================== 10:39:02 (1761316742) [ 5455.526395] Lustre: *** cfs_fail_loc=51b, val=0*** [ 5464.663621] Lustre: DEBUG MARKER: == recovery-small test 115b: write: late REQ MDunlink and no bulk ========================================================== 10:39:11 (1761316751) [ 5464.940145] Lustre: *** cfs_fail_loc=51b, val=0*** [ 5473.751930] Lustre: DEBUG MARKER: == recovery-small test 115c: read: late Reply MDunlink and no bulk ========================================================== 10:39:20 (1761316760) [ 5474.016577] Lustre: *** cfs_fail_loc=50f, val=0*** [ 5481.178483] Lustre: DEBUG MARKER: == recovery-small test 115d: write: late Reply MDunlink and no bulk ========================================================== 10:39:28 (1761316768) [ 5481.382141] Lustre: *** cfs_fail_loc=50f, val=0*** [ 5488.222879] Lustre: DEBUG MARKER: == recovery-small test 115e: read: late Bulk MDunlink and no reply ========================================================== 10:39:35 (1761316775) [ 5488.622071] Lustre: *** cfs_fail_loc=510, val=0*** [ 5495.552824] Lustre: DEBUG MARKER: == recovery-small test 115f: read: late REQ MDunlink and no reply ========================================================== 10:39:42 (1761316782) [ 5495.965590] Lustre: *** cfs_fail_loc=51b, val=0*** [ 5556.869650] Lustre: DEBUG MARKER: == recovery-small test 115g: read: late REQ MDunlink and Reply MDunlink ========================================================== 10:40:44 (1761316844) [ 5557.347234] Lustre: *** cfs_fail_loc=51c, val=0*** [ 5612.513132] Lustre: lustre-OST0000-osc-ffff8babc4bd6000: Connection to lustre-OST0000 (at 192.168.203.124@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 5612.524441] Lustre: Skipped 5 previous similar messages [ 5618.061819] Lustre: DEBUG MARKER: == recovery-small test 120: flock race: completion vs. evict ========================================================== 10:41:45 (1761316905) [ 5618.405133] LustreError: 88589:0:(fail.c:138:__cfs_fail_timeout_set()) cfs_fail_timeout id 320 sleeping for 4000ms [ 5621.204424] LustreError: 11-0: lustre-MDT0000-mdc-ffff8babc4bd6000: operation ldlm_enqueue to node 192.168.203.124@tcp failed: rc = -107 [ 5621.226359] LustreError: lustre-MDT0000-mdc-ffff8babc4bd6000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5621.243827] LustreError: 88607:0:(file.c:246:ll_close_inode_openhandle()) lustre-clilmv-ffff8babc4bd6000: inode [0x20000afe1:0x4:0x0] mdc close failed: rc = -108 [ 5621.267184] LustreError: 88607:0:(ldlm_resource.c:1127:ldlm_resource_complain()) lustre-MDT0000-mdc-ffff8babc4bd6000: namespace resource [0x20000afe1:0xa:0x0].0xc (00000000ed598e09) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 5621.300836] Lustre: lustre-MDT0000-mdc-ffff8babc4bd6000: Connection restored to (at 192.168.203.124@tcp) [ 5621.307525] Lustre: Skipped 4 previous similar messages [ 5622.481102] LustreError: 88589:0:(fail.c:149:__cfs_fail_timeout_set()) cfs_fail_timeout id 320 awake [ 5624.563963] LustreError: 88621:0:(fail.c:138:__cfs_fail_timeout_set()) cfs_fail_timeout id 320 sleeping for 4000ms [ 5627.378610] LustreError: lustre-MDT0000-mdc-ffff8babc4bd6000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5627.404938] LustreError: 88639:0:(ldlm_resource.c:1127:ldlm_resource_complain()) lustre-MDT0000-mdc-ffff8babc4bd6000: namespace resource [0x20000afe1:0xa:0x0].0xc (000000003b4de293) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 5627.429813] LustreError: 88639:0:(ldlm_resource.c:1127:ldlm_resource_complain()) Skipped 1 previous similar message [ 5627.438680] LustreError: 88644:0:(file.c:5205:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 5627.454582] LustreError: 88644:0:(file.c:5205:ll_inode_revalidate_fini()) Skipped 1 previous similar message [ 5628.639223] LustreError: 88621:0:(fail.c:149:__cfs_fail_timeout_set()) cfs_fail_timeout id 320 awake [ 5632.623794] LustreError: 88652:0:(fail.c:138:__cfs_fail_timeout_set()) cfs_fail_timeout id 320 sleeping for 4000ms [ 5635.533124] LustreError: lustre-MDT0000-mdc-ffff8babc4bd6000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5635.549373] LustreError: 88670:0:(ldlm_resource.c:1127:ldlm_resource_complain()) lustre-MDT0000-mdc-ffff8babc4bd6000: namespace resource [0x20000afe1:0xa:0x0].0xc (0000000062b2b722) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 5635.560876] LustreError: 88670:0:(ldlm_resource.c:1127:ldlm_resource_complain()) Skipped 1 previous similar message [ 5636.719170] LustreError: 88652:0:(fail.c:149:__cfs_fail_timeout_set()) cfs_fail_timeout id 320 awake [ 5636.822558] LustreError: 88682:0:(fail.c:138:__cfs_fail_timeout_set()) cfs_fail_timeout id 321 sleeping for 4000ms [ 5639.595377] LustreError: lustre-MDT0000-mdc-ffff8babc4bd6000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5639.649303] LustreError: 88704:0:(file.c:5205:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 5640.911445] LustreError: 88682:0:(fail.c:149:__cfs_fail_timeout_set()) cfs_fail_timeout id 321 awake [ 5640.917424] LustreError: 88682:0:(file.c:246:ll_close_inode_openhandle()) lustre-clilmv-ffff8babc4bd6000: inode [0x20000afe1:0xa:0x0] mdc close failed: rc = -108 [ 5640.943173] LustreError: 88682:0:(file.c:246:ll_close_inode_openhandle()) Skipped 4 previous similar messages [ 5641.864959] LustreError: 88722:0:(file.c:5205:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 5641.870446] LustreError: 88722:0:(file.c:5205:ll_inode_revalidate_fini()) Skipped 12 previous similar messages [ 5646.408686] LustreError: 88759:0:(fail.c:138:__cfs_fail_timeout_set()) cfs_fail_timeout id 321 sleeping for 4000ms [ 5649.168815] LustreError: lustre-MDT0000-mdc-ffff8babc4bd6000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5649.184312] LustreError: 88776:0:(ldlm_resource.c:1127:ldlm_resource_complain()) lustre-MDT0000-mdc-ffff8babc4bd6000: namespace resource [0x20000afe1:0xa:0x0].0xc (000000003ba5ad61) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 5649.191186] LustreError: 88776:0:(ldlm_resource.c:1127:ldlm_resource_complain()) Skipped 1 previous similar message [ 5650.471131] LustreError: 88759:0:(fail.c:149:__cfs_fail_timeout_set()) cfs_fail_timeout id 321 awake [ 5654.483330] LustreError: 88789:0:(fail.c:138:__cfs_fail_timeout_set()) cfs_fail_timeout id 321 sleeping for 4000ms [ 5657.124488] LustreError: lustre-MDT0000-mdc-ffff8babc4bd6000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5657.134350] LustreError: 88807:0:(ldlm_resource.c:1127:ldlm_resource_complain()) lustre-MDT0000-mdc-ffff8babc4bd6000: namespace resource [0x200000007:0x1:0x0].0x0 (00000000ea5655e3) refcount nonzero (2) after lock cleanup; forcing cleanup. [ 5657.142887] LustreError: 88807:0:(ldlm_resource.c:1127:ldlm_resource_complain()) Skipped 1 previous similar message [ 5658.543114] LustreError: 88789:0:(fail.c:149:__cfs_fail_timeout_set()) cfs_fail_timeout id 321 awake [ 5661.389127] LustreError: lustre-MDT0000-mdc-ffff8babc4bd6000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5665.503682] LustreError: lustre-MDT0000-mdc-ffff8babc4bd6000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5665.582405] LustreError: 88871:0:(file.c:5205:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 5665.587359] LustreError: 88871:0:(file.c:5205:ll_inode_revalidate_fini()) Skipped 13 previous similar messages [ 5666.871688] LustreError: 88849:0:(file.c:246:ll_close_inode_openhandle()) lustre-clilmv-ffff8babc4bd6000: inode [0x20000afe1:0xa:0x0] mdc close failed: rc = -108 [ 5674.281303] LustreError: 88922:0:(fail.c:138:__cfs_fail_timeout_set()) cfs_fail_timeout id 320 sleeping for 4000ms [ 5674.285294] LustreError: 88922:0:(fail.c:138:__cfs_fail_timeout_set()) Skipped 2 previous similar messages [ 5677.546580] LustreError: lustre-MDT0000-mdc-ffff8babc4bd6000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5677.605991] LustreError: 88948:0:(file.c:5205:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 5677.610955] LustreError: 88948:0:(file.c:5205:ll_inode_revalidate_fini()) Skipped 26 previous similar messages [ 5678.367182] LustreError: 88922:0:(fail.c:149:__cfs_fail_timeout_set()) cfs_fail_timeout id 320 awake [ 5678.375934] LustreError: 88922:0:(fail.c:149:__cfs_fail_timeout_set()) Skipped 2 previous similar messages [ 5678.386283] LustreError: 88922:0:(file.c:246:ll_close_inode_openhandle()) lustre-clilmv-ffff8babc4bd6000: inode [0x20000afe1:0xa:0x0] mdc close failed: rc = -108 [ 5688.259691] Lustre: DEBUG MARKER: == recovery-small test 113: ldlm enqueue dropped reply should not cause deadlocks ========================================================== 10:42:55 (1761316975) [ 5753.174062] LustreError: 81118:0:(fail.c:138:__cfs_fail_timeout_set()) cfs_fail_timeout id 31f sleeping for 4000ms [ 5753.177846] LustreError: 81118:0:(fail.c:138:__cfs_fail_timeout_set()) Skipped 1 previous similar message [ 5757.256022] LustreError: 81118:0:(fail.c:149:__cfs_fail_timeout_set()) cfs_fail_timeout id 31f awake [ 5757.263382] LustreError: 81118:0:(fail.c:149:__cfs_fail_timeout_set()) Skipped 1 previous similar message [ 5763.557510] Lustre: DEBUG MARKER: == recovery-small test 130a: enqueue resend on not existing file ========================================================== 10:44:10 (1761317050) [ 5835.285100] Lustre: DEBUG MARKER: == recovery-small test 130b: enqueue resend on a stale inode ========================================================== 10:45:22 (1761317122) [ 5904.098387] Lustre: DEBUG MARKER: == recovery-small test 130c: layout intent resend on a stale inode ========================================================== 10:46:31 (1761317191) [ 5937.810318] Lustre: DEBUG MARKER: == recovery-small test 132: long punch =================== 10:47:04 (1761317224) [ 5938.611517] Lustre: Mounted lustre-client [ 6061.620666] Lustre: Unmounted lustre-client [ 6070.357266] Lustre: DEBUG MARKER: == recovery-small test 131: IO vs evict results to IO under staled lock ========================================================== 10:49:17 (1761317357) [ 6070.963935] LustreError: 93367:0:(fail.c:138:__cfs_fail_timeout_set()) cfs_fail_timeout id 414 sleeping for 4000ms [ 6074.238983] LustreError: 11-0: lustre-OST0000-osc-ffff8babc4bd6000: operation ost_statfs to node 192.168.203.124@tcp failed: rc = -107 [ 6074.247119] LustreError: Skipped 8 previous similar messages [ 6074.272188] LustreError: lustre-OST0000-osc-ffff8babc4bd6000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 6074.284949] LustreError: 93453:0:(ldlm_resource.c:1127:ldlm_resource_complain()) lustre-OST0000-osc-ffff8babc4bd6000: namespace resource [0x4c0d:0x0:0x0].0x0 (00000000ea5655e3) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 6074.312951] LustreError: 93453:0:(ldlm_resource.c:1127:ldlm_resource_complain()) Skipped 4 previous similar messages [ 6075.031152] LustreError: 93367:0:(fail.c:149:__cfs_fail_timeout_set()) cfs_fail_timeout id 414 awake [ 6075.034189] Lustre: 2265:0:(llite_lib.c:3595:ll_dirty_page_discard_warn()) lustre: dirty page discard: 192.168.203.124@tcp:/lustre/fid: [0x20000bf89:0x9:0x0]// may get corrupted (rc -108) [ 6080.158947] Lustre: DEBUG MARKER: == recovery-small test 133: don't fail on flock resend === 10:49:27 (1761317367) [ 6100.959148] Lustre: 94064:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1761317371/real 1761317371] req@000000003d7b9646 x1846868839525504/t0(0) o101->lustre-MDT0000-mdc-ffff8babc4bd6000@192.168.203.124@tcp:12/10 lens 328/344 e 0 to 1 dl 1761317389 ref 2 fl Rpc:XQr/0/ffffffff rc 0/-1 job:'multiop.0' [ 6100.980192] Lustre: 94064:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 6 previous similar messages [ 6126.747727] Lustre: DEBUG MARKER: == recovery-small test 134: race between failover and search for reply data free slot ========================================================== 10:50:14 (1761317414) [ 6128.129200] Lustre: DEBUG MARKER: SKIP: recovery-small test_134 Need 2+ clients, have 1 [ 6129.459837] Lustre: DEBUG MARKER: == recovery-small test 135: DOM: open/create resend to return size ========================================================== 10:50:16 (1761317416) [ 6153.908833] Lustre: DEBUG MARKER: SKIP: recovery-small test_136 skipping excluded test 136 [ 6155.412709] Lustre: DEBUG MARKER: == recovery-small test 137: late resend must be skipped if already applied ========================================================== 10:50:42 (1761317442) [ 6176.921660] Lustre: DEBUG MARKER: == recovery-small test 138: Umount MDT during recovery === 10:51:03 (1761317463) [ 6178.656945] Lustre: Unmounted lustre-client [ 6305.804235] Lustre: Mounted lustre-client [ 6310.665248] Lustre: DEBUG MARKER: == recovery-small test 139: corrupted catid won't cause crash ========================================================== 10:53:17 (1761317597) [ 6316.024475] Lustre: lustre-MDT0000-mdc-ffff8babe0529000: Connection to lustre-MDT0000 (at 192.168.203.124@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 6316.037205] Lustre: Skipped 16 previous similar messages [ 6321.134113] LustreError: 166-1: MGC192.168.203.124@tcp: Connection to MGS (at 192.168.203.124@tcp) was lost; in progress operations using this service will fail [ 6321.161069] Lustre: Evicted from MGS (at 192.168.203.124@tcp) after server handle changed from 0x38552adf45df3cb to 0x38552adf45df62c [ 6321.185859] Lustre: MGC192.168.203.124@tcp: Connection restored to (at 192.168.203.124@tcp) [ 6321.200396] Lustre: Skipped 15 previous similar messages [ 6333.761327] Lustre: DEBUG MARKER: == recovery-small test 140a: local mount is flagged properly ========================================================== 10:53:40 (1761317620) [ 6361.089524] Lustre: DEBUG MARKER: == recovery-small test 140b: local mount is excluded from recovery ========================================================== 10:54:08 (1761317648) [ 6374.170843] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 6419.478751] Lustre: DEBUG MARKER: oleg324-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 6420.812749] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6428.482279] Lustre: DEBUG MARKER: == recovery-small test 141: do not lose locks on MGS restart ========================================================== 10:55:15 (1761317715) [ 6430.339614] Lustre: DEBUG MARKER: SKIP: recovery-small test_141 cannot run in local mode or from build tree [ 6431.698706] Lustre: DEBUG MARKER: == recovery-small test 142: orphan name stub can be cleaned up in startup ========================================================== 10:55:18 (1761317718) [ 6451.222548] Lustre: DEBUG MARKER: == recovery-small test 143: orphan cleanup thread shouldn't be blocked even delete failed ========================================================== 10:55:38 (1761317738) [ 6485.570798] Lustre: DEBUG MARKER: == recovery-small test 144a: MDT failover should stop precreation threads ========================================================== 10:56:12 (1761317772) [ 6492.561114] LustreError: 11-0: lustre-OST0000-osc-ffff8babe0529000: operation ost_setattr to node 192.168.203.124@tcp failed: rc = -19 [ 6492.563914] LustreError: Skipped 1 previous similar message [ 6523.192415] Lustre: DEBUG MARKER: oleg324-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 6524.565512] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 6618.131757] Lustre: DEBUG MARKER: oleg324-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 6619.476874] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6636.511302] INFO: task touch:103066 blocked for more than 120 seconds. [ 6636.513170] Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 6636.516341] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 6636.519293] task:touch state:D stack:0 pid:103066 ppid:102764 flags:0x80000004 [ 6636.522350] Call Trace: [ 6636.523254] __schedule+0x351/0xcb0 [ 6636.527243] schedule+0xc0/0x180 [ 6636.528534] schedule_preempt_disabled+0x21/0x40 [ 6636.530249] rwsem_down_write_slowpath+0x5d7/0xa40 [ 6636.532101] down_write+0x80/0xd0 [ 6636.533228] do_last+0x2eb/0xfc0 [ 6636.538468] ? nd_jump_root+0xe5/0x160 [ 6636.541877] ? path_init+0x437/0x520 [ 6636.543419] path_openat+0xf7/0x500 [ 6636.544555] ? __mod_lruvec_state+0x5a/0x80 [ 6636.548825] do_filp_open+0x99/0x140 [ 6636.549866] ? getname_flags+0x6e/0x330 [ 6636.552035] ? __check_object_size+0xff/0x256 [ 6636.557543] ? do_raw_spin_unlock+0x75/0x190 [ 6636.560245] ? _raw_spin_unlock+0x12/0x30 [ 6636.563226] do_sys_openat2+0x2b4/0x410 [ 6636.564806] do_sys_open+0x73/0xa0 [ 6636.566432] __x64_sys_openat+0x24/0x30 [ 6636.567542] do_syscall_64+0xc1/0x440 [ 6636.568913] entry_SYSCALL_64_after_hwframe+0x49/0xae [ 6636.570637] RIP: 0033:0x7fb639b1e332 [ 6636.571857] Code: Unable to access opcode bytes at RIP 0x7fb639b1e308. [ 6636.574225] RSP: 002b:00007fffff93c990 EFLAGS: 00000246 ORIG_RAX: 0000000000000101 [ 6636.577388] RAX: ffffffffffffffda RBX: 00000000ffffffff RCX: 00007fb639b1e332 [ 6636.579883] RDX: 0000000000000941 RSI: 00007fffff93df4d RDI: 00000000ffffff9c [ 6636.582917] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000001 [ 6636.585684] R10: 00000000000001b6 R11: 0000000000000246 R12: 0000000000000001 [ 6636.587892] R13: 0000000000000001 R14: 00007fffff93df4d R15: 00007fb639dc1374 [ 6636.590936] INFO: task touch:103070 blocked for more than 120 seconds. [ 6636.593219] Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 6636.597798] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 6636.600488] task:touch state:D stack:0 pid:103070 ppid:102764 flags:0x80000004 [ 6636.608558] Call Trace: [ 6636.612724] __schedule+0x351/0xcb0 [ 6636.616772] schedule+0xc0/0x180 [ 6636.618704] schedule_preempt_disabled+0x21/0x40 [ 6636.620368] rwsem_down_write_slowpath+0x5d7/0xa40 [ 6636.622108] down_write+0x80/0xd0 [ 6636.624801] do_last+0x2eb/0xfc0 [ 6636.625678] ? nd_jump_root+0xe5/0x160 [ 6636.628953] ? path_init+0x437/0x520 [ 6636.631014] path_openat+0xf7/0x500 [ 6636.633790] ? __mod_lruvec_state+0x5a/0x80 [ 6636.635315] do_filp_open+0x99/0x140 [ 6636.636714] ? getname_flags+0x6e/0x330 [ 6636.638176] ? __check_object_size+0xff/0x256 [ 6636.639767] ? do_raw_spin_unlock+0x75/0x190 [ 6636.641344] ? _raw_spin_unlock+0x12/0x30 [ 6636.642767] do_sys_openat2+0x2b4/0x410 [ 6636.644192] do_sys_open+0x73/0xa0 [ 6636.645466] __x64_sys_openat+0x24/0x30 [ 6636.646751] do_syscall_64+0xc1/0x440 [ 6636.647892] entry_SYSCALL_64_after_hwframe+0x49/0xae [ 6636.649861] RIP: 0033:0x7f1e82a6e332 [ 6636.651337] Code: Unable to access opcode bytes at RIP 0x7f1e82a6e308. [ 6636.653700] RSP: 002b:00007ffee129a930 EFLAGS: 00000246 ORIG_RAX: 0000000000000101 [ 6636.656193] RAX: ffffffffffffffda RBX: 00000000ffffffff RCX: 00007f1e82a6e332 [ 6636.658705] RDX: 0000000000000941 RSI: 00007ffee129bf4d RDI: 00000000ffffff9c [ 6636.661969] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000001 [ 6636.664855] R10: 00000000000001b6 R11: 0000000000000246 R12: 0000000000000001 [ 6636.667251] R13: 0000000000000001 R14: 00007ffee129bf4d R15: 00007f1e82d11374 [ 6636.671291] INFO: task touch:103071 blocked for more than 120 seconds. [ 6636.674375] Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 6636.683635] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 6636.686581] task:touch state:D stack:0 pid:103071 ppid:102764 flags:0x80000004 [ 6636.690873] Call Trace: [ 6636.692260] __schedule+0x351/0xcb0 [ 6636.693988] schedule+0xc0/0x180 [ 6636.695684] schedule_preempt_disabled+0x21/0x40 [ 6636.697960] rwsem_down_write_slowpath+0x5d7/0xa40 [ 6636.700193] down_write+0x80/0xd0 [ 6636.702047] do_last+0x2eb/0xfc0 [ 6636.704318] ? nd_jump_root+0xe5/0x160 [ 6636.707084] ? path_init+0x437/0x520 [ 6636.709109] path_openat+0xf7/0x500 [ 6636.710557] do_filp_open+0x99/0x140 [ 6636.711953] ? getname_flags+0x6e/0x330 [ 6636.713462] ? __check_object_size+0xff/0x256 [ 6636.716519] ? do_raw_spin_unlock+0x75/0x190 [ 6636.718450] ? _raw_spin_unlock+0x12/0x30 [ 6636.720122] do_sys_openat2+0x2b4/0x410 [ 6636.721595] do_sys_open+0x73/0xa0 [ 6636.726675] __x64_sys_openat+0x24/0x30 [ 6636.728452] do_syscall_64+0xc1/0x440 [ 6636.731448] entry_SYSCALL_64_after_hwframe+0x49/0xae [ 6636.736103] RIP: 0033:0x7f5917975332 [ 6636.739124] Code: Unable to access opcode bytes at RIP 0x7f5917975308. [ 6636.741418] RSP: 002b:00007ffe3748bae0 EFLAGS: 00000246 ORIG_RAX: 0000000000000101 [ 6636.744122] RAX: ffffffffffffffda RBX: 00000000ffffffff RCX: 00007f5917975332 [ 6636.751241] RDX: 0000000000000941 RSI: 00007ffe3748cf4d RDI: 00000000ffffff9c [ 6636.758264] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000001 [ 6636.761879] R10: 00000000000001b6 R11: 0000000000000246 R12: 0000000000000001 [ 6636.766144] R13: 0000000000000001 R14: 00007ffe3748cf4d R15: 00007f5917c18374 [ 6636.768887] INFO: task touch:103072 blocked for more than 120 seconds. [ 6636.774068] Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 6636.779663] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 6636.785460] task:touch state:D stack:0 pid:103072 ppid:102764 flags:0x80000004 [ 6636.789503] Call Trace: [ 6636.792258] __schedule+0x351/0xcb0 [ 6636.793839] schedule+0xc0/0x180 [ 6636.795152] schedule_preempt_disabled+0x21/0x40 [ 6636.796969] rwsem_down_write_slowpath+0x5d7/0xa40 [ 6636.799736] down_write+0x80/0xd0 [ 6636.801456] do_last+0x2eb/0xfc0 [ 6636.803855] ? nd_jump_root+0xe5/0x160 [ 6636.805387] ? path_init+0x437/0x520 [ 6636.806572] path_openat+0xf7/0x500 [ 6636.807838] ? __mod_lruvec_state+0x5a/0x80 [ 6636.810234] do_filp_open+0x99/0x140 [ 6636.811497] ? getname_flags+0x6e/0x330 [ 6636.813367] ? __check_object_size+0xff/0x256 [ 6636.816748] ? do_raw_spin_unlock+0x75/0x190 [ 6636.818875] ? _raw_spin_unlock+0x12/0x30 [ 6636.821446] do_sys_openat2+0x2b4/0x410 [ 6636.823444] do_sys_open+0x73/0xa0 [ 6636.825053] __x64_sys_openat+0x24/0x30 [ 6636.826607] do_syscall_64+0xc1/0x440 [ 6636.828361] entry_SYSCALL_64_after_hwframe+0x49/0xae [ 6636.830962] RIP: 0033:0x7fa55064e332 [ 6636.834298] Code: Unable to access opcode bytes at RIP 0x7fa55064e308. [ 6636.840816] RSP: 002b:00007fffcace9840 EFLAGS: 00000246 ORIG_RAX: 0000000000000101 [ 6636.848387] RAX: ffffffffffffffda RBX: 00000000ffffffff RCX: 00007fa55064e332 [ 6636.854071] RDX: 0000000000000941 RSI: 00007fffcacebf4d RDI: 00000000ffffff9c [ 6636.861327] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000001 [ 6636.869167] R10: 00000000000001b6 R11: 0000000000000246 R12: 0000000000000001 [ 6636.872027] R13: 0000000000000001 R14: 00007fffcacebf4d R15: 00007fa5508f1374 [ 6636.874825] INFO: task touch:103073 blocked for more than 120 seconds. [ 6636.878995] Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 6636.884222] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 6636.888148] task:touch state:D stack:0 pid:103073 ppid:102764 flags:0x80000004 [ 6636.892605] Call Trace: [ 6636.893465] __schedule+0x351/0xcb0 [ 6636.894624] schedule+0xc0/0x180 [ 6636.900197] schedule_preempt_disabled+0x21/0x40 [ 6636.904077] rwsem_down_write_slowpath+0x5d7/0xa40 [ 6636.906234] down_write+0x80/0xd0 [ 6636.909738] do_last+0x2eb/0xfc0 [ 6636.911807] ? nd_jump_root+0xe5/0x160 [ 6636.913163] ? path_init+0x437/0x520 [ 6636.914470] path_openat+0xf7/0x500 [ 6636.916310] ? __mod_lruvec_state+0x5a/0x80 [ 6636.918968] do_filp_open+0x99/0x140 [ 6636.920479] ? getname_flags+0x6e/0x330 [ 6636.922104] ? __check_object_size+0xff/0x256 [ 6636.924092] ? do_raw_spin_unlock+0x75/0x190 [ 6636.926502] ? _raw_spin_unlock+0x12/0x30 [ 6636.928727] do_sys_openat2+0x2b4/0x410 [ 6636.930398] do_sys_open+0x73/0xa0 [ 6636.931430] __x64_sys_openat+0x24/0x30 [ 6636.932590] do_syscall_64+0xc1/0x440 [ 6636.934958] entry_SYSCALL_64_after_hwframe+0x49/0xae [ 6636.937655] RIP: 0033:0x7f06ea9de332 [ 6636.939423] Code: Unable to access opcode bytes at RIP 0x7f06ea9de308. [ 6636.941977] RSP: 002b:00007fff7346ebe0 EFLAGS: 00000246 ORIG_RAX: 0000000000000101 [ 6636.945065] RAX: ffffffffffffffda RBX: 00000000ffffffff RCX: 00007f06ea9de332 [ 6636.947417] RDX: 0000000000000941 RSI: 00007fff7346ff4d RDI: 00000000ffffff9c [ 6636.949810] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000001 [ 6636.952246] R10: 00000000000001b6 R11: 0000000000000246 R12: 0000000000000001 [ 6636.954610] R13: 0000000000000001 R14: 00007fff7346ff4d R15: 00007f06eac81374 [ 6636.956995] INFO: task touch:103074 blocked for more than 120 seconds. [ 6636.959186] Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 6636.961637] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 6636.965183] task:touch state:D stack:0 pid:103074 ppid:102764 flags:0x80000004 [ 6636.970223] Call Trace: [ 6636.971158] __schedule+0x351/0xcb0 [ 6636.972521] schedule+0xc0/0x180 [ 6636.974558] schedule_preempt_disabled+0x21/0x40 [ 6636.976209] rwsem_down_write_slowpath+0x5d7/0xa40 [ 6636.977952] down_write+0x80/0xd0 [ 6636.979110] do_last+0x2eb/0xfc0 [ 6636.980265] ? nd_jump_root+0xe5/0x160 [ 6636.981712] ? path_init+0x437/0x520 [ 6636.983202] path_openat+0xf7/0x500 [ 6636.984370] do_filp_open+0x99/0x140 [ 6636.985782] ? getname_flags+0x6e/0x330 [ 6636.987136] ? __check_object_size+0xff/0x256 [ 6636.988737] ? do_raw_spin_unlock+0x75/0x190 [ 6636.990498] ? _raw_spin_unlock+0x12/0x30 [ 6636.992460] do_sys_openat2+0x2b4/0x410 [ 6636.996172] do_sys_open+0x73/0xa0 [ 6636.997321] __x64_sys_openat+0x24/0x30 [ 6636.998513] do_syscall_64+0xc1/0x440 [ 6637.000268] entry_SYSCALL_64_after_hwframe+0x49/0xae [ 6637.002500] RIP: 0033:0x7f3963151332 [ 6637.003985] Code: Unable to access opcode bytes at RIP 0x7f3963151308. [ 6637.007899] RSP: 002b:00007ffcf23e4c60 EFLAGS: 00000246 ORIG_RAX: 0000000000000101 [ 6637.011066] RAX: ffffffffffffffda RBX: 00000000ffffffff RCX: 00007f3963151332 [ 6637.015068] RDX: 0000000000000941 RSI: 00007ffcf23e5f4d RDI: 00000000ffffff9c [ 6637.017361] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000001 [ 6637.021445] R10: 00000000000001b6 R11: 0000000000000246 R12: 0000000000000001 [ 6637.024881] R13: 0000000000000001 R14: 00007ffcf23e5f4d R15: 00007f39633f4374 [ 6637.030416] INFO: task touch:103075 blocked for more than 120 seconds. [ 6637.036253] Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 6637.040012] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 6637.046772] task:touch state:D stack:0 pid:103075 ppid:102764 flags:0x80000004 [ 6637.051447] Call Trace: [ 6637.054141] __schedule+0x351/0xcb0 [ 6637.055906] schedule+0xc0/0x180 [ 6637.058385] schedule_preempt_disabled+0x21/0x40 [ 6637.064390] rwsem_down_write_slowpath+0x5d7/0xa40 [ 6637.066459] down_write+0x80/0xd0 [ 6637.067580] do_last+0x2eb/0xfc0 [ 6637.070891] ? nd_jump_root+0xe5/0x160 [ 6637.071979] ? path_init+0x437/0x520 [ 6637.074019] path_openat+0xf7/0x500 [ 6637.076852] do_filp_open+0x99/0x140 [ 6637.079121] ? getname_flags+0x6e/0x330 [ 6637.081831] ? __check_object_size+0xff/0x256 [ 6637.083543] ? do_raw_spin_unlock+0x75/0x190 [ 6637.084940] ? _raw_spin_unlock+0x12/0x30 [ 6637.086043] do_sys_openat2+0x2b4/0x410 [ 6637.087614] do_sys_open+0x73/0xa0 [ 6637.089331] __x64_sys_openat+0x24/0x30 [ 6637.091277] do_syscall_64+0xc1/0x440 [ 6637.093363] entry_SYSCALL_64_after_hwframe+0x49/0xae [ 6637.097117] RIP: 0033:0x7f7ce441a332 [ 6637.099498] Code: Unable to access opcode bytes at RIP 0x7f7ce441a308. [ 6637.102800] RSP: 002b:00007ffc1f4ae910 EFLAGS: 00000246 ORIG_RAX: 0000000000000101 [ 6637.107333] RAX: ffffffffffffffda RBX: 00000000ffffffff RCX: 00007f7ce441a332 [ 6637.111362] RDX: 0000000000000941 RSI: 00007ffc1f4aff4d RDI: 00000000ffffff9c [ 6637.115861] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000001 [ 6637.118632] R10: 00000000000001b6 R11: 0000000000000246 R12: 0000000000000001 [ 6637.121689] R13: 0000000000000001 R14: 00007ffc1f4aff4d R15: 00007f7ce46bd374 [ 6637.124072] INFO: task touch:103076 blocked for more than 120 seconds. [ 6637.126135] Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 6637.128703] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 6637.133807] task:touch state:D stack:0 pid:103076 ppid:102764 flags:0x80000004 [ 6637.137088] Call Trace: [ 6637.139152] __schedule+0x351/0xcb0 [ 6637.141016] schedule+0xc0/0x180 [ 6637.142502] schedule_preempt_disabled+0x21/0x40 [ 6637.145040] rwsem_down_write_slowpath+0x5d7/0xa40 [ 6637.147267] down_write+0x80/0xd0 [ 6637.149268] do_last+0x2eb/0xfc0 [ 6637.150772] ? nd_jump_root+0xe5/0x160 [ 6637.152267] ? path_init+0x437/0x520 [ 6637.154082] path_openat+0xf7/0x500 [ 6637.155384] ? __mod_lruvec_state+0x5a/0x80 [ 6637.159677] do_filp_open+0x99/0x140 [ 6637.161266] ? getname_flags+0x6e/0x330 [ 6637.162688] ? __check_object_size+0xff/0x256 [ 6637.164595] ? do_raw_spin_unlock+0x75/0x190 [ 6637.166366] ? _raw_spin_unlock+0x12/0x30 [ 6637.167988] do_sys_openat2+0x2b4/0x410 [ 6637.169495] do_sys_open+0x73/0xa0 [ 6637.170985] __x64_sys_openat+0x24/0x30 [ 6637.172926] do_syscall_64+0xc1/0x440 [ 6637.174426] entry_SYSCALL_64_after_hwframe+0x49/0xae [ 6637.176341] RIP: 0033:0x7fee4957b332 [ 6637.177743] Code: Unable to access opcode bytes at RIP 0x7fee4957b308. [ 6637.180017] RSP: 002b:00007fff2239a6b0 EFLAGS: 00000246 ORIG_RAX: 0000000000000101 [ 6637.183027] RAX: ffffffffffffffda RBX: 00000000ffffffff RCX: 00007fee4957b332 [ 6637.186807] RDX: 0000000000000941 RSI: 00007fff2239cf4d RDI: 00000000ffffff9c [ 6637.189976] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000001 [ 6637.195499] R10: 00000000000001b6 R11: 0000000000000246 R12: 0000000000000001 [ 6637.199075] R13: 0000000000000001 R14: 00007fff2239cf4d R15: 00007fee4981e374 [ 6637.202238] INFO: task touch:103077 blocked for more than 120 seconds. [ 6637.205054] Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 6637.209286] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 6637.212883] task:touch state:D stack:0 pid:103077 ppid:102764 flags:0x80000004 [ 6637.217023] Call Trace: [ 6637.218167] __schedule+0x351/0xcb0 [ 6637.219296] schedule+0xc0/0x180 [ 6637.220317] schedule_preempt_disabled+0x21/0x40 [ 6637.224501] rwsem_down_write_slowpath+0x5d7/0xa40 [ 6637.227072] down_write+0x80/0xd0 [ 6637.228539] do_last+0x2eb/0xfc0 [ 6637.229802] ? nd_jump_root+0xe5/0x160 [ 6637.231196] ? path_init+0x437/0x520 [ 6637.232647] path_openat+0xf7/0x500 [ 6637.234034] do_filp_open+0x99/0x140 [ 6637.235485] ? getname_flags+0x6e/0x330 [ 6637.238066] ? __check_object_size+0xff/0x256 [ 6637.242905] ? do_raw_spin_unlock+0x75/0x190 [ 6637.244443] ? _raw_spin_unlock+0x12/0x30 [ 6637.246236] do_sys_openat2+0x2b4/0x410 [ 6637.248927] do_sys_open+0x73/0xa0 [ 6637.250705] __x64_sys_openat+0x24/0x30 [ 6637.252524] do_syscall_64+0xc1/0x440 [ 6637.254249] entry_SYSCALL_64_after_hwframe+0x49/0xae [ 6637.257542] RIP: 0033:0x7f26a02d8332 [ 6637.258883] Code: Unable to access opcode bytes at RIP 0x7f26a02d8308. [ 6637.261961] RSP: 002b:00007ffe04ed5fc0 EFLAGS: 00000246 ORIG_RAX: 0000000000000101 [ 6637.265436] RAX: ffffffffffffffda RBX: 00000000ffffffff RCX: 00007f26a02d8332 [ 6637.269598] RDX: 0000000000000941 RSI: 00007ffe04ed7f4d RDI: 00000000ffffff9c [ 6637.272439] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000001 [ 6637.275684] R10: 00000000000001b6 R11: 0000000000000246 R12: 0000000000000001 [ 6637.278539] R13: 0000000000000001 R14: 00007ffe04ed7f4d R15: 00007f26a057b374 [ 6637.282580] INFO: task touch:103078 blocked for more than 120 seconds. [ 6637.285239] Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 6637.288266] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 6637.292902] task:touch state:D stack:0 pid:103078 ppid:102764 flags:0x80000004 [ 6637.298240] Call Trace: [ 6637.300957] __schedule+0x351/0xcb0 [ 6637.303838] schedule+0xc0/0x180 [ 6637.305990] schedule_preempt_disabled+0x21/0x40 [ 6637.308515] rwsem_down_write_slowpath+0x5d7/0xa40 [ 6637.310230] down_write+0x80/0xd0 [ 6637.311537] do_last+0x2eb/0xfc0 [ 6637.314290] ? nd_jump_root+0xe5/0x160 [ 6637.316717] ? path_init+0x437/0x520 [ 6637.318456] path_openat+0xf7/0x500 [ 6637.321098] ? __mod_lruvec_state+0x5a/0x80 [ 6637.324942] do_filp_open+0x99/0x140 [ 6637.327301] ? getname_flags+0x6e/0x330 [ 6637.330356] ? __check_object_size+0xff/0x256 [ 6637.333572] ? do_raw_spin_unlock+0x75/0x190 [ 6637.335884] ? _raw_spin_unlock+0x12/0x30 [ 6637.337372] do_sys_openat2+0x2b4/0x410 [ 6637.341036] do_sys_open+0x73/0xa0 [ 6637.342352] __x64_sys_openat+0x24/0x30 [ 6637.345662] do_syscall_64+0xc1/0x440 [ 6637.348149] entry_SYSCALL_64_after_hwframe+0x49/0xae [ 6637.350538] RIP: 0033:0x7f06595cd332 [ 6637.351816] Code: Unable to access opcode bytes at RIP 0x7f06595cd308. [ 6637.354362] RSP: 002b:00007ffe5d0da5e0 EFLAGS: 00000246 ORIG_RAX: 0000000000000101 [ 6637.357657] RAX: ffffffffffffffda RBX: 00000000ffffffff RCX: 00007f06595cd332 [ 6637.360897] RDX: 0000000000000941 RSI: 00007ffe5d0dbf4d RDI: 00000000ffffff9c [ 6637.363515] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000001 [ 6637.367565] R10: 00000000000001b6 R11: 0000000000000246 R12: 0000000000000001 [ 6637.370522] R13: 0000000000000001 R14: 00007ffe5d0dbf4d R15: 00007f0659870374 [ 6652.156297] Lustre: DEBUG MARKER: oleg324-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 6653.846243] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6710.977819] Lustre: DEBUG MARKER: == recovery-small test 145: connect mdtlovs and process update logs after recovery expire ========================================================== 10:59:58 (1761317998) [ 6713.788123] Lustre: DEBUG MARKER: SKIP: recovery-small test_145 needs >= 3 MDTs [ 6715.928973] Lustre: DEBUG MARKER: == recovery-small test 147: Check client reconnect ======= 11:00:03 (1761318003) [ 6903.686436] Lustre: DEBUG MARKER: == recovery-small test 148: data corruption through resend ========================================================== 11:03:10 (1761318190) [ 6928.863212] Lustre: 2263:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1761318196/real 1761318196] req@00000000d79ce829 x1846868839945472/t0(0) o4->lustre-OST0000-osc-ffff8babe0529000@192.168.203.124@tcp:6/4 lens 4584/448 e 0 to 1 dl 1761318216 ref 2 fl Rpc:XQr/0/ffffffff rc 0/-1 job:'dd.0' [ 6928.878372] Lustre: 2263:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 6 previous similar messages [ 6928.882974] Lustre: lustre-OST0000-osc-ffff8babe0529000: Connection to lustre-OST0000 (at 192.168.203.124@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 6928.888800] Lustre: Skipped 6 previous similar messages [ 6939.712702] Lustre: DEBUG MARKER: == recovery-small test 149: skip orphan removal at umount ========================================================== 11:03:46 (1761318226) [ 6959.590208] LustreError: 166-1: MGC192.168.203.124@tcp: Connection to MGS (at 192.168.203.124@tcp) was lost; in progress operations using this service will fail [ 6959.595925] LustreError: Skipped 5 previous similar messages [ 6959.605626] Lustre: Evicted from MGS (at 192.168.203.124@tcp) after server handle changed from 0x38552adf45e14e8 to 0x38552adf4639a63 [ 6959.615557] Lustre: Skipped 5 previous similar messages [ 6959.618364] Lustre: MGC192.168.203.124@tcp: Connection restored to 192.168.203.124@tcp (at 192.168.203.124@tcp) [ 6959.622468] Lustre: Skipped 11 previous similar messages [ 6969.856212] LustreError: lustre-MDT0001-mdc-ffff8babe0529000: This client was evicted by lustre-MDT0001; in progress operations using this service will fail. [ 6969.880752] LustreError: lustre-MDT0000-mdc-ffff8babe0529000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 6982.084610] Lustre: DEBUG MARKER: == recovery-small test 152: QoS object allocation could be awakened in case of OST failover ========================================================== 11:04:29 (1761318269) [ 7013.248906] Lustre: DEBUG MARKER: == recovery-small test complete, duration 6751 sec ======= 11:05:00 (1761318300) [ 7065.507736] Lustre: DEBUG MARKER: oleg324-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 7066.885559] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7069.913560] Lustre: Unmounted lustre-client [ 7119.387091] Key type lgssc unregistered [ 7119.581973] LNet: 111343:0:(lib-ptl.c:992:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 7120.609198] LNet: Removed LNI 192.168.203.24@tcp [ 7121.104892] Key type .llcrypt unregistered [ 7121.110487] Key type ._llcrypt unregistered