[ 0.000000] Linux version 4.18.0rh8.10-debug (green@maintenance) (gcc version 8.5.0 20210514 (Red Hat 8.5.0-26) (GCC)) #2 SMP Mon Jul 14 01:24:22 EDT 2025 [ 0.000000] Command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers' [ 0.000000] x86/fpu: xstate_offset[2]: 576, xstate_sizes[2]: 256 [ 0.000000] x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'standard' format. [ 0.000000] signal: max sigframe size: 1776 [ 0.000000] BIOS-provided physical RAM map: [ 0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable [ 0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000000100000-0x00000000bffd9fff] usable [ 0.000000] BIOS-e820: [mem 0x00000000bffda000-0x00000000bfffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000100000000-0x0000000146dfffff] usable [ 0.000000] NX (Execute Disable) protection: active [ 0.000000] SMBIOS 2.8 present. [ 0.000000] DMI: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.17.0-8.fc42 06/10/2025 [ 0.000000] Hypervisor detected: KVM [ 0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00 [ 0.000000] kvm-clock: using sched offset of 440790337 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2399.998 MHz processor [ 0.000000] last_pfn = 0x146e00 max_arch_pfn = 0x400000000 [ 0.000000] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT [ 0.000000] last_pfn = 0xbffda max_arch_pfn = 0x400000000 [ 0.000000] found SMP MP-table at [mem 0x000f54d0-0x000f54df] [ 0.000000] RAMDISK: [mem 0xbcc64000-0xbffcffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F52F0 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE2421 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE22BD 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 00227D (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE2331 000090 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE23C1 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE23F9 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe22bd-0xbffe2330] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe22bc] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe2331-0xbffe23c0] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe23c1-0xbffe23f8] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe23f9-0xbffe2420] [ 0.000000] No NUMA configuration found [ 0.000000] Faking a node at [mem 0x0000000000000000-0x0000000146dfffff] [ 0.000000] NODE_DATA(0) allocated [mem 0x1465a3000-0x1465cdfff] [ 0.000000] Reserving 256MB of memory at 2752MB for crashkernel (System RAM: 4205MB) [ 0.000000] Zone ranges: [ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.000000] DMA32 [mem 0x0000000001000000-0x00000000ffffffff] [ 0.000000] Normal [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Device empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff] [ 0.000000] node 0: [mem 0x0000000000100000-0x00000000bffd9fff] [ 0.000000] node 0: [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Zeroed struct page in unavailable ranges: 4744 pages [ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x0000000146dfffff] [ 0.000000] ACPI: PM-Timer IO Port: 0x608 [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) [ 0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) [ 0.000000] Using ACPI (MADT) for SMP configuration information [ 0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000] TSC deadline timer available [ 0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs [ 0.000000] kvm-guest: KVM setup pv remote TLB flush [ 0.000000] kvm-guest: setup PV sched yield [ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff] [ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff] [ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff] [ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff] [ 0.000000] PM: Registered nosave memory: [mem 0xbffda000-0xbfffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xc0000000-0xfeffbfff] [ 0.000000] PM: Registered nosave memory: [mem 0xfeffc000-0xfeffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xff000000-0xfffbffff] [ 0.000000] PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff] [ 0.000000] [mem 0xc0000000-0xfeffbfff] available for PCI devices [ 0.000000] Booting paravirtualized kernel on KVM [ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns [ 0.000000] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1 [ 0.000000] percpu: Embedded 63 pages/cpu s221184 r8192 d28672 u524288 [ 0.000000] kvm-guest: PV spinlocks enabled [ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1059618 [ 0.000000] Policy zone: Normal [ 0.000000] Kernel command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] Specific versions of hardware are certified with Red Hat Enterprise Linux 8. Please see the list of hardware certified with Red Hat Enterprise Linux 8 at https://catalog.redhat.com. [ 0.000000] audit: disabled (until reboot) [ 0.000000] software IO TLB: area num 4. [ 0.000000] Memory: 2829700K/4306400K available (18435K kernel code, 11221K rwdata, 7248K rodata, 2908K init, 18040K bss, 524584K 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.001019] APIC: Switch to symmetric I/O mode setup [ 0.003241] x2apic enabled [ 0.004009] Switched APIC routing to physical x2apic. [ 0.005024] kvm-guest: setup PV IPIs [ 0.008307] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.009000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.009037] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.010022] pid_max: default: 32768 minimum: 301 [ 0.011202] LSM: Security Framework initializing [ 0.012089] Yama: becoming mindful. [ 0.013077] SELinux: Initializing. [ 0.014151] *** VALIDATE selinux *** [ 0.023728] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.028740] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.029185] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.031039] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.032170] *** VALIDATE tmpfs *** [ 0.034052] *** VALIDATE proc *** [ 0.035181] *** VALIDATE cgroup *** [ 0.036012] *** VALIDATE cgroup2 *** [ 0.037331] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.038208] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.039011] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.040051] Spectre V2 : User space: Vulnerable [ 0.041010] Speculative Store Bypass: Vulnerable [ 0.045149] debug: unmapping init [mem 0xffffffff89659000-0xffffffff89660fff] [ 0.047320] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.048800] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.049037] ... version: 2 [ 0.050018] ... bit width: 48 [ 0.051022] ... generic registers: 4 [ 0.052019] ... value mask: 0000ffffffffffff [ 0.053020] ... max period: 00007fffffffffff [ 0.054025] ... fixed-purpose events: 3 [ 0.054990] ... event mask: 000000070000000f [ 0.056288] rcu: Hierarchical SRCU implementation. [ 0.058626] smp: Bringing up secondary CPUs ... [ 0.059733] x86: Booting SMP configuration: [ 0.060048] .... node #0, CPUs: #1 #2 #3 [ 0.064725] smp: Brought up 1 node, 4 CPUs [ 0.066025] smpboot: Max logical packages: 1 [ 0.067029] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.261047] node 0 deferred pages initialised in 191ms [ 0.265170] devtmpfs: initialized [ 0.266053] x86/mm: Memory block size: 128MB [ 0.269889] gcov: version magic: 0x41383552 [ 0.273266] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.274106] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.275418] pinctrl core: initialized pinctrl subsystem [ 0.277238] [ 0.277804] ************************************************************* [ 0.280029] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.282018] ** ** [ 0.285025] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.287028] ** ** [ 0.289018] ** This means that this kernel is built to expose internal ** [ 0.291018] ** IOMMU data structures, which may compromise security on ** [ 0.294020] ** your system. ** [ 0.296016] ** ** [ 0.298018] ** If you see this message and you are not debugging the ** [ 0.301019] ** kernel, report this immediately to your vendor! ** [ 0.303017] ** ** [ 0.305022] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.308019] ************************************************************* [ 0.310693] NET: Registered protocol family 16 [ 0.312478] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.315075] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.317071] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.321038] cpuidle: using governor menu [ 0.322728] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.326582] PCI: Using configuration type 1 for base access [ 0.328150] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.337151] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.340033] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.343108] cryptd: max_cpu_qlen set to 1000 [ 0.346364] ACPI: Added _OSI(Module Device) [ 0.348027] ACPI: Added _OSI(Processor Device) [ 0.350016] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.351019] ACPI: Added _OSI(Processor Aggregator Device) [ 0.356042] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.362478] ACPI: Interpreter enabled [ 0.364073] ACPI: PM: (supports S0 S3 S4 S5) [ 0.365015] ACPI: Using IOAPIC for interrupt routing [ 0.366147] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.370411] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.379000] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.382066] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.385028] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.388116] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.394780] acpiphp: Slot [2] registered [ 0.396216] acpiphp: Slot [5] registered [ 0.398187] acpiphp: Slot [6] registered [ 0.399180] acpiphp: Slot [3] registered [ 0.401119] acpiphp: Slot [4] registered [ 0.402151] acpiphp: Slot [7] registered [ 0.404116] acpiphp: Slot [8] registered [ 0.406164] acpiphp: Slot [9] registered [ 0.407160] acpiphp: Slot [10] registered [ 0.410157] acpiphp: Slot [11] registered [ 0.412119] acpiphp: Slot [12] registered [ 0.413144] acpiphp: Slot [13] registered [ 0.415148] acpiphp: Slot [14] registered [ 0.417145] acpiphp: Slot [15] registered [ 0.418146] acpiphp: Slot [16] registered [ 0.420143] acpiphp: Slot [17] registered [ 0.421115] acpiphp: Slot [18] registered [ 0.423173] acpiphp: Slot [19] registered [ 0.424139] acpiphp: Slot [20] registered [ 0.426136] acpiphp: Slot [21] registered [ 0.427084] acpiphp: Slot [22] registered [ 0.429189] acpiphp: Slot [23] registered [ 0.431167] acpiphp: Slot [24] registered [ 0.432136] acpiphp: Slot [25] registered [ 0.434134] acpiphp: Slot [26] registered [ 0.436130] acpiphp: Slot [27] registered [ 0.437128] acpiphp: Slot [28] registered [ 0.439157] acpiphp: Slot [29] registered [ 0.440130] acpiphp: Slot [30] registered [ 0.442110] acpiphp: Slot [31] registered [ 0.443060] PCI host bridge to bus 0000:00 [ 0.445038] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.447048] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.452041] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.455035] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.458038] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.461040] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.463261] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.467122] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.470650] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.477952] pci 0000:00:01.1: reg 0x20: [io 0xc120-0xc12f] [ 0.482066] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.485029] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.488024] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.490022] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.492678] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.495833] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.498055] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.501990] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.505605] pci 0000:00:02.0: reg 0x10: [io 0xc100-0xc11f] [ 0.514798] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.518014] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.525087] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.535036] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.542022] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.562024] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.575104] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.581021] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.586024] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.599023] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.611686] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.614435] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.617401] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.619346] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.621229] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.626251] iommu: Default domain type: Passthrough [ 0.629298] SCSI subsystem initialized [ 0.631196] ACPI: bus type USB registered [ 0.632178] usbcore: registered new interface driver usbfs [ 0.635160] usbcore: registered new interface driver hub [ 0.637267] usbcore: registered new device driver usb [ 0.639323] pps_core: LinuxPPS API ver. 1 registered [ 0.641015] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.644100] PTP clock support registered [ 0.647113] EDAC MC: Ver: 3.0.0 [ 0.649220] PCI: Using ACPI for IRQ routing [ 0.651926] NetLabel: Initializing [ 0.653017] NetLabel: domain hash size = 128 [ 0.655018] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.657110] NetLabel: unlabeled traffic allowed by default [ 0.660202] vgaarb: loaded [ 0.662404] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.664021] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.673271] clocksource: Switched to clocksource kvm-clock [ 0.781741] VFS: Disk quotas dquot_6.6.0 [ 0.783395] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.785927] *** VALIDATE ramfs *** [ 0.787250] *** VALIDATE hugetlbfs *** [ 0.789688] pnp: PnP ACPI init [ 0.792277] pnp: PnP ACPI: found 6 devices [ 0.810897] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.813633] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.815089] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.816775] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.818310] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.819991] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.821861] NET: Registered protocol family 2 [ 0.823815] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.827512] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.830869] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.836191] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.840208] TCP: Hash tables configured (established 65536 bind 65536) [ 0.843694] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.847309] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.850545] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.854129] NET: Registered protocol family 1 [ 0.857322] RPC: Registered named UNIX socket transport module. [ 0.859606] RPC: Registered udp transport module. [ 0.861519] RPC: Registered tcp transport module. [ 0.863565] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.866724] NET: Registered protocol family 44 [ 0.867966] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.869529] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.871717] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.873943] PCI: CLS 0 bytes, default 64 [ 0.875741] Unpacking initramfs... [ 3.709126] debug: unmapping init [mem 0xffff8c6bbcc64000-0xffff8c6bbffcffff] [ 3.713576] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 3.715862] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 3.718991] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 6.332634] Initialise system trusted keyrings [ 6.334514] Key type blacklist registered [ 6.342620] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 6.370685] zbud: loaded [ 6.375348] *** VALIDATE nfs *** [ 6.378664] *** VALIDATE nfs4 *** [ 6.382429] pstore: using deflate compression [ 6.390806] Platform Keyring initialized [ 6.911541] NET: Registered protocol family 38 [ 6.917921] Key type asymmetric registered [ 6.920814] Asymmetric key parser 'x509' registered [ 6.926869] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 6.936843] io scheduler mq-deadline registered [ 6.941539] io scheduler kyber registered [ 6.949239] io scheduler bfq registered [ 6.955050] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 6.962858] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 6.966926] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 6.971676] ACPI: Power Button [PWRF] [ 7.003700] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 7.030754] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 7.055241] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 7.110728] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 7.173936] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 7.190702] Non-volatile memory driver v1.3 [ 7.194634] Linux agpgart interface v0.103 [ 7.264612] virtio_blk virtio1: [vda] 68040 512-byte logical blocks (34.8 MB/33.2 MiB) [ 7.268699] vda: detected capacity change from 0 to 34836480 [ 7.320332] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 7.330680] vdb: detected capacity change from 0 to 1073741824 [ 7.352950] libphy: Fixed MDIO Bus: probed [ 7.361712] usbcore: registered new interface driver usbserial_generic [ 7.364808] usbserial: USB Serial support registered for generic [ 7.368294] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 7.373940] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 7.376315] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 7.380876] mousedev: PS/2 mouse device common for all mice [ 7.391707] rtc_cmos 00:05: RTC can wake from S4 [ 7.399086] rtc_cmos 00:05: registered as rtc0 [ 7.401000] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 7.417960] intel_pstate: CPU model not supported [ 7.434209] hid: raw HID events driver (C) Jiri Kosina [ 7.448853] usbcore: registered new interface driver usbhid [ 7.450745] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 7.457706] usbhid: USB HID core driver [ 7.457934] drop_monitor: Initializing network drop monitor service [ 7.458118] Initializing XFRM netlink socket [ 7.467978] NET: Registered protocol family 10 [ 7.488829] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 7.501698] Segment Routing with IPv6 [ 7.525538] NET: Registered protocol family 17 [ 7.528741] mpls_gso: MPLS GSO support [ 7.534851] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 7.545750] RAS: Correctable Errors collector initialized. [ 7.551482] AVX version of gcm_enc/dec engaged. [ 7.562740] AES CTR mode by8 optimization enabled [ 7.899663] sched_clock: Marking stable (7899633918, 0)->(8812422126, -912788208) [ 7.914094] registered taskstats version 1 [ 7.926849] Loading compiled-in X.509 certificates [ 7.936310] zswap: loaded using pool lzo/zbud [ 8.090794] Key type big_key registered [ 8.166269] Key type encrypted registered [ 8.173102] ima: No TPM chip found, activating TPM-bypass! [ 8.196088] ima: Allocated hash algorithm: sha1 [ 8.197577] ima: No architecture policies found [ 8.209904] evm: Initialising EVM extended attributes: [ 8.217598] evm: security.selinux [ 8.223260] evm: security.ima [ 8.231892] evm: security.capability [ 8.238288] evm: HMAC attrs: 0x1 [ 8.262654] rtc_cmos 00:05: setting system clock to 2026-04-14 18:24:41 UTC (1776191081) [ 8.287458] debug: unmapping init [mem 0xffffffff8a603000-0xffffffff8a7fffff] [ 8.302699] debug: unmapping init [mem 0xffffffff89382000-0xffffffff89658fff] [ 8.330965] Write protecting the kernel read-only data: 28672k [ 8.351259] debug: unmapping init [mem 0xffffffff87a03000-0xffffffff87bfffff] [ 8.363303] debug: unmapping init [mem 0xffffffff88314000-0xffffffff883fffff] [ 8.627706] 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) [ 8.659345] systemd[1]: Detected virtualization kvm. [ 8.671316] systemd[1]: Detected architecture x86-64. [ 8.677792] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 8.842216] systemd[1]: No hostname configured. [ 8.853059] systemd[1]: Set hostname to . [ 8.865296] random: systemd: uninitialized urandom read (16 bytes read) [ 8.892732] systemd[1]: Initializing machine ID from random generator. [ 9.142983] random: ln: uninitialized urandom read (6 bytes read) [ 9.633050] random: systemd: uninitialized urandom read (16 bytes read) [ 9.654652] systemd[1]: Listening on udev Control Socket. [ OK ] Listening on udev Control Socket. [ 9.686731] systemd[1]: Reached target Local File Systems. [ OK ] Reached target Local File Systems. [ 9.703690] systemd[1]: Listening on Journal Socket (/dev/log). [ OK ] Listening on Journal Socket (/dev/log). [ OK ] Listening on udev Kernel Socket. [ OK ] Reached target Slices. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Paths. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Swap. [ OK ] Reached target Initrd Root Device. [ OK ] Reached target Timers. [ OK ] Listening on Journal Socket. Starting Create Volatile Files and Directories... [ OK ] Started Memstrack Anylazing Service. Starting Create list of required st…ce nodes for the current kernel... Starting Setup Virtual Console... [ OK ] Reached target Sockets. Starting Apply Kernel Variables... Starting Journal Service... [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Setup Virtual Console. [ OK ] Started Apply Kernel Variables. Starting dracut cmdline hook... Starting Create Static Device Nodes in /dev... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started Journal Service. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 12.348599] device-mapper: uevent: version 1.0.3 [ 12.353140] device-mapper: ioctl: 4.46.0-ioctl (2022-02-22) initialised: dm-devel@redhat.com [ OK ] Started dracut pre-udev hook. Starting udev Kernel Device Manager... [ OK ] Started udev Kernel Device Manager. Starting dracut pre-trigger hook... [ OK ] Started dracut pre-trigger hook. Starting udev Coldplug all Devices... Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting dracut initqueue hook... [ 15.054190] virtio_net virtio0 ens2: renamed from eth0 [ 15.282936] scsi host0: ata_piix [ 15.301247] scsi host1: ata_piix [ 15.303371] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc120 irq 14 [ 15.305934] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc128 irq 15 [ 19.776150] random: crng init done [ 19.779094] random: 7 urandom warning(s) missed due to ratelimiting [ 22.003261] dracut-initqueue[587]: RTNETLINK answers: File exists Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Mounting /sysroot... [ 24.169887] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped target Timers. [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Slices. [ OK ] Stopped target Sockets. [ OK ] Stopped target Paths. [ OK ] Stopped target System Initialization. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. [ OK ] Stopped target Swap. Stopping udev Kernel Device Manager... [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Closed udev Control Socket. [ OK ] Closed udev Kernel Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 27.669380] printk: systemd: 26 output lines suppressed due to ratelimiting [ 29.206567] SELinux: Disabled at runtime. [ 29.375572] 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) [ 29.387864] systemd[1]: Detected virtualization kvm. [ 29.390498] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 31.830555] systemd[1]: initrd-switch-root.service: Succeeded. [ 31.836544] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 31.864889] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 31.885581] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 31.905447] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 31.933067] systemd[1]: Starting Journal Service... Starting Journal Service... [ 31.964667] systemd[1]: Listening on RPCbind Server Activation Socket. [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Listening on udev Control Socket. [ OK ] Created slice system-getty.slice. Activating swap /dev/disk/by-label/SWAP... [ OK ] Listening on Process Core Dump Socket. [ OK ] Created slice system-serial\x2dgetty.slice. [ 32.121428] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS Mounting Kernel Debug File System... Starting Apply Kernel Variables... Starting Remount Root and Kernel File Systems... [ OK ] Started Forward Password Requests to Wall Directory Watch. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Reached target rpc_pipefs.target. [ OK ] Created slice User and Session Slice. [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd Root File System. [ OK ] Stopped target Initrd File Systems. [ OK ] Reached target Slices. Mounting Huge Pages File System... [ OK ] Listening on udev Kernel Socket. Starting udev Coldplug all Devices... [ OK ] Reached target RPC Port Mapper. [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. Mounting POSIX Message Queue File System... [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Mounted Kernel Debug File System. [ OK ] Started Apply Kernel Variables. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Journal Service. [ OK ] Mounted Huge Pages File System. [ OK ] Mounted POSIX Message Queue File System. Starting Configure read-only root support... Starting Create Static Device Nodes in /dev... Starting Flush Journal to Persistent Storage... [ OK ] Reached target Swap. [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Reached target Local File Systems (Pre). Mounting /home/green/git/lustre-release... Mounting /mnt... Starting udev Kernel Device Manager... [ OK ] Started udev Coldplug all Devices. [ OK ] Mounted /mnt. [ 34.077568] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 35.463946] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 35.504821] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 35.978280] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 36.138646] EDAC sbridge: Ver: 1.1.2 [* ] A start job is running for Configur…-only root support (8s / no limit) [** ] A start job is running for Configur…-only root support (8s / no limit)[ 40.607348] Key type dns_resolver registered [*** ] A start job is running for Configur…-only root support (9s / no limit) [ *** ] A start job is running for Configur…-only root support (9s / no limit)[ 41.975788] NFS: Registering the id_resolver key type [ 41.991724] Key type id_resolver registered [ 42.003921] Key type id_legacy registered [ *** ] A start job is running for Configur…only root support (10s / no limit) [ OK ] Started Configure read-only root support. Starting Load/Save Random Seed... [ OK ] Reached target Local File Systems. Starting Rebuild Dynamic Linker Cache... Starting Create Volatile Files and Directories... Starting Mark the need to relabel after reboot... [ OK ] Started Load/Save Random Seed. [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Create Volatile Files and Directories. Starting RPC Bind... Starting Update UTMP about System Boot/Shutdown... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ 45.050084] hrtimer: interrupt took 7997750 ns [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Started dnf makecache --timer. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Reached target Basic System. [ OK ] Started irqbalance daemon. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting Restore /run/initramfs on shutdown... [ OK ] Started D-Bus System Message Bus. Starting Login Service... Starting Network Manager... [ OK ] Reached target sshd-keygen.target. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Reached target Timers. [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Login Service. [ OK ] Started Network Manager. [ OK ] Reached target Network. Starting OpenSSH server daemon... Starting Dynamic System Tuning Daemon... Starting GSSAPI Proxy Daemon... Starting Network Manager Wait Online... [ OK ] Started OpenSSH server daemon. [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... Starting Hostname Service... [ OK ] Started Permit User Sessions. [ OK ] Started 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 Crash recovery kernel arming... Starting System Logging Service... Starting Notify NFS peers of a restart... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg218-client login: [ 105.060711] libcfs: loading out-of-tree module taints kernel. [ 105.373598] alg: No test for adler32 (adler32-zlib) [ 106.153527] Key type ._llcrypt registered [ 106.156443] Key type .llcrypt registered [ 106.595104] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [ 107.339508] Lustre: Lustre: Build Version: 2.15.8_10_g54e838e [ 107.946901] LNet: Added LNI 192.168.202.18@tcp [8/256/0/180] [ 107.949989] LNet: Accept secure, port 988 [ 109.647091] Key type lgssc registered [ 111.754900] Lustre: Echo OBD driver; http://www.lustre.org/ [ 246.321164] Lustre: Mounted lustre-client [ 251.783607] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 269.207822] Lustre: DEBUG MARKER: oleg218-client.virtnet: executing check_logdir /tmp/testlogs/ [ 271.839250] Lustre: lustre-OST0000-osc-ffff8c6c194cb800: disconnect after 23s idle [ 274.084992] Lustre: DEBUG MARKER: oleg218-client.virtnet: executing yml_node [ 278.681861] Lustre: DEBUG MARKER: Client: 2.15.8.10 [ 281.374805] Lustre: DEBUG MARKER: MDS: 2.15.8.10 [ 283.903386] Lustre: DEBUG MARKER: OSS: 2.15.8.10 [ 285.631568] Lustre: DEBUG MARKER: -----============= acceptance-small: recovery-small ============----- Tue Apr 14 14:29:17 EDT 2026 [ 295.585252] Lustre: DEBUG MARKER: excepting tests: 136 [ 301.493584] Lustre: DEBUG MARKER: oleg218-client.virtnet: executing check_config_client /mnt/lustre [ 319.282595] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 327.942090] Lustre: DEBUG MARKER: == recovery-small test 1: create, chmod, stat: drop req, drop rep ========================================================== 14:30:00 (1776191400) [ 341.471151] Lustre: 8961:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776191402/real 1776191402] req@000000008316bec1 x1862471443814144/t0(0) o700->lustre-MDT0000-mdc-ffff8c6c194cb800@192.168.202.118@tcp:30/10 lens 264/248 e 0 to 1 dl 1776191414 ref 2 fl Rpc:XQr/0/ffffffff rc 0/-1 job:'mcreate.0' [ 341.491247] Lustre: lustre-MDT0000-mdc-ffff8c6c194cb800: Connection to lustre-MDT0000 (at 192.168.202.118@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 341.535614] Lustre: lustre-MDT0000-mdc-ffff8c6c194cb800: Connection restored to (at 192.168.202.118@tcp) [ 351.711176] Lustre: 8981:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776191417/real 1776191417] req@000000000e704dbf x1862471443814912/t0(0) o36->lustre-MDT0000-mdc-ffff8c6c194cb800@192.168.202.118@tcp:12/10 lens 520/448 e 0 to 1 dl 1776191424 ref 2 fl Rpc:XQr/0/ffffffff rc 0/-1 job:'mcreate.0' [ 351.748710] Lustre: lustre-MDT0000-mdc-ffff8c6c194cb800: Connection to lustre-MDT0000 (at 192.168.202.118@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 351.821315] Lustre: lustre-MDT0000-mdc-ffff8c6c194cb800: Connection restored to (at 192.168.202.118@tcp) [ 361.951239] Lustre: 9004:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776191428/real 1776191428] req@00000000088434b8 x1862471443815360/t0(0) o101->lustre-MDT0000-mdc-ffff8c6c194cb800@192.168.202.118@tcp:12/10 lens 576/1152 e 0 to 1 dl 1776191435 ref 2 fl Rpc:XQr/0/ffffffff rc 0/-1 job:'tchmod.0' [ 361.989294] Lustre: lustre-MDT0000-mdc-ffff8c6c194cb800: Connection to lustre-MDT0000 (at 192.168.202.118@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 362.026301] Lustre: lustre-MDT0000-mdc-ffff8c6c194cb800: Connection restored to (at 192.168.202.118@tcp) [ 371.167195] Lustre: 9024:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776191437/real 1776191437] req@00000000db2ba3ef x1862471443816256/t0(0) o36->lustre-MDT0000-mdc-ffff8c6c194cb800@192.168.202.118@tcp:12/10 lens 488/512 e 0 to 1 dl 1776191444 ref 2 fl Rpc:XQr/0/ffffffff rc 0/-1 job:'tchmod.0' [ 371.184265] Lustre: lustre-MDT0000-mdc-ffff8c6c194cb800: Connection to lustre-MDT0000 (at 192.168.202.118@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 371.205255] Lustre: lustre-MDT0000-mdc-ffff8c6c194cb800: Connection restored to (at 192.168.202.118@tcp) [ 380.383419] Lustre: 9048:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776191446/real 1776191446] req@00000000ec4002a9 x1862471443816640/t0(0) o34->lustre-MDT0000-mdc-ffff8c6c194cb800@192.168.202.118@tcp:12/10 lens 472/728 e 0 to 1 dl 1776191453 ref 2 fl Rpc:XQr/0/ffffffff rc 0/-1 job:'statone.0' [ 380.416575] Lustre: lustre-MDT0000-mdc-ffff8c6c194cb800: Connection to lustre-MDT0000 (at 192.168.202.118@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 380.461773] Lustre: lustre-MDT0000-mdc-ffff8c6c194cb800: Connection restored to (at 192.168.202.118@tcp) [ 389.087195] Lustre: 9066:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776191455/real 1776191455] req@00000000f2b3989a x1862471443817024/t0(0) o34->lustre-MDT0000-mdc-ffff8c6c194cb800@192.168.202.118@tcp:12/10 lens 472/728 e 0 to 1 dl 1776191462 ref 2 fl Rpc:XQr/0/ffffffff rc 0/-1 job:'statone.0' [ 389.116286] Lustre: lustre-MDT0000-mdc-ffff8c6c194cb800: Connection to lustre-MDT0000 (at 192.168.202.118@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 389.173564] Lustre: lustre-MDT0000-mdc-ffff8c6c194cb800: Connection restored to (at 192.168.202.118@tcp) [ 397.327148] Lustre: DEBUG MARKER: == recovery-small test 4: open: drop req, drop rep ======= 14:31:09 (1776191469) [ 414.693838] Lustre: 9684:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776191480/real 1776191480] req@000000001583ce72 x1862471443819136/t0(0) o35->lustre-MDT0000-mdc-ffff8c6c194cb800@192.168.202.118@tcp:23/10 lens 392/624 e 0 to 1 dl 1776191487 ref 2 fl Rpc:XQr/0/ffffffff rc 0/-1 job:'cat.0' [ 414.731943] Lustre: 9684:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 414.739428] Lustre: lustre-MDT0000-mdc-ffff8c6c194cb800: Connection to lustre-MDT0000 (at 192.168.202.118@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 414.747096] Lustre: Skipped 1 previous similar message [ 414.766159] Lustre: lustre-MDT0000-mdc-ffff8c6c194cb800: Connection restored to (at 192.168.202.118@tcp) [ 414.770503] Lustre: Skipped 1 previous similar message [ 422.862899] Lustre: DEBUG MARKER: == recovery-small test 5: rename: drop req, drop rep ===== 14:31:34 (1776191494) [ 447.246573] Lustre: DEBUG MARKER: == recovery-small test 6: link, unlink: drop req, drop rep ========================================================== 14:31:58 (1776191518) [ 455.647967] Lustre: 10906:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776191521/real 1776191521] req@000000002bbf2e47 x1862471443823296/t0(0) o36->lustre-MDT0000-mdc-ffff8c6c194cb800@192.168.202.118@tcp:12/10 lens 512/440 e 0 to 1 dl 1776191528 ref 2 fl Rpc:XQr/0/ffffffff rc 0/-1 job:'mlink.0' [ 455.702046] Lustre: 10906:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 455.715990] Lustre: lustre-MDT0000-mdc-ffff8c6c194cb800: Connection to lustre-MDT0000 (at 192.168.202.118@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 455.731899] Lustre: Skipped 2 previous similar messages [ 455.778307] Lustre: lustre-MDT0000-mdc-ffff8c6c194cb800: Connection restored to (at 192.168.202.118@tcp) [ 455.784802] Lustre: Skipped 2 previous similar messages [ 465.375820] Lustre: lustre-OST0001-osc-ffff8c6c194cb800: disconnect after 20s idle [ 465.379203] Lustre: Skipped 1 previous similar message [ 490.876972] Lustre: DEBUG MARKER: == recovery-small test 8: touch: drop rep (bug 1423) ===== 14:32:42 (1776191562) [ 505.677665] Lustre: DEBUG MARKER: == recovery-small test 9: pause bulk on OST (bug 1420) === 14:32:57 (1776191577) [ 522.650353] Lustre: DEBUG MARKER: == recovery-small test 10a: finish request on server after client eviction (bug 1521) ========================================================== 14:33:14 (1776191594) [ 523.200468] Lustre: *** cfs_fail_loc=305, val=0*** [ 534.653992] Lustre: *** cfs_fail_loc=305, val=0*** [ 534.662571] Lustre: Skipped 1 previous similar message [ 539.108515] Lustre: lustre-OST0001-osc-ffff8c6c194cb800: disconnect after 22s idle [ 545.921489] Lustre: *** cfs_fail_loc=305, val=0*** [ 545.925460] Lustre: Skipped 1 previous similar message [ 557.170125] Lustre: *** cfs_fail_loc=305, val=0*** [ 557.173615] Lustre: Skipped 1 previous similar message [ 568.459557] Lustre: *** cfs_fail_loc=305, val=0*** [ 568.464689] Lustre: Skipped 1 previous similar message [ 579.733228] Lustre: *** cfs_fail_loc=305, val=0*** [ 579.741833] Lustre: Skipped 1 previous similar message [ 602.201131] Lustre: *** cfs_fail_loc=305, val=0*** [ 602.203757] Lustre: Skipped 3 previous similar messages [ 625.077760] LustreError: 11-0: lustre-MDT0000-mdc-ffff8c6c194cb800: operation ldlm_enqueue to node 192.168.202.118@tcp failed: rc = -107 [ 625.091306] Lustre: lustre-MDT0000-mdc-ffff8c6c194cb800: Connection to lustre-MDT0000 (at 192.168.202.118@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 625.108471] Lustre: Skipped 4 previous similar messages [ 625.142229] LustreError: lustre-MDT0000-mdc-ffff8c6c194cb800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 625.168068] Lustre: lustre-MDT0000-mdc-ffff8c6c194cb800: Connection restored to (at 192.168.202.118@tcp) [ 625.175713] Lustre: Skipped 4 previous similar messages [ 633.003327] Lustre: DEBUG MARKER: == recovery-small test 10b: re-send BL AST =============== 14:35:04 (1776191704) [ 653.663106] Lustre: DEBUG MARKER: == recovery-small test 10c: re-send BL AST vs reconnect race (LU-5569) ========================================================== 14:35:25 (1776191725) [ 654.238159] Lustre: *** cfs_fail_loc=305, val=0*** [ 654.240997] Lustre: Skipped 4 previous similar messages [ 662.723089] Lustre: DEBUG MARKER: == recovery-small test 10d: test failed blocking ast ===== 14:35:34 (1776191734) [ 667.151153] Lustre: Unmounted lustre-client [ 667.702498] Lustre: Mounted lustre-client [ 669.415826] LustreError: 11-0: lustre-OST0000-osc-ffff8c6c0864f800: operation ldlm_enqueue to node 192.168.202.118@tcp failed: rc = -107 [ 669.430975] LustreError: lustre-OST0000-osc-ffff8c6c0864f800: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 669.440506] Lustre: 2222:0:(llite_lib.c:3595:ll_dirty_page_discard_warn()) lustre: dirty page discard: 192.168.202.118@tcp:/lustre/fid: [0x200000403:0x1:0x0]// may get corrupted (rc -108) [ 672.215062] Lustre: Unmounted lustre-client [ 677.958293] Lustre: DEBUG MARKER: == recovery-small test 10e: re-send BL AST vs reconnect race 2 ========================================================== 14:35:49 (1776191749) [ 679.328235] Lustre: DEBUG MARKER: SKIP: recovery-small test_10e need two clients [ 681.236471] Lustre: DEBUG MARKER: == recovery-small test 11: wake up a thread waiting for completion after eviction (b=2460) ========================================================== 14:35:52 (1776191752) [ 701.626049] Lustre: DEBUG MARKER: == recovery-small test 12: recover from timed out resend in ptlrpcd (b=2494) ========================================================== 14:36:13 (1776191773) [ 701.703853] Lustre: DEBUG MARKER: multiop /mnt/lustre/f12.recovery-small OS_c [ 709.087970] Lustre: 16474:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776191775/real 1776191775] req@0000000040ad41bf x1862471443857600/t0(0) o35->lustre-MDT0000-mdc-ffff8c6c0864f800@192.168.202.118@tcp:23/10 lens 392/624 e 0 to 1 dl 1776191782 ref 2 fl Rpc:XQr/0/ffffffff rc 0/-1 job:'multiop.0' [ 709.124386] Lustre: 16474:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 4 previous similar messages [ 745.187624] Lustre: DEBUG MARKER: == recovery-small test 13: mdc_readpage restart test (bug 1138) ========================================================== 14:36:57 (1776191817) [ 753.119254] Lustre: lustre-MDT0000-mdc-ffff8c6c0864f800: Connection to lustre-MDT0000 (at 192.168.202.118@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 753.136430] Lustre: Skipped 3 previous similar messages [ 758.978106] Lustre: DEBUG MARKER: == recovery-small test 14: mdc_readpage resend test (bug 1138) ========================================================== 14:37:11 (1776191831) [ 766.656357] Lustre: DEBUG MARKER: == recovery-small test 15: failed open (-ENOMEM) ========= 14:37:18 (1776191838) [ 772.669885] Lustre: DEBUG MARKER: == recovery-small test 16: timeout bulk put, don't evict client (2732) ========================================================== 14:37:24 (1776191844) [ 850.701914] Lustre: DEBUG MARKER: == recovery-small test 17a: timeout bulk get, don't evict client (2732) ========================================================== 14:38:41 (1776191921) [ 905.906848] Lustre: DEBUG MARKER: == recovery-small test 17b: timeout bulk get, dont evict client (3582) ========================================================== 14:39:37 (1776191977) [ 907.446631] Lustre: DEBUG MARKER: SKIP: recovery-small test_17b Needs multiple clients [ 909.366129] Lustre: DEBUG MARKER: == recovery-small test 18a: manual ost invalidate clears page cache immediately ========================================================== 14:39:41 (1776191981) [ 910.555392] Lustre: setting import lustre-OST0001_UUID INACTIVE by administrator request [ 910.625361] LustreError: lustre-OST0001-osc-ffff8c6c0864f800: This client was evicted by lustre-OST0001; in progress operations using this service will fail. [ 910.634295] Lustre: lustre-OST0001-osc-ffff8c6c0864f800: Connection restored to (at 192.168.202.118@tcp) [ 910.642248] Lustre: Skipped 4 previous similar messages [ 917.025804] Lustre: DEBUG MARKER: == recovery-small test 18b: eviction and reconnect clears page cache (2766) ========================================================== 14:39:49 (1776191989) [ 921.075319] LustreError: lustre-OST0000-osc-ffff8c6c0864f800: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 947.236052] Lustre: DEBUG MARKER: == recovery-small test 18c: Dropped connect reply after eviction handing (14755) ========================================================== 14:40:19 (1776192019) [ 951.325154] LustreError: 11-0: lustre-OST0000-osc-ffff8c6c0864f800: operation ost_statfs to node 192.168.202.118@tcp failed: rc = -107 [ 957.446274] Lustre: Evicted from lustre-OST0000_UUID (at 192.168.202.118@tcp) after server handle changed from 0x7b87496447d6d832 to 0x7b87496447d6d966 [ 957.456911] LustreError: lustre-OST0000-osc-ffff8c6c0864f800: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 967.687880] Lustre: DEBUG MARKER: == recovery-small test 19a: test expired_lock_main on mds (2867) ========================================================== 14:40:38 (1776192038) [ 968.302896] Lustre: Mounted lustre-client [ 968.304488] Lustre: Skipped 1 previous similar message [ 977.311229] Lustre: 2223:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776192043/real 1776192043] req@000000007a641998 x1862471443885696/t0(0) o103->lustre-MDT0000-mdc-ffff8c6c0864f800@192.168.202.118@tcp:17/18 lens 328/224 e 0 to 1 dl 1776192050 ref 1 fl Rpc:XQr/0/ffffffff rc 0/-1 job:'ldlm_bl_02.0' [ 977.342867] Lustre: 2223:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 1012.192082] Lustre: lustre-MDT0000-mdc-ffff8c6c0864f800: Connection to lustre-MDT0000 (at 192.168.202.118@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1012.216095] Lustre: Skipped 9 previous similar messages [ 1073.646656] LustreError: lustre-MDT0000-mdc-ffff8c6c0864f800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 1073.663917] LustreError: 22680:0:(file.c:246:ll_close_inode_openhandle()) lustre-clilmv-ffff8c6c0864f800: inode [0x200000403:0x1:0x0] mdc close failed: rc = -108 [ 1077.245995] Lustre: Unmounted lustre-client [ 1082.526792] Lustre: DEBUG MARKER: == recovery-small test 19b: test expired_lock_main on ost (2867) ========================================================== 14:42:34 (1776192154) [ 1083.147734] Lustre: Mounted lustre-client [ 1167.850742] Lustre: lustre-OST0000-osc-ffff8c6c0864f800: Connection restored to (at 192.168.202.118@tcp) [ 1167.857874] Lustre: Skipped 26 previous similar messages [ 1187.315064] LustreError: lustre-OST0000-osc-ffff8c6c0864f800: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 1188.439439] Lustre: Unmounted lustre-client [ 1196.748070] Lustre: DEBUG MARKER: == recovery-small test 19c: check reconnect and lock resend do not trigger expired_lock_main ========================================================== 14:44:28 (1776192268) [ 1197.252408] Lustre: Mounted lustre-client [ 1202.228656] Lustre: Unmounted lustre-client [ 1214.451437] Lustre: DEBUG MARKER: == recovery-small test 20a: ldlm_handle_enqueue error (should return error) ========================================================== 14:44:46 (1776192286) [ 1216.167407] LustreError: 11-0: lustre-OST0000-osc-ffff8c6c0864f800: operation ldlm_enqueue to node 192.168.202.118@tcp failed: rc = -12 [ 1223.045671] Lustre: DEBUG MARKER: == recovery-small test 20b: ldlm_handle_enqueue error (should return error) ========================================================== 14:44:54 (1776192294) [ 1224.565853] LustreError: 11-0: lustre-OST0000-osc-ffff8c6c0864f800: operation ldlm_enqueue to node 192.168.202.118@tcp failed: rc = -12 [ 1231.094972] Lustre: DEBUG MARKER: == recovery-small test 21a: drop close request while close and open are both in flight ========================================================== 14:45:03 (1776192303) [ 1244.128664] Lustre: 25952:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776192309/real 1776192309] req@000000009fd995a1 x1862471443921664/t0(0) o35->lustre-MDT0000-mdc-ffff8c6c0864f800@192.168.202.118@tcp:23/10 lens 392/624 e 0 to 1 dl 1776192317 ref 2 fl Rpc:XQr/0/ffffffff rc 0/-1 job:'multiop.0' [ 1244.165800] Lustre: 25952:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 41 previous similar messages [ 1250.691979] Lustre: DEBUG MARKER: == recovery-small test 21b: drop open request while close and open are both in flight ========================================================== 14:45:22 (1776192322) [ 1395.963922] Lustre: DEBUG MARKER: == recovery-small test 21c: drop both request while close and open are both in flight ========================================================== 14:47:47 (1776192467) [ 1415.664557] Lustre: DEBUG MARKER: == recovery-small test 21d: drop close reply while close and open are both in flight ========================================================== 14:48:07 (1776192487) [ 1432.176672] Lustre: DEBUG MARKER: == recovery-small test 21e: drop open reply while close and open are both in flight ========================================================== 14:48:24 (1776192504) [ 1569.759866] Lustre: lustre-MDT0000-mdc-ffff8c6c0864f800: Connection to lustre-MDT0000 (at 192.168.202.118@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1569.787121] Lustre: Skipped 28 previous similar messages [ 1571.384672] Lustre: DEBUG MARKER: == recovery-small test 21f: drop both reply while close and open are both in flight ========================================================== 14:50:43 (1776192643) [ 1589.301937] Lustre: DEBUG MARKER: == recovery-small test 21g: drop open reply and close request while close and open are both in flight ========================================================== 14:51:01 (1776192661) [ 1607.538675] Lustre: DEBUG MARKER: == recovery-small test 21h: drop open request and close reply while close and open are both in flight ========================================================== 14:51:18 (1776192678) [ 1626.092777] Lustre: DEBUG MARKER: == recovery-small test 22: drop close request and do mknod ========================================================== 14:51:37 (1776192697) [ 1640.005045] Lustre: DEBUG MARKER: == recovery-small test 23: client hang when close a file after mds crash ========================================================== 14:51:51 (1776192711) [ 1659.812515] LustreError: 166-1: MGC192.168.202.118@tcp: Connection to MGS (at 192.168.202.118@tcp) was lost; in progress operations using this service will fail [ 1677.224479] Lustre: Evicted from MGS (at 192.168.202.118@tcp) after server handle changed from 0x7b87496447d6cfe9 to 0x7b87496447d6f10d [ 1686.518433] Lustre: lustre-MDT0000-mdc-ffff8c6c0864f800: Connection restored to 192.168.202.118@tcp (at 192.168.202.118@tcp) [ 1686.523231] Lustre: Skipped 13 previous similar messages [ 1691.945286] Lustre: DEBUG MARKER: oleg218-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1693.579862] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1701.061770] Lustre: DEBUG MARKER: == recovery-small test 24a: fsync error (should return error) ========================================================== 14:52:52 (1776192772) [ 1702.977599] LustreError: 11-0: lustre-OST0000-osc-ffff8c6c0864f800: operation ost_write to node 192.168.202.118@tcp failed: rc = -107 [ 1702.997368] LustreError: lustre-OST0000-osc-ffff8c6c0864f800: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 1703.016634] Lustre: 2224:0:(llite_lib.c:3595:ll_dirty_page_discard_warn()) lustre: dirty page discard: 192.168.202.118@tcp:/lustre/fid: [0x200000404:0x30:0x0]// may get corrupted (rc -5) [ 1709.199351] Lustre: DEBUG MARKER: == recovery-small test 24b: test dirty page discard due to client eviction ========================================================== 14:53:01 (1776192781) [ 1710.771936] LustreError: lustre-OST0000-osc-ffff8c6c0864f800: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 1710.804397] Lustre: 2221:0:(llite_lib.c:3595:ll_dirty_page_discard_warn()) lustre: dirty page discard: 192.168.202.118@tcp:/lustre/fid: [0x200000404:0x35:0x0]// may get corrupted (rc -108) [ 1719.862202] Lustre: DEBUG MARKER: == recovery-small test 26a: evict dead exports =========== 14:53:11 (1776192791) [ 1722.701378] Lustre: DEBUG MARKER: SKIP: recovery-small test_26a msg and ost1 are at the same node [ 1725.474367] Lustre: DEBUG MARKER: == recovery-small test 26b: evict dead exports =========== 14:53:16 (1776192796) [ 1728.613602] Lustre: DEBUG MARKER: SKIP: recovery-small test_26b msg and ost1 are at the same node [ 1730.763790] Lustre: DEBUG MARKER: == recovery-small test 27: fail LOV while using OSC's ==== 14:53:22 (1776192802) [ 1734.857496] LustreError: 11-0: lustre-MDT0000-mdc-ffff8c6c0864f800: operation ldlm_enqueue to node 192.168.202.118@tcp failed: rc = -19 [ 1734.871940] LustreError: Skipped 1 previous similar message [ 1743.839500] LustreError: 166-1: MGC192.168.202.118@tcp: Connection to MGS (at 192.168.202.118@tcp) was lost; in progress operations using this service will fail [ 1761.260213] Lustre: Evicted from MGS (at 192.168.202.118@tcp) after server handle changed from 0x7b87496447d6f10d to 0x7b87496447d70805 [ 1868.533236] LustreError: 11-0: lustre-MDT0000-mdc-ffff8c6c0864f800: operation mds_reint to node 192.168.202.118@tcp failed: rc = -19 [ 1879.007683] Lustre: 2223:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776192945/real 1776192945] req@00000000527119a9 x1862471445102528/t0(0) o400->MGC192.168.202.118@tcp@192.168.202.118@tcp:26/25 lens 224/224 e 0 to 1 dl 1776192952 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:3.0' [ 1879.036496] Lustre: 2223:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 11 previous similar messages [ 1879.050246] LustreError: 166-1: MGC192.168.202.118@tcp: Connection to MGS (at 192.168.202.118@tcp) was lost; in progress operations using this service will fail [ 1896.425454] Lustre: Evicted from MGS (at 192.168.202.118@tcp) after server handle changed from 0x7b87496447d70805 to 0x7b87496447d97ae0 [ 1911.748558] Lustre: DEBUG MARKER: == recovery-small test 28: handle error adding new clients (bug 6086) ========================================================== 14:56:23 (1776192983) [ 1912.531592] Lustre: *** cfs_fail_loc=305, val=0*** [ 1912.534460] Lustre: Skipped 2 previous similar messages [ 1950.701458] LustreError: 166-1: MGC192.168.202.118@tcp: Connection to MGS (at 192.168.202.118@tcp) was lost; in progress operations using this service will fail [ 1950.765254] Lustre: Evicted from MGS (at 192.168.202.118@tcp) after server handle changed from 0x7b87496447d97ae0 to 0x7b87496447d99ba2 [ 1967.928866] Lustre: DEBUG MARKER: oleg218-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1969.264953] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1978.374767] Lustre: DEBUG MARKER: == recovery-small test 29a: error adding new clients doesn't cause LBUG (bug 22273) ========================================================== 14:57:29 (1776193049) [ 1993.695599] LustreError: 166-1: MGC192.168.202.118@tcp: Connection to MGS (at 192.168.202.118@tcp) was lost; in progress operations using this service will fail [ 1993.715428] Lustre: Evicted from MGS (at 192.168.202.118@tcp) after server handle changed from 0x7b87496447d99ba2 to 0x7b87496447d99e65 [ 1995.484302] LustreError: lustre-MDT0000-mdc-ffff8c6c0864f800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 2017.905843] Lustre: DEBUG MARKER: == recovery-small test 29b: error adding new clients doesn't cause LBUG (bug 22273) ========================================================== 14:58:09 (1776193089) [ 2029.549943] LustreError: lustre-OST0000-osc-ffff8c6c0864f800: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 2046.267676] Lustre: DEBUG MARKER: == recovery-small test 50: failover MDS under load ======= 14:58:37 (1776193117) [ 2059.967555] LustreError: 11-0: lustre-MDT0000-mdc-ffff8c6c0864f800: operation ldlm_enqueue to node 192.168.202.118@tcp failed: rc = -19 [ 2072.548421] LustreError: 166-1: MGC192.168.202.118@tcp: Connection to MGS (at 192.168.202.118@tcp) was lost; in progress operations using this service will fail [ 2088.932630] Lustre: Evicted from MGS (at 192.168.202.118@tcp) after server handle changed from 0x7b87496447d99e65 to 0x7b87496447da0d93 [ 2111.172145] Lustre: DEBUG MARKER: oleg218-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2114.028434] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2180.727571] Lustre: lustre-MDT0000-mdc-ffff8c6c0864f800: Connection to lustre-MDT0000 (at 192.168.202.118@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 2180.738980] Lustre: Skipped 13 previous similar messages [ 2192.351309] LustreError: 166-1: MGC192.168.202.118@tcp: Connection to MGS (at 192.168.202.118@tcp) was lost; in progress operations using this service will fail [ 2209.703345] Lustre: Evicted from MGS (at 192.168.202.118@tcp) after server handle changed from 0x7b87496447da0d93 to 0x7b87496447dc2f9a [ 2230.554858] Lustre: DEBUG MARKER: oleg218-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2233.312409] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2300.204682] LustreError: 11-0: lustre-MDT0000-mdc-ffff8c6c0864f800: operation mds_reint to node 192.168.202.118@tcp failed: rc = -19 [ 2300.221943] LustreError: Skipped 2 previous similar messages [ 2311.007262] LustreError: 166-1: MGC192.168.202.118@tcp: Connection to MGS (at 192.168.202.118@tcp) was lost; in progress operations using this service will fail [ 2328.365066] Lustre: Evicted from MGS (at 192.168.202.118@tcp) after server handle changed from 0x7b87496447dc2f9a to 0x7b87496447de681b [ 2328.379383] Lustre: MGC192.168.202.118@tcp: Connection restored to 192.168.202.118@tcp (at 192.168.202.118@tcp) [ 2328.391039] Lustre: Skipped 14 previous similar messages [ 2350.843208] Lustre: DEBUG MARKER: oleg218-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2353.143730] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2382.199716] Lustre: DEBUG MARKER: == recovery-small test 51: failover MDS during recovery == 15:04:14 (1776193454) [ 2395.103502] LustreError: 166-1: MGC192.168.202.118@tcp: Connection to MGS (at 192.168.202.118@tcp) was lost; in progress operations using this service will fail [ 2412.465074] Lustre: Evicted from MGS (at 192.168.202.118@tcp) after server handle changed from 0x7b87496447de681b to 0x7b87496447dfa93b [ 2426.172469] Lustre: DEBUG MARKER: test_51: failover in 1 sec [ 2468.779197] Lustre: DEBUG MARKER: test_51: failover in 5 sec [ 2485.151432] Lustre: 2221:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776193551/real 1776193551] req@000000002868b0e7 x1862471447869056/t0(0) o400->MGC192.168.202.118@tcp@192.168.202.118@tcp:26/25 lens 224/224 e 0 to 1 dl 1776193558 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:1.0' [ 2485.176912] Lustre: 2221:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 10 previous similar messages [ 2512.225416] Lustre: DEBUG MARKER: test_51: failover in 10 sec [ 2535.391621] LustreError: 166-1: MGC192.168.202.118@tcp: Connection to MGS (at 192.168.202.118@tcp) was lost; in progress operations using this service will fail [ 2535.441661] LustreError: Skipped 2 previous similar messages [ 2551.781948] Lustre: Evicted from MGS (at 192.168.202.118@tcp) after server handle changed from 0x7b87496447dfaeeb to 0x7b87496447e01b17 [ 2551.792449] Lustre: Skipped 2 previous similar messages [ 2563.316915] Lustre: DEBUG MARKER: test_51: failover in 20 sec [ 2587.198491] LustreError: 11-0: lustre-MDT0000-mdc-ffff8c6c0864f800: operation mds_reint to node 192.168.202.118@tcp failed: rc = -19 [ 2587.207603] LustreError: Skipped 4 previous similar messages [ 2624.986506] Lustre: DEBUG MARKER: test_51: failover in 25 sec [ 2692.045554] Lustre: DEBUG MARKER: test_51: failover in 30 sec [ 2786.202239] Lustre: DEBUG MARKER: == recovery-small test 52: failover OST under load ======= 15:10:58 (1776193858) [ 2800.220091] Lustre: lustre-OST0000-osc-ffff8c6c0864f800: Connection to lustre-OST0000 (at 192.168.202.118@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 2800.265773] Lustre: Skipped 6 previous similar messages [ 2843.356395] Lustre: DEBUG MARKER: oleg218-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 2845.765080] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 3132.315341] LustreError: 11-0: lustre-OST0000-osc-ffff8c6c0864f800: operation ldlm_enqueue to node 192.168.202.118@tcp failed: rc = -19 [ 3132.330226] LustreError: Skipped 10 previous similar messages [ 3168.921866] Lustre: DEBUG MARKER: oleg218-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 3171.717502] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 3463.750170] Lustre: lustre-OST0000-osc-ffff8c6c0864f800: Connection to lustre-OST0000 (at 192.168.202.118@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 3463.770615] Lustre: Skipped 1 previous similar message [ 3500.945654] Lustre: DEBUG MARKER: oleg218-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 3503.282435] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 3758.262765] Lustre: DEBUG MARKER: == recovery-small test 53a: touch: drop rep ============== 15:27:10 (1776194830) [ 3806.187892] Lustre: 49610:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776194832/real 1776194832] req@00000000d46d41e1 x1862471461151168/t0(0) o101->lustre-MDT0000-mdc-ffff8c6c0864f800@192.168.202.118@tcp:12/10 lens 648/66264 e 0 to 1 dl 1776194876 ref 2 fl Rpc:XPQr/0/ffffffff rc 0/-1 job:'openfile.0' [ 3806.223913] Lustre: 49610:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 4 previous similar messages [ 3806.280966] Lustre: lustre-MDT0000-mdc-ffff8c6c0864f800: Connection restored to 192.168.202.118@tcp (at 192.168.202.118@tcp) [ 3806.293555] Lustre: Skipped 13 previous similar messages [ 3815.422560] Lustre: DEBUG MARKER: == recovery-small test 53b: touch: drop rep ============== 15:28:07 (1776194887) [ 3871.546383] Lustre: DEBUG MARKER: == recovery-small test 53c: touch: drop rep ============== 15:29:03 (1776194943) [ 3916.767201] Lustre: 50966:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776194946/real 1776194946] req@00000000b792ae23 x1862471461157248/t0(0) o101->lustre-MDT0000-mdc-ffff8c6c0864f800@192.168.202.118@tcp:12/10 lens 664/66264 e 0 to 1 dl 1776194990 ref 2 fl Rpc:XPQr/0/ffffffff rc 0/-1 job:'openfile.0' [ 3916.821664] Lustre: 50966:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 3916.897756] Lustre: lustre-MDT0000-mdc-ffff8c6c0864f800: Connection restored to 192.168.202.118@tcp (at 192.168.202.118@tcp) [ 3916.918373] Lustre: Skipped 1 previous similar message [ 3927.504609] Lustre: DEBUG MARKER: == recovery-small test 54: back in time ================== 15:29:59 (1776194999) [ 3928.044251] Lustre: Mounted lustre-client [ 3963.880589] LustreError: 166-1: MGC192.168.202.118@tcp: Connection to MGS (at 192.168.202.118@tcp) was lost; in progress operations using this service will fail [ 3963.900152] LustreError: Skipped 3 previous similar messages [ 3963.921189] Lustre: Evicted from MGS (at 192.168.202.118@tcp) after server handle changed from 0x7b87496447e302ec to 0x7b87496447fdbd5e [ 3963.932370] Lustre: Skipped 3 previous similar messages [ 3974.611685] Lustre: DEBUG MARKER: oleg218-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3976.070098] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3978.030255] Lustre: Unmounted lustre-client [ 3984.755932] Lustre: DEBUG MARKER: == recovery-small test 55: ost_brw_read/write drops timed-out read/write request ========================================================== 15:30:56 (1776195056) [ 4065.247272] Lustre: lustre-OST0000-osc-ffff8c6c0864f800: Connection to lustre-OST0000 (at 192.168.202.118@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 4065.281857] Lustre: Skipped 13 previous similar messages [ 4072.415096] Lustre: 2222:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776195138/real 1776195138] req@00000000ba117b97 x1862471461197184/t0(0) o4->lustre-OST0000-osc-ffff8c6c0864f800@192.168.202.118@tcp:6/4 lens 488/448 e 0 to 1 dl 1776195145 ref 2 fl Rpc:XQr/2/ffffffff rc -11/-1 job:'dd.0' [ 4072.451658] Lustre: 2222:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 83 previous similar messages [ 4072.473961] Lustre: lustre-OST0000-osc-ffff8c6c0864f800: Connection restored to (at 192.168.202.118@tcp) [ 4072.485430] Lustre: Skipped 11 previous similar messages [ 4293.215665] Lustre: DEBUG MARKER: == recovery-small test 56: do not fail on getattr resend ========================================================== 15:36:04 (1776195364) [ 4344.469427] Lustre: DEBUG MARKER: == recovery-small test 57: read procfs entries causes kernel crash ========================================================== 15:36:55 (1776195415) [ 4348.379632] Lustre: Unmounted lustre-client [ 4371.691323] Lustre: Mounted lustre-client [ 4377.889886] Lustre: DEBUG MARKER: == recovery-small test 58: Eviction in the middle of open RPC reply processing ========================================================== 15:37:29 (1776195449) [ 4378.119465] LustreError: 55574:0:(fail.c:138:__cfs_fail_timeout_set()) cfs_fail_timeout id 801 sleeping for 20000ms [ 4379.167117] LustreError: 55574:0:(fail.c:144:__cfs_fail_timeout_set()) cfs_fail_timeout interrupted [ 4379.337576] Lustre: *** cfs_fail_loc=305, val=0*** [ 4397.674296] Lustre: DEBUG MARKER: == recovery-small test 59: Read cancel race on client eviction ========================================================== 15:37:49 (1776195469) [ 4398.221698] Lustre: Mounted lustre-client [ 4400.162434] Lustre: setting import lustre-MDT0000_UUID INACTIVE by administrator request [ 4410.432362] Lustre: Unmounted lustre-client [ 4417.227441] Lustre: DEBUG MARKER: == recovery-small test 60: Add Changelog entries during MDS failover ========================================================== 15:38:09 (1776195489) [ 4503.894507] LustreError: 11-0: lustre-MDT0000-mdc-ffff8c6c06f06800: operation mds_reint to node 192.168.202.118@tcp failed: rc = -19 [ 4503.903487] LustreError: Skipped 1 previous similar message [ 4513.247206] Lustre: 2224:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776195579/real 1776195579] req@00000000146aa1e5 x1862471462573248/t0(0) o400->MGC192.168.202.118@tcp@192.168.202.118@tcp:26/25 lens 224/224 e 0 to 1 dl 1776195586 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:1.0' [ 4513.286993] Lustre: 2224:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 247 previous similar messages [ 4513.296698] LustreError: 166-1: MGC192.168.202.118@tcp: Connection to MGS (at 192.168.202.118@tcp) was lost; in progress operations using this service will fail [ 4530.670912] Lustre: Evicted from MGS (at 192.168.202.118@tcp) after server handle changed from 0x7b87496447fdc4b2 to 0x7b87496448007cc2 [ 4530.695587] Lustre: MGC192.168.202.118@tcp: Connection restored to (at 192.168.202.118@tcp) [ 4530.705667] Lustre: Skipped 28 previous similar messages [ 4649.628420] Lustre: DEBUG MARKER: == recovery-small test 61: Verify to not reuse orphan objects - bug 17025 ========================================================== 15:42:01 (1776195721) [ 4654.413223] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4666.871299] Lustre: lustre-MDT0000-mdc-ffff8c6c06f06800: Connection to lustre-MDT0000 (at 192.168.202.118@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 4666.887384] Lustre: Skipped 30 previous similar messages [ 4666.892096] LustreError: 166-1: MGC192.168.202.118@tcp: Connection to MGS (at 192.168.202.118@tcp) was lost; in progress operations using this service will fail [ 4666.920382] Lustre: Evicted from MGS (at 192.168.202.118@tcp) after server handle changed from 0x7b87496448007cc2 to 0x7b87496448053c14 [ 4668.700424] LustreError: lustre-MDT0000-mdc-ffff8c6c06f06800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 4687.512140] Lustre: DEBUG MARKER: == recovery-small test 65: lock enqueue for destroyed export ========================================================== 15:42:39 (1776195759) [ 4688.083494] Lustre: Mounted lustre-client [ 4695.636154] LustreError: 11-0: lustre-OST0000-osc-ffff8c6c06f06800: operation ldlm_enqueue to node 192.168.202.118@tcp failed: rc = -107 [ 4695.651817] LustreError: lustre-OST0000-osc-ffff8c6c06f06800: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 4695.665617] LustreError: 59242:0:(ldlm_resource.c:1127:ldlm_resource_complain()) lustre-OST0000-osc-ffff8c6c06f06800: namespace resource [0x4b03:0x0:0x0].0x0 (00000000c1470477) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 4703.572217] Lustre: Unmounted lustre-client [ 4710.747782] Lustre: DEBUG MARKER: == recovery-small test 66: lock enqueue re-send vs client eviction ========================================================== 15:43:02 (1776195782) [ 4721.669884] LustreError: lustre-MDT0000-mdc-ffff8c6c06f06800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 4729.448303] Lustre: DEBUG MARKER: == recovery-small test 67: connect vs import invalidate race ========================================================== 15:43:21 (1776195801) [ 4729.664463] LustreError: 60607:0:(libcfs_fail.h:169:cfs_race()) cfs_race id 531 sleeping [ 4733.929713] LustreError: lustre-MDT0000-mdc-ffff8c6c06f06800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 4733.942935] LustreError: 60632:0:(libcfs_fail.h:180:cfs_race()) cfs_fail_race id 531 waking [ 4733.948947] LustreError: 60607:0:(libcfs_fail.h:178:cfs_race()) cfs_fail_race id 531 awake: rc=725 [ 4733.958507] LustreError: 60607:0:(import.c:702:ptlrpc_connect_import_locked()) already connecting [ 4734.011383] LustreError: 60637:0:(file.c:5205:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 4735.156143] LustreError: 60649:0:(file.c:5205:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 4736.368640] LustreError: 60660:0:(file.c:5205:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 4738.660698] LustreError: 60682:0:(file.c:5205:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 4738.677694] LustreError: 60682:0:(file.c:5205:ll_inode_revalidate_fini()) Skipped 1 previous similar message [ 4743.249478] LustreError: 60727:0:(file.c:5205:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 4743.268648] LustreError: 60727:0:(file.c:5205:ll_inode_revalidate_fini()) Skipped 3 previous similar messages [ 4752.368586] Lustre: DEBUG MARKER: == recovery-small test 100: IR: Make sure normal recovery still works w/o IR ========================================================== 15:43:44 (1776195824) [ 4793.115092] Lustre: DEBUG MARKER: oleg218-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 4794.862925] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4804.263944] Lustre: DEBUG MARKER: == recovery-small test 101a: IR: Make sure IR works w/o normal recovery ========================================================== 15:44:36 (1776195876) [ 4839.948325] Lustre: DEBUG MARKER: oleg218-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 4841.615796] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4851.947969] Lustre: DEBUG MARKER: == recovery-small test 101b: IR: Make sure IR works w/o normal recovery and proceed EAGAIN ========================================================== 15:45:23 (1776195923) [ 4914.333496] Lustre: DEBUG MARKER: oleg218-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 4916.003451] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4923.712356] Lustre: DEBUG MARKER: == recovery-small test 102: IR: New client gets updated nidtbl after MGS restart ========================================================== 15:46:35 (1776195995) [ 4959.184425] Lustre: DEBUG MARKER: oleg218-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 4960.974058] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4967.261486] Lustre: Unmounted lustre-client [ 5022.744549] Lustre: DEBUG MARKER: oleg218-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 5025.120948] Lustre: Mounted lustre-client [ 5031.939381] Lustre: DEBUG MARKER: == recovery-small test 103: IR: MDS can start w/o MGS and get updated nidtbl later ========================================================== 15:48:23 (1776196103) [ 5034.194825] Lustre: DEBUG MARKER: SKIP: recovery-small test_103 needs separate mgs and mds [ 5035.695753] Lustre: DEBUG MARKER: == recovery-small test 104: IR: ost can disable IR voluntarily ========================================================== 15:48:27 (1776196107) [ 5065.796365] Lustre: DEBUG MARKER: == recovery-small test 105: IR: NON IR clients support === 15:48:57 (1776196137) [ 5067.815590] Lustre: DEBUG MARKER: SKIP: recovery-small test_105 Needs multiple clients [ 5069.632342] Lustre: DEBUG MARKER: == recovery-small test 106: lightweight connection support ========================================================== 15:49:01 (1776196141) [ 5071.560183] Lustre: *** cfs_fail_loc=805, val=0*** [ 5071.608654] Lustre: Mounted lustre-client [ 5077.861480] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5089.248710] LustreError: 166-1: MGC192.168.202.118@tcp: Connection to MGS (at 192.168.202.118@tcp) was lost; in progress operations using this service will fail [ 5106.680320] Lustre: Evicted from MGS (at 192.168.202.118@tcp) after server handle changed from 0x7b87496448054d01 to 0x7b87496448055050 [ 5115.852509] Lustre: Unmounted lustre-client [ 5123.602164] Lustre: DEBUG MARKER: == recovery-small test 107: drop reint reply, then restart MDT ========================================================== 15:49:55 (1776196195) [ 5132.257533] Lustre: 70542:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776196198/real 1776196198] req@00000000232f909a x1862471463595648/t0(0) o36->lustre-MDT0000-mdc-ffff8c6c11a23000@192.168.202.118@tcp:12/10 lens 504/448 e 0 to 1 dl 1776196205 ref 2 fl Rpc:XQr/0/ffffffff rc 0/-1 job:'mkdir.0' [ 5132.295784] Lustre: 70542:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 8 previous similar messages [ 5156.784661] Lustre: MGC192.168.202.118@tcp: Connection restored to 192.168.202.118@tcp (at 192.168.202.118@tcp) [ 5156.796392] Lustre: Skipped 16 previous similar messages [ 5165.046833] LustreError: 2220:0:(client.c:3161:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@00000000c5e9c360 x1862471463595392/t85899345924(85899345924) o101->lustre-MDT0000-mdc-ffff8c6c11a23000@192.168.202.118@tcp:12/10 lens 664/600 e 0 to 0 dl 1776196245 ref 2 fl Interpret:RPQU/4/0 rc 301/301 job:'multiop.0' [ 5172.574885] Lustre: DEBUG MARKER: oleg218-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 5174.231638] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5183.432632] Lustre: DEBUG MARKER: == recovery-small test 108: client eviction don't crash == 15:50:55 (1776196255) [ 5185.035671] LustreError: 11-0: lustre-OST0000-osc-ffff8c6c11a23000: operation ost_write to node 192.168.202.118@tcp failed: rc = -107 [ 5185.045354] LustreError: Skipped 1 previous similar message [ 5185.065987] LustreError: lustre-OST0000-osc-ffff8c6c11a23000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 5185.077866] Lustre: 2223:0:(llite_lib.c:3595:ll_dirty_page_discard_warn()) lustre: dirty page discard: 192.168.202.118@tcp:/lustre/fid: [0x20000a042:0x6:0x0]// may get corrupted (rc -5) [ 5185.104451] LustreError: 71979:0:(ldlm_resource.c:1127:ldlm_resource_complain()) lustre-OST0000-osc-ffff8c6c11a23000: namespace resource [0x4c22:0x0:0x0].0x0 (00000000d8846df5) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 5185.112140] LustreError: 71979:0:(ldlm_resource.c:1127:ldlm_resource_complain()) Skipped 1 previous similar message [ 5194.590942] Lustre: DEBUG MARKER: == recovery-small test 110a: create remote directory: drop client req ========================================================== 15:51:05 (1776196265) [ 5196.263444] Lustre: DEBUG MARKER: SKIP: recovery-small test_110a needs >= 2 MDTs [ 5197.845562] Lustre: DEBUG MARKER: == recovery-small test 110b: create remote directory: drop Master rep ========================================================== 15:51:09 (1776196269) [ 5199.209776] Lustre: DEBUG MARKER: SKIP: recovery-small test_110b needs >= 2 MDTs [ 5200.969645] Lustre: DEBUG MARKER: == recovery-small test 110c: create remote directory: drop update rep on slave MDT ========================================================== 15:51:12 (1776196272) [ 5202.801489] Lustre: DEBUG MARKER: SKIP: recovery-small test_110c needs >= 2 MDTs [ 5204.375452] Lustre: DEBUG MARKER: == recovery-small test 110d: remove remote directory: drop client req ========================================================== 15:51:16 (1776196276) [ 5206.151798] Lustre: DEBUG MARKER: SKIP: recovery-small test_110d needs >= 2 MDTs [ 5208.094341] Lustre: DEBUG MARKER: == recovery-small test 110e: remove remote directory: drop master rep ========================================================== 15:51:19 (1776196279) [ 5209.822528] Lustre: DEBUG MARKER: SKIP: recovery-small test_110e needs >= 2 MDTs [ 5211.587409] Lustre: DEBUG MARKER: == recovery-small test 110f: remove remote directory: drop slave rep ========================================================== 15:51:23 (1776196283) [ 5212.972262] Lustre: DEBUG MARKER: SKIP: recovery-small test_110f needs >= 2 MDTs [ 5214.527862] Lustre: DEBUG MARKER: == recovery-small test 110g: drop reply during migration ========================================================== 15:51:26 (1776196286) [ 5216.310802] Lustre: DEBUG MARKER: SKIP: recovery-small test_110g needs >= 2 MDTs [ 5218.450869] Lustre: DEBUG MARKER: == recovery-small test 110h: drop update reply during cross-MDT file rename ========================================================== 15:51:30 (1776196290) [ 5220.116975] Lustre: DEBUG MARKER: SKIP: recovery-small test_110h needs >= 2 MDTs [ 5222.302383] Lustre: DEBUG MARKER: == recovery-small test 110i: drop update reply during cross-MDT dir rename ========================================================== 15:51:34 (1776196294) [ 5223.866877] Lustre: DEBUG MARKER: SKIP: recovery-small test_110i needs >= 2 MDTs [ 5225.826805] Lustre: DEBUG MARKER: == recovery-small test 110j: drop update reply during cross-MDT ln ========================================================== 15:51:37 (1776196297) [ 5227.118702] Lustre: DEBUG MARKER: SKIP: recovery-small test_110j needs >= 2 MDTs [ 5229.213226] Lustre: DEBUG MARKER: == recovery-small test 110k: FID_QUERY failed during recovery ========================================================== 15:51:40 (1776196300) [ 5231.174254] Lustre: DEBUG MARKER: SKIP: recovery-small test_110k needs >= 2 MDTS [ 5232.910793] Lustre: DEBUG MARKER: == recovery-small test 110m: update resent vs original RPC race ========================================================== 15:51:44 (1776196304) [ 5235.971461] Lustre: DEBUG MARKER: SKIP: recovery-small test_110m needs at least 2 MDTs [ 5237.998953] Lustre: DEBUG MARKER: == recovery-small test 111: mdd setup fail should not cause umount oops ========================================================== 15:51:49 (1776196309) [ 5269.897291] Lustre: DEBUG MARKER: == recovery-small test 112a: bulk resend while orignal request is in progress ========================================================== 15:52:21 (1776196341) [ 5301.010518] Lustre: DEBUG MARKER: == recovery-small test 115a: read: late REQ MDunlink and no bulk ========================================================== 15:52:52 (1776196372) [ 5301.597807] Lustre: *** cfs_fail_loc=51b, val=0*** [ 5313.227995] Lustre: DEBUG MARKER: == recovery-small test 115b: write: late REQ MDunlink and no bulk ========================================================== 15:53:04 (1776196384) [ 5313.775477] Lustre: *** cfs_fail_loc=51b, val=0*** [ 5324.844744] Lustre: DEBUG MARKER: == recovery-small test 115c: read: late Reply MDunlink and no bulk ========================================================== 15:53:16 (1776196396) [ 5325.286961] Lustre: *** cfs_fail_loc=50f, val=0*** [ 5334.711175] Lustre: DEBUG MARKER: == recovery-small test 115d: write: late Reply MDunlink and no bulk ========================================================== 15:53:26 (1776196406) [ 5335.055702] Lustre: *** cfs_fail_loc=50f, val=0*** [ 5344.305863] Lustre: DEBUG MARKER: == recovery-small test 115e: read: late Bulk MDunlink and no reply ========================================================== 15:53:35 (1776196415) [ 5344.590764] Lustre: *** cfs_fail_loc=510, val=0*** [ 5353.098975] Lustre: DEBUG MARKER: == recovery-small test 115f: read: late REQ MDunlink and no reply ========================================================== 15:53:44 (1776196424) [ 5353.500147] Lustre: *** cfs_fail_loc=51b, val=0*** [ 5391.263274] Lustre: lustre-OST0000-osc-ffff8c6c11a23000: Connection to lustre-OST0000 (at 192.168.202.118@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 5391.275718] Lustre: Skipped 17 previous similar messages [ 5416.309674] Lustre: DEBUG MARKER: == recovery-small test 115g: read: late REQ MDunlink and Reply MDunlink ========================================================== 15:54:48 (1776196488) [ 5416.786254] Lustre: *** cfs_fail_loc=51c, val=0*** [ 5480.589458] Lustre: DEBUG MARKER: == recovery-small test 120: flock race: completion vs. evict ========================================================== 15:55:52 (1776196552) [ 5480.840643] LustreError: 82085:0:(fail.c:138:__cfs_fail_timeout_set()) cfs_fail_timeout id 320 sleeping for 4000ms [ 5483.926358] LustreError: lustre-MDT0000-mdc-ffff8c6c11a23000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5483.945092] LustreError: 82102:0:(file.c:246:ll_close_inode_openhandle()) lustre-clilmv-ffff8c6c11a23000: inode [0x20000a042:0x8:0x0] mdc close failed: rc = -108 [ 5483.975044] LustreError: 82102:0:(ldlm_resource.c:1127:ldlm_resource_complain()) lustre-MDT0000-mdc-ffff8c6c11a23000: namespace resource [0x20000a042:0xf:0x0].0xc (0000000057d4dcea) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 5484.927603] LustreError: 82085:0:(fail.c:149:__cfs_fail_timeout_set()) cfs_fail_timeout id 320 awake [ 5487.059549] LustreError: 82117:0:(fail.c:138:__cfs_fail_timeout_set()) cfs_fail_timeout id 320 sleeping for 4000ms [ 5490.294422] LustreError: 11-0: lustre-MDT0000-mdc-ffff8c6c11a23000: operation ldlm_enqueue to node 192.168.202.118@tcp failed: rc = -107 [ 5490.313299] LustreError: Skipped 1 previous similar message [ 5490.340778] LustreError: lustre-MDT0000-mdc-ffff8c6c11a23000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5490.368433] LustreError: 82135:0:(ldlm_resource.c:1127:ldlm_resource_complain()) lustre-MDT0000-mdc-ffff8c6c11a23000: namespace resource [0x20000a042:0xf:0x0].0xc (00000000f214ccb8) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 5490.403891] LustreError: 82135:0:(ldlm_resource.c:1127:ldlm_resource_complain()) Skipped 1 previous similar message [ 5490.438944] LustreError: 82140:0:(file.c:5205:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 5491.151132] LustreError: 82117:0:(fail.c:149:__cfs_fail_timeout_set()) cfs_fail_timeout id 320 awake [ 5495.148587] LustreError: 82148:0:(fail.c:138:__cfs_fail_timeout_set()) cfs_fail_timeout id 320 sleeping for 4000ms [ 5498.007650] LustreError: lustre-MDT0000-mdc-ffff8c6c11a23000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5498.029679] LustreError: 82165:0:(ldlm_resource.c:1127:ldlm_resource_complain()) lustre-MDT0000-mdc-ffff8c6c11a23000: namespace resource [0x20000a042:0xf:0x0].0xc (00000000f214ccb8) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 5498.064364] LustreError: 82165:0:(ldlm_resource.c:1127:ldlm_resource_complain()) Skipped 1 previous similar message [ 5499.247266] LustreError: 82148:0:(fail.c:149:__cfs_fail_timeout_set()) cfs_fail_timeout id 320 awake [ 5499.396964] LustreError: 82177:0:(fail.c:138:__cfs_fail_timeout_set()) cfs_fail_timeout id 321 sleeping for 4000ms [ 5502.691948] LustreError: lustre-MDT0000-mdc-ffff8c6c11a23000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5502.749547] LustreError: 82200:0:(file.c:5205:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 5503.471420] LustreError: 82177:0:(fail.c:149:__cfs_fail_timeout_set()) cfs_fail_timeout id 321 awake [ 5503.477976] LustreError: 82177:0:(file.c:246:ll_close_inode_openhandle()) lustre-clilmv-ffff8c6c11a23000: inode [0x20000a042:0xf:0x0] mdc close failed: rc = -108 [ 5503.484041] LustreError: 82177:0:(file.c:246:ll_close_inode_openhandle()) Skipped 2 previous similar messages [ 5504.967518] LustreError: 82217:0:(file.c:5205:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 5504.978713] LustreError: 82217:0:(file.c:5205:ll_inode_revalidate_fini()) Skipped 12 previous similar messages [ 5509.937206] LustreError: 82254:0:(fail.c:138:__cfs_fail_timeout_set()) cfs_fail_timeout id 321 sleeping for 4000ms [ 5513.084184] LustreError: lustre-MDT0000-mdc-ffff8c6c11a23000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5513.117176] LustreError: 82272:0:(ldlm_resource.c:1127:ldlm_resource_complain()) lustre-MDT0000-mdc-ffff8c6c11a23000: namespace resource [0x20000a042:0xf:0x0].0xc (00000000b38c9628) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 5513.144862] LustreError: 82272:0:(ldlm_resource.c:1127:ldlm_resource_complain()) Skipped 1 previous similar message [ 5513.174305] LustreError: 82277:0:(file.c:5205:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 5513.186035] LustreError: 82277:0:(file.c:5205:ll_inode_revalidate_fini()) Skipped 13 previous similar messages [ 5514.007989] LustreError: 82254:0:(fail.c:149:__cfs_fail_timeout_set()) cfs_fail_timeout id 321 awake [ 5517.984660] LustreError: 82285:0:(fail.c:138:__cfs_fail_timeout_set()) cfs_fail_timeout id 321 sleeping for 4000ms [ 5521.239330] LustreError: lustre-MDT0000-mdc-ffff8c6c11a23000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5522.063140] LustreError: 82285:0:(fail.c:149:__cfs_fail_timeout_set()) cfs_fail_timeout id 321 awake [ 5525.217685] LustreError: lustre-MDT0000-mdc-ffff8c6c11a23000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5529.404888] LustreError: lustre-MDT0000-mdc-ffff8c6c11a23000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5529.507887] LustreError: 82367:0:(file.c:5205:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 5530.464143] LustreError: 82345:0:(file.c:246:ll_close_inode_openhandle()) lustre-clilmv-ffff8c6c11a23000: inode [0x20000a042:0xf:0x0] mdc close failed: rc = -108 [ 5538.405751] LustreError: 82418:0:(fail.c:138:__cfs_fail_timeout_set()) cfs_fail_timeout id 320 sleeping for 4000ms [ 5538.414424] LustreError: 82418:0:(fail.c:138:__cfs_fail_timeout_set()) Skipped 2 previous similar messages [ 5541.975242] LustreError: lustre-MDT0000-mdc-ffff8c6c11a23000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5542.495843] LustreError: 82418:0:(fail.c:149:__cfs_fail_timeout_set()) cfs_fail_timeout id 320 awake [ 5542.522693] LustreError: 82418:0:(fail.c:149:__cfs_fail_timeout_set()) Skipped 2 previous similar messages [ 5542.531915] LustreError: 82418:0:(file.c:246:ll_close_inode_openhandle()) lustre-clilmv-ffff8c6c11a23000: inode [0x20000a042:0xf:0x0] mdc close failed: rc = -108 [ 5545.557764] LustreError: 82477:0:(file.c:5205:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 5545.587392] LustreError: 82477:0:(file.c:5205:ll_inode_revalidate_fini()) Skipped 47 previous similar messages [ 5554.209758] Lustre: DEBUG MARKER: == recovery-small test 113: ldlm enqueue dropped reply should not cause deadlocks ========================================================== 15:57:06 (1776196626) [ 5576.009973] Lustre: DEBUG MARKER: == recovery-small test 130a: enqueue resend on not existing file ========================================================== 15:57:27 (1776196647) [ 5631.972268] Lustre: DEBUG MARKER: == recovery-small test 130b: enqueue resend on a stale inode ========================================================== 15:58:23 (1776196703) [ 5688.663488] Lustre: DEBUG MARKER: == recovery-small test 130c: layout intent resend on a stale inode ========================================================== 15:59:19 (1776196759) [ 5726.534681] Lustre: DEBUG MARKER: == recovery-small test 132: long punch =================== 15:59:58 (1776196798) [ 5727.056754] Lustre: Mounted lustre-client [ 5851.332844] Lustre: Unmounted lustre-client [ 5858.521744] Lustre: DEBUG MARKER: == recovery-small test 131: IO vs evict results to IO under staled lock ========================================================== 16:02:10 (1776196930) [ 5859.237482] LustreError: 86772:0:(fail.c:138:__cfs_fail_timeout_set()) cfs_fail_timeout id 414 sleeping for 4000ms [ 5859.244579] LustreError: 86772:0:(fail.c:138:__cfs_fail_timeout_set()) Skipped 2 previous similar messages [ 5862.685785] LustreError: lustre-OST0000-osc-ffff8c6c11a23000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 5862.697893] LustreError: 86857:0:(ldlm_resource.c:1127:ldlm_resource_complain()) lustre-OST0000-osc-ffff8c6c11a23000: namespace resource [0x4c4d:0x0:0x0].0x0 (00000000d8846df5) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 5862.708801] LustreError: 86857:0:(ldlm_resource.c:1127:ldlm_resource_complain()) Skipped 6 previous similar messages [ 5863.327135] LustreError: 86772:0:(fail.c:149:__cfs_fail_timeout_set()) cfs_fail_timeout id 414 awake [ 5863.334682] LustreError: 86772:0:(fail.c:149:__cfs_fail_timeout_set()) Skipped 2 previous similar messages [ 5863.350175] Lustre: 2223:0:(llite_lib.c:3595:ll_dirty_page_discard_warn()) lustre: dirty page discard: 192.168.202.118@tcp:/lustre/fid: [0x20000bf89:0x9:0x0]// may get corrupted (rc -108) [ 5863.380282] Lustre: lustre-OST0000-osc-ffff8c6c11a23000: Connection restored to (at 192.168.202.118@tcp) [ 5863.392247] Lustre: Skipped 15 previous similar messages [ 5871.187846] Lustre: DEBUG MARKER: == recovery-small test 133: don't fail on flock resend === 16:02:22 (1776196942) [ 5919.712429] Lustre: 87460:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776196947/real 1776196947] req@000000007b49dfc9 x1862471463684672/t0(0) o101->lustre-MDT0000-mdc-ffff8c6c11a23000@192.168.202.118@tcp:12/10 lens 328/344 e 0 to 1 dl 1776196991 ref 2 fl Rpc:XQr/0/ffffffff rc 0/-1 job:'multiop.0' [ 5919.785290] Lustre: 87460:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 9 previous similar messages [ 5927.036254] Lustre: DEBUG MARKER: == recovery-small test 134: race between failover and search for reply data free slot ========================================================== 16:03:18 (1776196998) [ 5928.373654] Lustre: DEBUG MARKER: SKIP: recovery-small test_134 Need 2+ clients, have 1 [ 5931.065265] Lustre: DEBUG MARKER: == recovery-small test 135: DOM: open/create resend to return size ========================================================== 16:03:22 (1776197002) [ 5982.583768] Lustre: DEBUG MARKER: SKIP: recovery-small test_136 skipping excluded test 136 [ 5984.045131] Lustre: DEBUG MARKER: == recovery-small test 137: late resend must be skipped if already applied ========================================================== 16:04:16 (1776197056) [ 6030.303341] Lustre: lustre-MDT0000-mdc-ffff8c6c11a23000: Connection to lustre-MDT0000 (at 192.168.202.118@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 6030.323776] Lustre: Skipped 17 previous similar messages [ 6031.905206] Lustre: DEBUG MARKER: == recovery-small test 138: Umount MDT during recovery === 16:05:03 (1776197103) [ 6034.357528] Lustre: DEBUG MARKER: SKIP: recovery-small test_138 needs >= 2 MDTs [ 6036.123268] Lustre: DEBUG MARKER: == recovery-small test 139: corrupted catid won't cause crash ========================================================== 16:05:07 (1776197107) [ 6037.822652] Lustre: DEBUG MARKER: SKIP: recovery-small test_139 needs >= 2 MDTs [ 6039.986595] Lustre: DEBUG MARKER: == recovery-small test 140a: local mount is flagged properly ========================================================== 16:05:11 (1776197111) [ 6079.631800] Lustre: DEBUG MARKER: == recovery-small test 140b: local mount is excluded from recovery ========================================================== 16:05:51 (1776197151) [ 6092.434337] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 6109.151249] LustreError: 166-1: MGC192.168.202.118@tcp: Connection to MGS (at 192.168.202.118@tcp) was lost; in progress operations using this service will fail [ 6109.161617] LustreError: Skipped 2 previous similar messages [ 6126.587269] Lustre: Evicted from MGS (at 192.168.202.118@tcp) after server handle changed from 0x7b87496448055cf2 to 0x7b8749644805723f [ 6126.605208] Lustre: Skipped 2 previous similar messages [ 6130.115670] LustreError: 2220:0:(client.c:3161:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@00000000c5e9c360 x1862471463681088/t94489280648(94489280648) o101->lustre-MDT0000-mdc-ffff8c6c11a23000@192.168.202.118@tcp:12/10 lens 576/600 e 0 to 0 dl 1776197246 ref 2 fl Interpret:RPQU/4/0 rc 301/301 job:'dd.0' [ 6143.887888] Lustre: DEBUG MARKER: oleg218-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 6145.739729] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6156.600189] Lustre: DEBUG MARKER: == recovery-small test 141: do not lose locks on MGS restart ========================================================== 16:07:08 (1776197228) [ 6159.025930] Lustre: DEBUG MARKER: SKIP: recovery-small test_141 cannot run in local mode or from build tree [ 6160.633961] Lustre: DEBUG MARKER: == recovery-small test 142: orphan name stub can be cleaned up in startup ========================================================== 16:07:12 (1776197232) [ 6172.692413] LustreError: 166-1: MGC192.168.202.118@tcp: Connection to MGS (at 192.168.202.118@tcp) was lost; in progress operations using this service will fail [ 6172.744842] Lustre: Evicted from MGS (at 192.168.202.118@tcp) after server handle changed from 0x7b8749644805723f to 0x7b87496448057587 [ 6180.226409] LustreError: 2220:0:(client.c:3161:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@00000000c5e9c360 x1862471463681088/t94489280648(94489280648) o101->lustre-MDT0000-mdc-ffff8c6c11a23000@192.168.202.118@tcp:12/10 lens 576/600 e 0 to 0 dl 1776197295 ref 2 fl Interpret:RPQU/4/0 rc 301/301 job:'dd.0' [ 6193.757838] Lustre: DEBUG MARKER: == recovery-small test 143: orphan cleanup thread shouldn't be blocked even delete failed ========================================================== 16:07:45 (1776197265) [ 6223.327121] LustreError: 2220:0:(client.c:3161:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@00000000c5e9c360 x1862471463681088/t94489280648(94489280648) o101->lustre-MDT0000-mdc-ffff8c6c11a23000@192.168.202.118@tcp:12/10 lens 576/600 e 0 to 0 dl 1776197337 ref 2 fl Interpret:RPQU/4/0 rc 301/301 job:'dd.0' [ 6241.581130] Lustre: DEBUG MARKER: == recovery-small test 144a: MDT failover should stop precreation threads ========================================================== 16:08:33 (1776197313) [ 6247.660457] LustreError: 11-0: lustre-OST0000-osc-ffff8c6c11a23000: operation ost_setattr to node 192.168.202.118@tcp failed: rc = -19 [ 6247.673056] LustreError: Skipped 13 previous similar messages [ 6281.476611] Lustre: DEBUG MARKER: oleg218-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 6283.192937] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 6362.089353] LustreError: 166-1: MGC192.168.202.118@tcp: Connection to MGS (at 192.168.202.118@tcp) was lost; in progress operations using this service will fail [ 6362.106701] LustreError: Skipped 1 previous similar message [ 6368.303481] Lustre: Evicted from MGS (at 192.168.202.118@tcp) after server handle changed from 0x7b8749644805791c to 0x7b87496448057e6a [ 6368.309077] Lustre: Skipped 1 previous similar message [ 6384.687972] LustreError: 2220:0:(client.c:3161:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@00000000c5e9c360 x1862471463681088/t94489280648(94489280648) o101->lustre-MDT0000-mdc-ffff8c6c11a23000@192.168.202.118@tcp:12/10 lens 576/600 e 0 to 0 dl 1776197608 ref 2 fl Interpret:RPQU/4/0 rc 301/301 job:'dd.0' [ 6390.752956] INFO: task touch:94996 blocked for more than 120 seconds. [ 6390.755219] Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 6390.777090] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 6390.819502] task:touch state:D stack:0 pid:94996 ppid:94734 flags:0x80000004 [ 6390.852644] Call Trace: [ 6390.853585] __schedule+0x351/0xcb0 [ 6390.894329] schedule+0xc0/0x180 [ 6390.905748] schedule_preempt_disabled+0x21/0x40 [ 6390.916536] rwsem_down_write_slowpath+0x5d7/0xa40 [ 6390.939785] down_write+0x80/0xd0 [ 6390.961554] do_last+0x2eb/0xfc0 [ 6390.968834] ? nd_jump_root+0xe5/0x160 [ 6390.992891] ? path_init+0x437/0x520 [ 6390.994160] path_openat+0xf7/0x500 [ 6390.995330] do_filp_open+0x99/0x140 [ 6391.039069] ? getname_flags+0x6e/0x330 [ 6391.040431] ? __check_object_size+0xff/0x256 [ 6391.041826] ? do_raw_spin_unlock+0x75/0x190 [ 6391.059983] ? _raw_spin_unlock+0x12/0x30 [ 6391.073363] do_sys_openat2+0x2b4/0x410 [ 6391.074860] do_sys_open+0x73/0xa0 [ 6391.082042] __x64_sys_openat+0x24/0x30 [ 6391.088971] do_syscall_64+0xc1/0x440 [ 6391.093943] entry_SYSCALL_64_after_hwframe+0x49/0xae [ 6391.115132] RIP: 0033:0x7fd033ef1332 [ 6391.118889] Code: Unable to access opcode bytes at RIP 0x7fd033ef1308. [ 6391.132492] RSP: 002b:00007ffc3edc68c0 EFLAGS: 00000246 ORIG_RAX: 0000000000000101 [ 6391.153732] RAX: ffffffffffffffda RBX: 00000000ffffffff RCX: 00007fd033ef1332 [ 6391.168795] RDX: 0000000000000941 RSI: 00007ffc3edc9075 RDI: 00000000ffffff9c [ 6391.184010] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000001 [ 6391.197650] R10: 00000000000001b6 R11: 0000000000000246 R12: 0000000000000001 [ 6391.208814] R13: 0000000000000001 R14: 00007ffc3edc9075 R15: 00007fd034194374 [ 6391.223834] INFO: task touch:94997 blocked for more than 120 seconds. [ 6391.226309] Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 6391.235416] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 6391.264715] task:touch state:D stack:0 pid:94997 ppid:94734 flags:0x80000004 [ 6391.289800] Call Trace: [ 6391.296273] __schedule+0x351/0xcb0 [ 6391.301056] schedule+0xc0/0x180 [ 6391.302289] schedule_preempt_disabled+0x21/0x40 [ 6391.309614] rwsem_down_write_slowpath+0x5d7/0xa40 [ 6391.320079] down_write+0x80/0xd0 [ 6391.326660] do_last+0x2eb/0xfc0 [ 6391.335172] ? nd_jump_root+0xe5/0x160 [ 6391.341564] ? path_init+0x437/0x520 [ 6391.349096] path_openat+0xf7/0x500 [ 6391.356581] ? __mod_lruvec_state+0x5a/0x80 [ 6391.363573] do_filp_open+0x99/0x140 [ 6391.370196] ? getname_flags+0x6e/0x330 [ 6391.375308] ? __check_object_size+0xff/0x256 [ 6391.386590] ? do_raw_spin_unlock+0x75/0x190 [ 6391.388191] ? _raw_spin_unlock+0x12/0x30 [ 6391.389707] do_sys_openat2+0x2b4/0x410 [ 6391.398990] do_sys_open+0x73/0xa0 [ 6391.401390] __x64_sys_openat+0x24/0x30 [ 6391.404718] do_syscall_64+0xc1/0x440 [ 6391.406716] entry_SYSCALL_64_after_hwframe+0x49/0xae [ 6391.409676] RIP: 0033:0x7fcd382dd332 [ 6391.411675] Code: Unable to access opcode bytes at RIP 0x7fcd382dd308. [ 6391.415660] RSP: 002b:00007ffe055e7e30 EFLAGS: 00000246 ORIG_RAX: 0000000000000101 [ 6391.422926] RAX: ffffffffffffffda RBX: 00000000ffffffff RCX: 00007fcd382dd332 [ 6391.427146] RDX: 0000000000000941 RSI: 00007ffe055e9075 RDI: 00000000ffffff9c [ 6391.430255] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000001 [ 6391.432239] R10: 00000000000001b6 R11: 0000000000000246 R12: 0000000000000001 [ 6391.434305] R13: 0000000000000001 R14: 00007ffe055e9075 R15: 00007fcd38580374 [ 6391.436803] INFO: task touch:94998 blocked for more than 120 seconds. [ 6391.438588] Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 6391.440434] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 6391.442532] task:touch state:D stack:0 pid:94998 ppid:94734 flags:0x80000004 [ 6391.444906] Call Trace: [ 6391.445776] __schedule+0x351/0xcb0 [ 6391.446738] schedule+0xc0/0x180 [ 6391.447701] schedule_preempt_disabled+0x21/0x40 [ 6391.448935] rwsem_down_write_slowpath+0x5d7/0xa40 [ 6391.450168] down_write+0x80/0xd0 [ 6391.450971] do_last+0x2eb/0xfc0 [ 6391.451745] ? nd_jump_root+0xe5/0x160 [ 6391.452792] ? path_init+0x437/0x520 [ 6391.453760] path_openat+0xf7/0x500 [ 6391.454692] do_filp_open+0x99/0x140 [ 6391.455645] ? getname_flags+0x6e/0x330 [ 6391.456701] ? __check_object_size+0xff/0x256 [ 6391.457907] ? do_raw_spin_unlock+0x75/0x190 [ 6391.459294] ? _raw_spin_unlock+0x12/0x30 [ 6391.460505] do_sys_openat2+0x2b4/0x410 [ 6391.461556] do_sys_open+0x73/0xa0 [ 6391.462745] __x64_sys_openat+0x24/0x30 [ 6391.463751] do_syscall_64+0xc1/0x440 [ 6391.464735] entry_SYSCALL_64_after_hwframe+0x49/0xae [ 6391.466073] RIP: 0033:0x7f44aab5a332 [ 6391.467147] Code: Unable to access opcode bytes at RIP 0x7f44aab5a308. [ 6391.468746] RSP: 002b:00007ffe13d281d0 EFLAGS: 00000246 ORIG_RAX: 0000000000000101 [ 6391.472742] RAX: ffffffffffffffda RBX: 00000000ffffffff RCX: 00007f44aab5a332 [ 6391.476430] RDX: 0000000000000941 RSI: 00007ffe13d29075 RDI: 00000000ffffff9c [ 6391.479803] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000001 [ 6391.483209] R10: 00000000000001b6 R11: 0000000000000246 R12: 0000000000000001 [ 6391.486118] R13: 0000000000000001 R14: 00007ffe13d29075 R15: 00007f44aadfd374 [ 6391.488366] INFO: task touch:94999 blocked for more than 120 seconds. [ 6391.491239] Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 6391.494608] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 6391.498129] task:touch state:D stack:0 pid:94999 ppid:94734 flags:0x80000004 [ 6391.501488] Call Trace: [ 6391.502770] __schedule+0x351/0xcb0 [ 6391.504281] schedule+0xc0/0x180 [ 6391.505634] schedule_preempt_disabled+0x21/0x40 [ 6391.507483] rwsem_down_write_slowpath+0x5d7/0xa40 [ 6391.510954] down_write+0x80/0xd0 [ 6391.512762] do_last+0x2eb/0xfc0 [ 6391.514491] ? nd_jump_root+0xe5/0x160 [ 6391.518792] ? path_init+0x437/0x520 [ 6391.520930] path_openat+0xf7/0x500 [ 6391.522770] ? __mod_lruvec_state+0x5a/0x80 [ 6391.524904] do_filp_open+0x99/0x140 [ 6391.526468] ? getname_flags+0x6e/0x330 [ 6391.533402] ? __check_object_size+0xff/0x256 [ 6391.534895] ? do_raw_spin_unlock+0x75/0x190 [ 6391.537431] ? _raw_spin_unlock+0x12/0x30 [ 6391.541829] do_sys_openat2+0x2b4/0x410 [ 6391.543908] do_sys_open+0x73/0xa0 [ 6391.545954] __x64_sys_openat+0x24/0x30 [ 6391.547969] do_syscall_64+0xc1/0x440 [ 6391.550152] entry_SYSCALL_64_after_hwframe+0x49/0xae [ 6391.552526] RIP: 0033:0x7f674ce1f332 [ 6391.554306] Code: Unable to access opcode bytes at RIP 0x7f674ce1f308. [ 6391.557149] RSP: 002b:00007fff16d317a0 EFLAGS: 00000246 ORIG_RAX: 0000000000000101 [ 6391.560308] RAX: ffffffffffffffda RBX: 00000000ffffffff RCX: 00007f674ce1f332 [ 6391.566782] RDX: 0000000000000941 RSI: 00007fff16d33075 RDI: 00000000ffffff9c [ 6391.575362] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000001 [ 6391.579903] R10: 00000000000001b6 R11: 0000000000000246 R12: 0000000000000001 [ 6391.588299] R13: 0000000000000001 R14: 00007fff16d33075 R15: 00007f674d0c2374 [ 6391.609058] INFO: task touch:95000 blocked for more than 120 seconds. [ 6391.611423] Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 6391.619059] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 6391.630146] task:touch state:D stack:0 pid:95000 ppid:94734 flags:0x80000004 [ 6391.641092] Call Trace: [ 6391.652516] __schedule+0x351/0xcb0 [ 6391.653867] schedule+0xc0/0x180 [ 6391.660862] schedule_preempt_disabled+0x21/0x40 [ 6391.668149] rwsem_down_write_slowpath+0x5d7/0xa40 [ 6391.673977] down_write+0x80/0xd0 [ 6391.680306] do_last+0x2eb/0xfc0 [ 6391.682705] ? nd_jump_root+0xe5/0x160 [ 6391.705811] ? path_init+0x437/0x520 [ 6391.714889] path_openat+0xf7/0x500 [ 6391.721587] do_filp_open+0x99/0x140 [ 6391.728559] ? getname_flags+0x6e/0x330 [ 6391.733335] ? __check_object_size+0xff/0x256 [ 6391.737170] ? do_raw_spin_unlock+0x75/0x190 [ 6391.743182] ? _raw_spin_unlock+0x12/0x30 [ 6391.752618] do_sys_openat2+0x2b4/0x410 [ 6391.768264] do_sys_open+0x73/0xa0 [ 6391.776543] __x64_sys_openat+0x24/0x30 [ 6391.791968] do_syscall_64+0xc1/0x440 [ 6391.794461] entry_SYSCALL_64_after_hwframe+0x49/0xae [ 6391.807900] RIP: 0033:0x7fd180756332 [ 6391.815753] Code: Unable to access opcode bytes at RIP 0x7fd180756308. [ 6391.833089] RSP: 002b:00007ffd6fba9050 EFLAGS: 00000246 ORIG_RAX: 0000000000000101 [ 6391.853400] RAX: ffffffffffffffda RBX: 00000000ffffffff RCX: 00007fd180756332 [ 6391.873561] RDX: 0000000000000941 RSI: 00007ffd6fbaa075 RDI: 00000000ffffff9c [ 6391.889803] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000001 [ 6391.901339] R10: 00000000000001b6 R11: 0000000000000246 R12: 0000000000000001 [ 6391.908162] R13: 0000000000000001 R14: 00007ffd6fbaa075 R15: 00007fd1809f9374 [ 6391.929063] INFO: task touch:95001 blocked for more than 120 seconds. [ 6391.940917] Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 6391.974798] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 6391.978768] task:touch state:D stack:0 pid:95001 ppid:94734 flags:0x80000004 [ 6392.005867] Call Trace: [ 6392.024793] __schedule+0x351/0xcb0 [ 6392.026355] schedule+0xc0/0x180 [ 6392.029318] schedule_preempt_disabled+0x21/0x40 [ 6392.040640] rwsem_down_write_slowpath+0x5d7/0xa40 [ 6392.050785] down_write+0x80/0xd0 [ 6392.052079] do_last+0x2eb/0xfc0 [ 6392.053332] ? nd_jump_root+0xe5/0x160 [ 6392.075318] ? path_init+0x437/0x520 [ 6392.094356] path_openat+0xf7/0x500 [ 6392.095961] do_filp_open+0x99/0x140 [ 6392.108738] ? getname_flags+0x6e/0x330 [ 6392.112860] ? __check_object_size+0xff/0x256 [ 6392.130995] ? do_raw_spin_unlock+0x75/0x190 [ 6392.142377] ? _raw_spin_unlock+0x12/0x30 [ 6392.143858] do_sys_openat2+0x2b4/0x410 [ 6392.153785] do_sys_open+0x73/0xa0 [ 6392.166704] __x64_sys_openat+0x24/0x30 [ 6392.170514] do_syscall_64+0xc1/0x440 [ 6392.171908] entry_SYSCALL_64_after_hwframe+0x49/0xae [ 6392.187397] RIP: 0033:0x7f67100a7332 [ 6392.192822] Code: Unable to access opcode bytes at RIP 0x7f67100a7308. [ 6392.208665] RSP: 002b:00007ffd4b3823c0 EFLAGS: 00000246 ORIG_RAX: 0000000000000101 [ 6392.219862] RAX: ffffffffffffffda RBX: 00000000ffffffff RCX: 00007f67100a7332 [ 6392.235594] RDX: 0000000000000941 RSI: 00007ffd4b383075 RDI: 00000000ffffff9c [ 6392.244575] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000001 [ 6392.252593] R10: 00000000000001b6 R11: 0000000000000246 R12: 0000000000000001 [ 6392.260173] R13: 0000000000000001 R14: 00007ffd4b383075 R15: 00007f671034a374 [ 6392.275069] INFO: task touch:95002 blocked for more than 120 seconds. [ 6392.277507] Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 6392.297133] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 6392.314098] task:touch state:D stack:0 pid:95002 ppid:94734 flags:0x80000004 [ 6392.329323] Call Trace: [ 6392.330862] __schedule+0x351/0xcb0 [ 6392.333362] schedule+0xc0/0x180 [ 6392.347153] schedule_preempt_disabled+0x21/0x40 [ 6392.362846] rwsem_down_write_slowpath+0x5d7/0xa40 [ 6392.368306] down_write+0x80/0xd0 [ 6392.372985] do_last+0x2eb/0xfc0 [ 6392.380322] ? nd_jump_root+0xe5/0x160 [ 6392.388046] ? path_init+0x437/0x520 [ 6392.389635] path_openat+0xf7/0x500 [ 6392.394834] ? __mod_lruvec_state+0x5a/0x80 [ 6392.402394] do_filp_open+0x99/0x140 [ 6392.414310] ? getname_flags+0x6e/0x330 [ 6392.423751] ? __check_object_size+0xff/0x256 [ 6392.445848] ? do_raw_spin_unlock+0x75/0x190 [ 6392.454993] ? _raw_spin_unlock+0x12/0x30 [ 6392.470107] do_sys_openat2+0x2b4/0x410 [ 6392.474379] do_sys_open+0x73/0xa0 [ 6392.475784] __x64_sys_openat+0x24/0x30 [ 6392.481401] do_syscall_64+0xc1/0x440 [ 6392.498787] entry_SYSCALL_64_after_hwframe+0x49/0xae [ 6392.507204] RIP: 0033:0x7fe5a157f332 [ 6392.511398] Code: Unable to access opcode bytes at RIP 0x7fe5a157f308. [ 6392.517623] RSP: 002b:00007ffea0710480 EFLAGS: 00000246 ORIG_RAX: 0000000000000101 [ 6392.535320] RAX: ffffffffffffffda RBX: 00000000ffffffff RCX: 00007fe5a157f332 [ 6392.551754] RDX: 0000000000000941 RSI: 00007ffea0712075 RDI: 00000000ffffff9c [ 6392.569728] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000001 [ 6392.588200] R10: 00000000000001b6 R11: 0000000000000246 R12: 0000000000000001 [ 6392.598091] R13: 0000000000000001 R14: 00007ffea0712075 R15: 00007fe5a1822374 [ 6392.605736] INFO: task touch:95003 blocked for more than 120 seconds. [ 6392.619038] Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 6392.635578] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 6392.651789] task:touch state:D stack:0 pid:95003 ppid:94734 flags:0x80000004 [ 6392.658068] Call Trace: [ 6392.659093] __schedule+0x351/0xcb0 [ 6392.660550] schedule+0xc0/0x180 [ 6392.661757] schedule_preempt_disabled+0x21/0x40 [ 6392.663376] rwsem_down_write_slowpath+0x5d7/0xa40 [ 6392.665428] down_write+0x80/0xd0 [ 6392.667041] do_last+0x2eb/0xfc0 [ 6392.668870] ? nd_jump_root+0xe5/0x160 [ 6392.670343] ? path_init+0x437/0x520 [ 6392.671589] path_openat+0xf7/0x500 [ 6392.673030] do_filp_open+0x99/0x140 [ 6392.674694] ? getname_flags+0x6e/0x330 [ 6392.676310] ? __check_object_size+0xff/0x256 [ 6392.678187] ? do_raw_spin_unlock+0x75/0x190 [ 6392.680142] ? _raw_spin_unlock+0x12/0x30 [ 6392.681363] do_sys_openat2+0x2b4/0x410 [ 6392.683854] do_sys_open+0x73/0xa0 [ 6392.685977] __x64_sys_openat+0x24/0x30 [ 6392.689603] do_syscall_64+0xc1/0x440 [ 6392.691296] entry_SYSCALL_64_after_hwframe+0x49/0xae [ 6392.692960] RIP: 0033:0x7fbd4aab9332 [ 6392.694127] Code: Unable to access opcode bytes at RIP 0x7fbd4aab9308. [ 6392.696608] RSP: 002b:00007ffd3303ef00 EFLAGS: 00000246 ORIG_RAX: 0000000000000101 [ 6392.698983] RAX: ffffffffffffffda RBX: 00000000ffffffff RCX: 00007fbd4aab9332 [ 6392.701019] RDX: 0000000000000941 RSI: 00007ffd33040075 RDI: 00000000ffffff9c [ 6392.703795] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000001 [ 6392.707135] R10: 00000000000001b6 R11: 0000000000000246 R12: 0000000000000001 [ 6392.710212] R13: 0000000000000001 R14: 00007ffd33040075 R15: 00007fbd4ad5c374 [ 6392.713359] INFO: task touch:95004 blocked for more than 120 seconds. [ 6392.718205] Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 6392.723074] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 6392.725729] task:touch state:D stack:0 pid:95004 ppid:94734 flags:0x80004004 [ 6392.729599] Call Trace: [ 6392.732100] __schedule+0x351/0xcb0 [ 6392.734193] schedule+0xc0/0x180 [ 6392.735716] schedule_preempt_disabled+0x21/0x40 [ 6392.738691] rwsem_down_write_slowpath+0x5d7/0xa40 [ 6392.741833] down_write+0x80/0xd0 [ 6392.744248] do_last+0x2eb/0xfc0 [ 6392.746152] ? nd_jump_root+0xe5/0x160 [ 6392.752340] ? path_init+0x437/0x520 [ 6392.753207] path_openat+0xf7/0x500 [ 6392.754380] do_filp_open+0x99/0x140 [ 6392.759848] ? getname_flags+0x6e/0x330 [ 6392.764959] ? __check_object_size+0xff/0x256 [ 6392.766535] ? do_raw_spin_unlock+0x75/0x190 [ 6392.769635] ? _raw_spin_unlock+0x12/0x30 [ 6392.784690] do_sys_openat2+0x2b4/0x410 [ 6392.788883] do_sys_open+0x73/0xa0 [ 6392.791777] __x64_sys_openat+0x24/0x30 [ 6392.792690] do_syscall_64+0xc1/0x440 [ 6392.795206] entry_SYSCALL_64_after_hwframe+0x49/0xae [ 6392.798526] RIP: 0033:0x7f90ef5c6332 [ 6392.799423] Code: Unable to access opcode bytes at RIP 0x7f90ef5c6308. [ 6392.808098] RSP: 002b:00007ffe7ffdef60 EFLAGS: 00000246 ORIG_RAX: 0000000000000101 [ 6392.817031] RAX: ffffffffffffffda RBX: 00000000ffffffff RCX: 00007f90ef5c6332 [ 6392.822883] RDX: 0000000000000941 RSI: 00007ffe7ffe0075 RDI: 00000000ffffff9c [ 6392.830187] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000001 [ 6392.840888] R10: 00000000000001b6 R11: 0000000000000246 R12: 0000000000000001 [ 6392.851713] R13: 0000000000000001 R14: 00007ffe7ffe0075 R15: 00007f90ef869374 [ 6392.861349] INFO: task touch:95005 blocked for more than 120 seconds. [ 6392.864772] Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 6392.876155] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 6392.879598] task:touch state:D stack:0 pid:95005 ppid:94734 flags:0x80000004 [ 6392.886055] Call Trace: [ 6392.887785] __schedule+0x351/0xcb0 [ 6392.891936] schedule+0xc0/0x180 [ 6392.894348] schedule_preempt_disabled+0x21/0x40 [ 6392.898551] rwsem_down_write_slowpath+0x5d7/0xa40 [ 6392.901310] down_write+0x80/0xd0 [ 6392.903126] do_last+0x2eb/0xfc0 [ 6392.911131] ? nd_jump_root+0xe5/0x160 [ 6392.913798] ? path_init+0x437/0x520 [ 6392.915090] path_openat+0xf7/0x500 [ 6392.931340] do_filp_open+0x99/0x140 [ 6392.938256] ? getname_flags+0x6e/0x330 [ 6392.951763] ? __check_object_size+0xff/0x256 [ 6392.956501] ? do_raw_spin_unlock+0x75/0x190 [ 6392.972402] ? _raw_spin_unlock+0x12/0x30 [ 6392.981252] do_sys_openat2+0x2b4/0x410 [ 6392.986329] do_sys_open+0x73/0xa0 [ 6392.993538] __x64_sys_openat+0x24/0x30 [ 6392.997041] do_syscall_64+0xc1/0x440 [ 6392.999269] entry_SYSCALL_64_after_hwframe+0x49/0xae [ 6393.007665] RIP: 0033:0x7f4ca2af5332 [ 6393.010055] Code: Unable to access opcode bytes at RIP 0x7f4ca2af5308. [ 6393.014913] RSP: 002b:00007fffa485a150 EFLAGS: 00000246 ORIG_RAX: 0000000000000101 [ 6393.029233] RAX: ffffffffffffffda RBX: 00000000ffffffff RCX: 00007f4ca2af5332 [ 6393.031904] RDX: 0000000000000941 RSI: 00007fffa485b075 RDI: 00000000ffffff9c [ 6393.046123] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000001 [ 6393.053562] R10: 00000000000001b6 R11: 0000000000000246 R12: 0000000000000001 [ 6393.058110] R13: 0000000000000001 R14: 00007fffa485b075 R15: 00007f4ca2d98374 [ 6396.172727] Lustre: DEBUG MARKER: oleg218-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 6398.702904] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6432.796308] LustreError: 2220:0:(client.c:3161:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@00000000c5e9c360 x1862471463681088/t94489280648(94489280648) o101->lustre-MDT0000-mdc-ffff8c6c11a23000@192.168.202.118@tcp:12/10 lens 576/600 e 0 to 0 dl 1776197656 ref 2 fl Interpret:RPQU/4/0 rc 301/301 job:'dd.0' [ 6447.559776] Lustre: DEBUG MARKER: oleg218-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 6449.054735] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6531.359273] Lustre: DEBUG MARKER: == recovery-small test 145: connect mdtlovs and process update logs after recovery expire ========================================================== 16:13:23 (1776197603) [ 6536.035265] Lustre: DEBUG MARKER: SKIP: recovery-small test_145 needs >= 3 MDTs [ 6540.473683] Lustre: DEBUG MARKER: == recovery-small test 147: Check client reconnect ======= 16:13:32 (1776197612) [ 6730.313933] Lustre: DEBUG MARKER: == recovery-small test 148: data corruption through resend ========================================================== 16:16:42 (1776197802) [ 6756.192658] Lustre: 2223:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776197809/real 1776197809] req@000000009ba8d4a9 x1862471463965312/t0(0) o4->lustre-OST0000-osc-ffff8c6c11a23000@192.168.202.118@tcp:6/4 lens 4584/448 e 0 to 1 dl 1776197829 ref 2 fl Rpc:XQr/0/ffffffff rc 0/-1 job:'dd.0' [ 6756.225563] Lustre: 2223:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 24 previous similar messages [ 6756.231427] Lustre: lustre-OST0000-osc-ffff8c6c11a23000: Connection to lustre-OST0000 (at 192.168.202.118@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 6756.244188] Lustre: Skipped 6 previous similar messages [ 6769.984961] Lustre: DEBUG MARKER: == recovery-small test 149: skip orphan removal at umount ========================================================== 16:17:21 (1776197841) [ 6771.984436] Lustre: DEBUG MARKER: SKIP: recovery-small test_149 needs >= 2 MDTs [ 6773.759950] Lustre: DEBUG MARKER: == recovery-small test 152: QoS object allocation could be awakened in case of OST failover ========================================================== 16:17:25 (1776197845) [ 6808.221404] Lustre: DEBUG MARKER: == recovery-small test complete, duration 6520 sec ======= 16:17:59 (1776197879) [ 6815.254978] Lustre: Unmounted lustre-client [ 6842.119253] Key type lgssc unregistered [ 6842.345635] LNet: 101311:0:(lib-ptl.c:992:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 6843.362663] LNet: Removed LNI 192.168.202.18@tcp [ 6844.192431] Key type .llcrypt unregistered [ 6844.194925] Key type ._llcrypt unregistered